search

vanackej / risco-mqtt-local

Provide Risco alarm system integration to Home assistant using local TCP communication (no cloud required) and MQTT
MIT License
24 stars 11 forks source link

Failed to send CLOCK command && Add-on Crash #30

Closed pergolafabio closed 1 year ago

pergolafabio commented 2 years ago

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

Logs

3/15/2022, 7:43:53 AM [info] Initialization completed
3/15/2022, 7:43:53 AM [verbose] System initialization completed.
3/15/2022, 7:43:56 AM [debug] [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 [debug] 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 [debug] Command[55] crcOK : true, Computed CRC : ED23, Message CRC: ED23
3/15/2022, 7:43:56 AM [verbose] Command[55] Received data: CLOCK=15/03/2022 07:44, crcOk: true
3/15/2022, 7:43:56 AM [debug] Command[55] Data from Panel, need to send an ACK
3/15/2022, 7:43:56 AM [debug] Command[55] Sending Ack.
3/15/2022, 7:43:56 AM [debug] Command[55] Data type: Clock
3/15/2022, 7:43:56 AM [verbose] [Panel => MQTT] Published alarm online
3/15/2022, 7:44:03 AM [verbose] Command[14] Sending Command: CLOCK
3/15/2022, 7:44:03 AM [debug] 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 [debug] Command[14] Data Sent : CLOCK
3/15/2022, 7:44:03 AM [debug] [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 [debug] 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 [debug] Command[14] crcOK : true, Computed CRC : 5D2B, Message CRC: 5D2B
3/15/2022, 7:44:03 AM [verbose] Command[14] Received data: CLOCK=15/03/2022 07:44, crcOk: true
3/15/2022, 7:44:03 AM [debug] Command[14] Command response from Panel
3/15/2022, 7:44:03 AM [debug] Command[14] Emitting expected command response
3/15/2022, 7:44:03 AM [debug] Command[14] Data type: Clock
3/15/2022, 7:44:03 AM [verbose] [Panel => MQTT] Published alarm online
3/15/2022, 7:44:03 AM [debug] Command[14] command response : CLOCK=15/03/2022 07:44
3/15/2022, 7:44:13 AM [verbose] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:13 AM [debug] 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 [debug] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:18 AM [warn] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:18 AM [verbose] Command[15] retrying command
3/15/2022, 7:44:18 AM [verbose] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:18 AM [debug] 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 [debug] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:23 AM [warn] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:23 AM [verbose] Command[15] retrying command
3/15/2022, 7:44:23 AM [verbose] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:23 AM [debug] 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 [debug] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:28 AM [warn] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:28 AM [verbose] Command[15] retrying command
3/15/2022, 7:44:28 AM [verbose] Command[15] Sending Command: CLOCK
3/15/2022, 7:44:28 AM [debug] 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 [debug] Command[15] Data Sent : CLOCK
3/15/2022, 7:44:33 AM [warn] Command[15] 'CLOCK' Timeout
3/15/2022, 7:44:33 AM [debug] Command[15] command response : undefined

deleted some loops here

3/15/2022, 7:59:04 AM [warn] 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 [error] RiscoCloud Socket: close. Retrying within 5sec...
3/15/2022, 7:59:14 AM [verbose] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:14 AM [debug] 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 [debug] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:18 AM [debug] RiscoCloud Socket: connect
3/15/2022, 7:59:18 AM [info] RiscoCloud Socket: ready
3/15/2022, 7:59:19 AM [warn] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:19 AM [verbose] Command[45] retrying command
3/15/2022, 7:59:19 AM [verbose] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:19 AM [debug] 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 [debug] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:24 AM [warn] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:24 AM [verbose] Command[45] retrying command
3/15/2022, 7:59:24 AM [verbose] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:24 AM [debug] 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 [debug] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:29 AM [warn] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:29 AM [verbose] Command[45] retrying command
3/15/2022, 7:59:29 AM [verbose] Command[45] Sending Command: CLOCK
3/15/2022, 7:59:29 AM [debug] 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 [debug] Command[45] Data Sent : CLOCK
3/15/2022, 7:59:34 AM [warn] Command[45] 'CLOCK' Timeout
3/15/2022, 7:59:34 AM [debug] Command[45] command response : undefined
3/15/2022, 7:59:34 AM [warn] 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 [error] RiscoCloud Socket: close. Retrying within 5sec...
3/15/2022, 7:59:42 AM [debug] RiscoCloud Socket: connect
3/15/2022, 7:59:42 AM [info] RiscoCloud Socket: ready
3/15/2022, 7:59:44 AM [verbose] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:44 AM [debug] 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 [debug] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:49 AM [warn] Command[46] 'CLOCK' Timeout
3/15/2022, 7:59:49 AM [verbose] Command[46] retrying command
3/15/2022, 7:59:49 AM [verbose] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:49 AM [debug] 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 [debug] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:54 AM [warn] Command[46] 'CLOCK' Timeout
3/15/2022, 7:59:54 AM [verbose] Command[46] retrying command
3/15/2022, 7:59:54 AM [verbose] Command[46] Sending Command: CLOCK
3/15/2022, 7:59:54 AM [debug] 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 [debug] Command[46] Data Sent : CLOCK
3/15/2022, 7:59:55 AM [error] Panel Socket Error : Error: read EHOSTUNREACH
3/15/2022, 7:59:55 AM [debug] RiscoCloud Socket Destroyed.
3/15/2022, 7:59:55 AM [info] TCP Socket Disconnected
3/15/2022, 7:59:55 AM [info] Automatic reconnection will be attempted in 10000 ms
3/15/2022, 7:59:55 AM [verbose] [Panel => MQTT] Published alarm offline
3/15/2022, 7:59:55 AM [error] Command[46] error: Error: read EHOSTUNREACH
3/15/2022, 7:59:55 AM [error] Panel Socket Closed.
3/15/2022, 7:59:55 AM [verbose] [Panel => MQTT] Published alarm offline
3/15/2022, 7:59:55 AM [debug] Command[46] command response : undefined
3/15/2022, 7:59:55 AM [warn] 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 [verbose] Start Connection to Panel
3/15/2022, 8:00:05 AM [debug] A TCP Socket already exists, clearing its listeners before creating a new one
3/15/2022, 8:00:05 AM [debug] Pseudo Buffer Created for Panel Id(1)
3/15/2022, 8:00:05 AM [debug] TCP Socket created
3/15/2022, 8:00:05 AM [info] Listening on IP :: and Port 33000
3/15/2022, 8:00:05 AM [info] Waiting for panel incoming connection... This can take up to 1 or 2 minutes
3/15/2022, 8:01:57 AM [info] Incoming connection from panel received
3/15/2022, 8:01:57 AM [debug] RiscoCloud Socket: connect
3/15/2022, 8:01:57 AM [info] RiscoCloud Socket: ready
3/15/2022, 8:01:57 AM [info] Setting a timer for panel connection in 30000 ms
3/15/2022, 8:01:57 AM [debug] [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 [debug] [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 [debug] [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 [debug] [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 [debug] [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 [debug] [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 [debug] [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 [verbose] Authenticating to the panel
3/15/2022, 8:02:27 AM [verbose] Command[1] Sending Command: RMT=1014
3/15/2022, 8:02:27 AM [debug] 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 [debug] Command[1] Data Sent : RMT=1014
3/15/2022, 8:02:27 AM [debug] [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 [debug] Received data Buffer : [2,48,49,65,67,75,23,51,57,69,66,3]
3/15/2022, 8:02:27 AM [debug] Command[1] crcOK : true, Computed CRC : 39EB, Message CRC: 39EB
3/15/2022, 8:02:27 AM [verbose] Command[1] Received data: ACK, crcOk: true
3/15/2022, 8:02:27 AM [debug] Command[1] Command response from Panel
3/15/2022, 8:02:27 AM [debug] Command[1] Emitting expected command response
3/15/2022, 8:02:27 AM [debug] Command[1] command response : ACK
3/15/2022, 8:02:27 AM [verbose] Command[2] Sending Command: LCL
3/15/2022, 8:02:27 AM [debug] 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 [debug] Command[2] Data Sent : LCL
3/15/2022, 8:02:27 AM [debug] [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 [debug] Received data Buffer : [2,48,50,65,67,75,23,51,57,65,70,3]
3/15/2022, 8:02:27 AM [debug] Command[2] crcOK : true, Computed CRC : 39AF, Message CRC: 39AF
3/15/2022, 8:02:27 AM [verbose] Command[2] Received data: ACK, crcOk: true
3/15/2022, 8:02:27 AM [debug] Command[2] Command response from Panel
3/15/2022, 8:02:27 AM [debug] Command[2] Emitting expected command response
3/15/2022, 8:02:27 AM [debug] Command[2] command response : ACK
3/15/2022, 8:02:27 AM [debug] LCL command result OK
3/15/2022, 8:02:27 AM [verbose] Setting up encryption using Panel Id
3/15/2022, 8:02:27 AM [debug] [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 [debug] 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 [debug] Command[57] crcOK : true, Computed CRC : A992, Message CRC: A992
3/15/2022, 8:02:27 AM [verbose] Command[57] Received data: PSTT1=--------R-E-----, crcOk: true
3/15/2022, 8:02:27 AM [verbose] Command[2] inCryptTest enabled, emitting response without checks to latest sent command
3/15/2022, 8:02:27 AM [error] Panel Socket Closed.
3/15/2022, 8:02:27 AM [debug] RiscoCloud Socket Destroyed.
3/15/2022, 8:02:27 AM [info] TCP Socket Disconnected
3/15/2022, 8:02:27 AM [info] Automatic reconnection will be attempted in 10000 ms
3/15/2022, 8:02:27 AM [warn] sendCommand(ZLBL*1:8?): Socket is destroyed, ignoring command
3/15/2022, 8:02:27 AM [debug] cryptTableTester response: , attempt: 1
3/15/2022, 8:02:27 AM [verbose] Connection to the control panel successfully established.
3/15/2022, 8:02:27 AM [debug] Risco Panel Connected.
3/15/2022, 8:02:27 AM [warn] 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 commented 2 years ago

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

ekkesa commented 2 years ago

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 commented 2 years ago

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.

pergolafabio commented 2 years ago

Good idea for now, keep us posted

ekkesa commented 2 years ago

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 commented 2 years ago

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....