risco-mqtt-local icon indicating copy to clipboard operation
risco-mqtt-local copied to clipboard

Published 20 hours ago • verified publisher icon vanackej

Failed to send CLOCK command && Add-on Crash

Open pergolafabio opened this issue 2 years ago • 6 comments

Describe the bug

Hi @vanackej , i had the error before also in the past, sure if its the same now, but i use the proxy method, when i take out the UTP cable or my network is down for a little white, it never reconnects again, i see a continues loop like below

I attached the logs, copy/pasted from where i took out the network cable

Seems also at the bottom of the log, it crashed the add-on, i think this is the first time i see this The logs are starting when i took out the cable

thnx for looking into it!

Configuration

  • Environment: HA Addon
  • Version: 0.4.1
  • Mode: Proxy
  • Risco Panel model: Lightsys 2
  • Risco Panel firmware version: 2.72

Logs

3/15/2022, 7:43:53 AM [[32minfo[39m] Initialization completed
3/15/2022, 7:43:53 AM [[36mverbose[39m] System initialization completed.
3/15/2022, 7:43:56 AM [[34mdebug[39m] [Panel => Bridge] Received encrypted data Buffer from Panel : [2,17,55,48,72,91,96,29,246,71,197,221,255,145,113,170,57,38,31,104,149,91,225,151,110,128,127,149,229,113,180,3]
3/15/2022, 7:43:56 AM [[34mdebug[39m] Received data Buffer : [2,17,55,48,72,91,96,29,246,71,197,221,255,145,113,170,57,38,31,104,149,91,225,151,110,128,127,149,229,113,180,3]
3/15/2022, 7:43:56 AM [[34mdebug[39m] Command[55] crcOK : true, Computed CRC : ED23, Message CRC: ED23
3/15/2022, 7:43:56 AM [[36mverbose[39m] Command[55] Received data: CLOCK=15/03/2022 07:44, crcOk: true
3/15/2022, 7:43:56 AM [[34mdebug[39m] Command[55] Data from Panel, need to send an ACK
3/15/2022, 7:43:56 AM [[34mdebug[39m] Command[55] Sending Ack.
3/15/2022, 7:43:56 AM [[34mdebug[39m] Command[55] Data type: Clock
3/15/2022, 7:43:56 AM [[36mverbose[39m] [Panel => MQTT] Published alarm online
3/15/2022, 7:44:03 AM [[36mverbose[39m] Command[14] Sending Command: CLOCK
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] Writing command buffer to socket: [2,17,51,49,72,91,96,29,246,109,176,219,231,152,3]
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] Data Sent : CLOCK
3/15/2022, 7:44:03 AM [[34mdebug[39m] [Panel => Bridge] Received encrypted data Buffer from Panel : [2,17,51,49,72,91,96,29,246,71,197,221,255,145,113,170,57,38,31,104,149,91,225,151,110,128,127,229,229,113,197,3]
3/15/2022, 7:44:03 AM [[34mdebug[39m] Received data Buffer : [2,17,51,49,72,91,96,29,246,71,197,221,255,145,113,170,57,38,31,104,149,91,225,151,110,128,127,229,229,113,197,3]
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] crcOK : true, Computed CRC : 5D2B, Message CRC: 5D2B
3/15/2022, 7:44:03 AM [[36mverbose[39m] Command[14] Received data: CLOCK=15/03/2022 07:44, crcOk: true
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] Command response from Panel
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] Emitting expected command response
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] Data type: Clock
3/15/2022, 7:44:03 AM [[36mverbose[39m] [Panel => MQTT] Published alarm online
3/15/2022, 7:44:03 AM [[34mdebug[39m] Command[14] command response : CLOCK=15/03/2022 07:44
3/15/2022, 7:44:13 AM [[36mverbose[39m] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:13 AM [[34mdebug[39m] Command[15] Writing command buffer to socket: [2,17,51,48,72,91,96,29,246,109,197,219,230,152,3]
3/15/2022, 7:44:13 AM [[34mdebug[39m] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:18 AM [[33mwarn[39m] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:18 AM [[36mverbose[39m] Command[15] retrying command
3/15/2022, 7:44:18 AM [[36mverbose[39m] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:18 AM [[34mdebug[39m] Command[15] Writing command buffer to socket: [2,17,51,48,72,91,96,29,246,109,197,219,230,152,3]
3/15/2022, 7:44:18 AM [[34mdebug[39m] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:23 AM [[33mwarn[39m] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:23 AM [[36mverbose[39m] Command[15] retrying command
3/15/2022, 7:44:23 AM [[36mverbose[39m] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:23 AM [[34mdebug[39m] Command[15] Writing command buffer to socket: [2,17,51,48,72,91,96,29,246,109,197,219,230,152,3]
3/15/2022, 7:44:23 AM [[34mdebug[39m] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:28 AM [[33mwarn[39m] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:28 AM [[36mverbose[39m] Command[15] retrying command
3/15/2022, 7:44:28 AM [[36mverbose[39m] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:28 AM [[34mdebug[39m] Command[15] Writing command buffer to socket: [2,17,51,48,72,91,96,29,246,109,197,219,230,152,3]
3/15/2022, 7:44:28 AM [[34mdebug[39m] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:33 AM [[33mwarn[39m] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:33 AM [[34mdebug[39m] Command[15] command response : undefined

deleted some loops here

3/15/2022, 7:59:04 AM [[33mwarn[39m] Failed to send CLOCK command: RiscoCommandError: Risco command error: TIMEOUT. Command: {"panelId":1,"commandId":44,"attempts":4,"crcOk":false,"commandStr":"CLOCK","sentBuffer":{"type":"Buffer","data":[2,17,54,49,72,91,96,29,246,109,177,171,146,152,3]}}
3/15/2022, 7:59:13 AM [[31merror[39m] RiscoCloud Socket: close. Retrying within 5sec...
3/15/2022, 7:59:14 AM [[36mverbose[39m] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:14 AM [[34mdebug[39m] Command[45] Writing command buffer to socket: [2,17,54,48,72,91,96,29,246,109,198,171,145,152,3]
3/15/2022, 7:59:14 AM [[34mdebug[39m] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:18 AM [[34mdebug[39m] RiscoCloud Socket: connect
3/15/2022, 7:59:18 AM [[32minfo[39m] RiscoCloud Socket: ready
3/15/2022, 7:59:19 AM [[33mwarn[39m] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:19 AM [[36mverbose[39m] Command[45] retrying command
3/15/2022, 7:59:19 AM [[36mverbose[39m] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:19 AM [[34mdebug[39m] Command[45] Writing command buffer to socket: [2,17,54,48,72,91,96,29,246,109,198,171,145,152,3]
3/15/2022, 7:59:19 AM [[34mdebug[39m] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:24 AM [[33mwarn[39m] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:24 AM [[36mverbose[39m] Command[45] retrying command
3/15/2022, 7:59:24 AM [[36mverbose[39m] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:24 AM [[34mdebug[39m] Command[45] Writing command buffer to socket: [2,17,54,48,72,91,96,29,246,109,198,171,145,152,3]
3/15/2022, 7:59:24 AM [[34mdebug[39m] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:29 AM [[33mwarn[39m] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:29 AM [[36mverbose[39m] Command[45] retrying command
3/15/2022, 7:59:29 AM [[36mverbose[39m] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:29 AM [[34mdebug[39m] Command[45] Writing command buffer to socket: [2,17,54,48,72,91,96,29,246,109,198,171,145,152,3]
3/15/2022, 7:59:29 AM [[34mdebug[39m] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:34 AM [[33mwarn[39m] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:34 AM [[34mdebug[39m] Command[45] command response : undefined
3/15/2022, 7:59:34 AM [[33mwarn[39m] Failed to send CLOCK command: RiscoCommandError: Risco command error: TIMEOUT. Command: {"panelId":1,"commandId":45,"attempts":4,"crcOk":false,"commandStr":"CLOCK","sentBuffer":{"type":"Buffer","data":[2,17,54,48,72,91,96,29,246,109,198,171,145,152,3]}}
3/15/2022, 7:59:37 AM [[31merror[39m] RiscoCloud Socket: close. Retrying within 5sec...
3/15/2022, 7:59:42 AM [[34mdebug[39m] RiscoCloud Socket: connect
3/15/2022, 7:59:42 AM [[32minfo[39m] RiscoCloud Socket: ready
3/15/2022, 7:59:44 AM [[36mverbose[39m] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:44 AM [[34mdebug[39m] Command[46] Writing command buffer to socket: [2,17,54,51,72,91,96,29,246,109,198,171,233,224,3]
3/15/2022, 7:59:44 AM [[34mdebug[39m] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:49 AM [[33mwarn[39m] Command[46] 'CLOCK' Timeout
3/15/2022, 7:59:49 AM [[36mverbose[39m] Command[46] retrying command
3/15/2022, 7:59:49 AM [[36mverbose[39m] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:49 AM [[34mdebug[39m] Command[46] Writing command buffer to socket: [2,17,54,51,72,91,96,29,246,109,198,171,233,224,3]
3/15/2022, 7:59:49 AM [[34mdebug[39m] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:54 AM [[33mwarn[39m] Command[46] 'CLOCK' Timeout
3/15/2022, 7:59:54 AM [[36mverbose[39m] Command[46] retrying command
3/15/2022, 7:59:54 AM [[36mverbose[39m] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:54 AM [[34mdebug[39m] Command[46] Writing command buffer to socket: [2,17,54,51,72,91,96,29,246,109,198,171,233,224,3]
3/15/2022, 7:59:54 AM [[34mdebug[39m] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:55 AM [[31merror[39m] Panel Socket Error : Error: read EHOSTUNREACH
3/15/2022, 7:59:55 AM [[34mdebug[39m] RiscoCloud Socket Destroyed.
3/15/2022, 7:59:55 AM [[32minfo[39m] TCP Socket Disconnected
3/15/2022, 7:59:55 AM [[32minfo[39m] Automatic reconnection will be attempted in 10000 ms
3/15/2022, 7:59:55 AM [[36mverbose[39m] [Panel => MQTT] Published alarm offline
3/15/2022, 7:59:55 AM [[31merror[39m] Command[46] error: Error: read EHOSTUNREACH
3/15/2022, 7:59:55 AM [[31merror[39m] Panel Socket Closed.
3/15/2022, 7:59:55 AM [[36mverbose[39m] [Panel => MQTT] Published alarm offline
3/15/2022, 7:59:55 AM [[34mdebug[39m] Command[46] command response : undefined
3/15/2022, 7:59:55 AM [[33mwarn[39m] Failed to send CLOCK command: RiscoCommandError: Risco command error: TIMEOUT. Command: {"panelId":1,"commandId":46,"attempts":3,"crcOk":false,"commandStr":"CLOCK","sentBuffer":{"type":"Buffer","data":[2,17,54,51,72,91,96,29,246,109,198,171,233,224,3]}}
3/15/2022, 8:00:05 AM [[36mverbose[39m] Start Connection to Panel
3/15/2022, 8:00:05 AM [[34mdebug[39m] A TCP Socket already exists, clearing its listeners before creating a new one
3/15/2022, 8:00:05 AM [[34mdebug[39m] Pseudo Buffer Created for Panel Id(1)
3/15/2022, 8:00:05 AM [[34mdebug[39m] TCP Socket created
3/15/2022, 8:00:05 AM [[32minfo[39m] Listening on IP :: and Port 33000
3/15/2022, 8:00:05 AM [[32minfo[39m] Waiting for panel incoming connection... This can take up to 1 or 2 minutes
3/15/2022, 8:01:57 AM [[32minfo[39m] Incoming connection from panel received
3/15/2022, 8:01:57 AM [[34mdebug[39m] RiscoCloud Socket: connect
3/15/2022, 8:01:57 AM [[32minfo[39m] RiscoCloud Socket: ready
3/15/2022, 8:01:57 AM [[32minfo[39m] Setting a timer for panel connection in 30000 ms
3/15/2022, 8:01:57 AM [[34mdebug[39m] [Panel => Cloud] Forwarding panel packet to cloud: [2,19,56,54,4,81,0,16,3,0,51,48,48,53,48,48,50,48,52,49,50,32,32,32,32,32,65,65,65,65,65,65,32,32,32,32,32,32,32,32,32,32,0,0,23,23,69,76,16,2,112,1,255,255,255,255,255,255,49,16,2,49,0,0,0,0,6,255,30,236,60,0,0,16,2,15,49,57,50,46,49,54,56,46,48,48,48,46,48,50,54,1,23,51,68,56,67,3]
3/15/2022, 8:01:57 AM [[34mdebug[39m] [Panel => Cloud] Forwarding panel packet to cloud: [2,19,56,54,4,81,0,16,3,0,51,48,48,53,48,48,50,48,52,49,50,32,32,32,32,32,65,65,65,65,65,65,32,32,32,32,32,32,32,32,32,32,0,0,23,23,69,76,16,2,112,1,255,255,255,255,255,255,49,16,2,49,0,0,0,0,6,255,30,236,60,0,0,16,2,15,49,57,50,46,49,54,56,46,48,48,48,46,48,50,54,1,23,51,68,56,67,3]
3/15/2022, 8:01:58 AM [[34mdebug[39m] [Cloud => Panel] Forwarding Cloud data Buffer to panel: [2,19,56,54,0,9,0,16,3,0,87,1,8,34,16,3,21,16,3,23,65,51,53,69,3,2,19,48,48,4,16,3,0,10,0,255,23,51,48,49,65,3]
3/15/2022, 8:01:58 AM [[34mdebug[39m] [Panel => Cloud] Forwarding panel packet to cloud: [2,19,56,55,4,81,0,16,3,0,51,48,48,53,48,48,50,48,52,49,50,32,32,32,32,32,65,65,65,65,65,65,32,32,32,32,32,32,32,32,32,32,0,0,23,23,69,76,16,2,112,1,255,255,255,255,255,255,49,16,2,49,0,0,0,0,6,255,30,236,60,0,0,16,2,15,49,57,50,46,49,54,56,46,48,48,48,46,48,50,54,1,23,53,50,55,52,3]
3/15/2022, 8:02:03 AM [[34mdebug[39m] [Panel => Cloud] Forwarding panel packet to cloud: [2,19,56,55,4,81,0,16,3,0,51,48,48,53,48,48,50,48,52,49,50,32,32,32,32,32,65,65,65,65,65,65,32,32,32,32,32,32,32,32,32,32,0,0,23,23,69,76,16,2,112,1,255,255,255,255,255,255,49,16,2,49,0,0,0,0,6,255,30,236,60,0,0,16,2,15,49,57,50,46,49,54,56,46,48,48,48,46,48,50,54,1,23,53,50,55,52,3]
3/15/2022, 8:02:09 AM [[34mdebug[39m] [Panel => Cloud] Forwarding panel packet to cloud: [2,19,56,55,4,81,0,16,3,0,51,48,48,53,48,48,50,48,52,49,50,32,32,32,32,32,65,65,65,65,65,65,32,32,32,32,32,32,32,32,32,32,0,0,23,23,69,76,16,2,112,1,255,255,255,255,255,255,49,16,2,49,0,0,0,0,6,255,30,236,60,0,0,16,2,15,49,57,50,46,49,54,56,46,48,48,48,46,48,50,54,1,23,53,50,55,52,3]
3/15/2022, 8:02:15 AM [[34mdebug[39m] [Cloud => Panel] Forwarding Cloud data Buffer to panel: [2,19,48,48,4,16,3,0,10,0,255,23,51,48,49,65,3]
3/15/2022, 8:02:27 AM [[36mverbose[39m] Authenticating to the panel
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[1] Sending Command: RMT=1014
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] Writing command buffer to socket: [2,48,49,82,77,84,61,49,48,49,52,23,70,57,69,67,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] Data Sent : RMT=1014
3/15/2022, 8:02:27 AM [[34mdebug[39m] [Panel => Bridge] Received unencrypted data Buffer from Panel : [2,48,49,65,67,75,23,51,57,69,66,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Received data Buffer : [2,48,49,65,67,75,23,51,57,69,66,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] crcOK : true, Computed CRC : 39EB, Message CRC: 39EB
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[1] Received data: ACK, crcOk: true
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] Command response from Panel
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] Emitting expected command response
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[1] command response : ACK
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[2] Sending Command: LCL
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] Writing command buffer to socket: [2,48,50,76,67,76,23,65,53,65,70,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] Data Sent : LCL
3/15/2022, 8:02:27 AM [[34mdebug[39m] [Panel => Bridge] Received unencrypted data Buffer from Panel : [2,48,50,65,67,75,23,51,57,65,70,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Received data Buffer : [2,48,50,65,67,75,23,51,57,65,70,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] crcOK : true, Computed CRC : 39AF, Message CRC: 39AF
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[2] Received data: ACK, crcOk: true
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] Command response from Panel
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] Emitting expected command response
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[2] command response : ACK
3/15/2022, 8:02:27 AM [[34mdebug[39m] LCL command result OK
3/15/2022, 8:02:27 AM [[36mverbose[39m] Setting up encryption using Panel Id
3/15/2022, 8:02:27 AM [[34mdebug[39m] [Panel => Bridge] Received encrypted data Buffer from Panel : [2,17,55,50,91,68,123,10,140,71,217,197,253,140,111,168,38,59,127,119,240,70,251,128,119,153,127,145,152,122,181,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Received data Buffer : [2,17,55,50,91,68,123,10,140,71,217,197,253,140,111,168,38,59,127,119,240,70,251,128,119,153,127,145,152,122,181,3]
3/15/2022, 8:02:27 AM [[34mdebug[39m] Command[57] crcOK : true, Computed CRC : A992, Message CRC: A992
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[57] Received data: PSTT1=--------R-E-----, crcOk: true
3/15/2022, 8:02:27 AM [[36mverbose[39m] Command[2] inCryptTest enabled, emitting response without checks to latest sent command
3/15/2022, 8:02:27 AM [[31merror[39m] Panel Socket Closed.
3/15/2022, 8:02:27 AM [[34mdebug[39m] RiscoCloud Socket Destroyed.
3/15/2022, 8:02:27 AM [[32minfo[39m] TCP Socket Disconnected
3/15/2022, 8:02:27 AM [[32minfo[39m] Automatic reconnection will be attempted in 10000 ms
3/15/2022, 8:02:27 AM [[33mwarn[39m] sendCommand(ZLBL*1:8?): Socket is destroyed, ignoring command
3/15/2022, 8:02:27 AM [[34mdebug[39m] cryptTableTester response: , attempt: 1
3/15/2022, 8:02:27 AM [[36mverbose[39m] Connection to the control panel successfully established.
3/15/2022, 8:02:27 AM [[34mdebug[39m] Risco Panel Connected.
3/15/2022, 8:02:27 AM [[33mwarn[39m] sendCommand(PNLCNF): Socket is destroyed, ignoring command
/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoComm.js:304
                    throw new Error(`Unsupported panel type : ${panelType}`);
                          ^
Error: Unsupported panel type : 
    at RiscoComm.<anonymous> (/app/node_modules/@vanackej/risco-lan-bridge/dist/RiscoComm.js:304:27)
    at Generator.next (<anonymous>)
    at fulfilled (/app/node_modules/tslib/tslib.js:114:62)

pergolafabio avatar Mar 15 '22 07:03 pergolafabio

ok, tested again, and indeed add-on crashes again , never noticed it before

pergolafabio avatar Mar 15 '22 08:03 pergolafabio

I seem to experience this also after a few hours.

It starts with 'CLOCK' Timeout and eventually the add-on stops working till restarted.

I'm on version 0.4.2

ekkesa avatar Jul 01 '22 10:07 ekkesa

As a workaround - I'm trying to figure out how to get a heart-beart from the add-on. Perhaps with a mqtt topic that publishes "uptime" or such every minute or so. Then an automation on HA can fire if there was no update in x amount of minutes and then restart the addon.

ekkesa avatar Jul 01 '22 11:07 ekkesa

Good idea for now, keep us posted

pergolafabio avatar Jul 01 '22 11:07 pergolafabio

I think I got a workable workaround.

I created a MQTT Binary Sensor, which monitors 'riscopanel/alarm/status'. I use the force_update option in the config. Then with a template trigger looking at last_changed attribute I fire service: hassio.addon_restart if it exceeds a predetermined value e.g. 30 seconds

ekkesa avatar Jul 01 '22 14:07 ekkesa

I changed the script to grab the add-on container name with a template, that should the container name change with an update it will continue to work.

So far it has worked very well. I have not had a unresponsive alarm from HA since implementing. Fingers crossed....

ekkesa avatar Jul 07 '22 19:07 ekkesa