After update to 0.12.0, senser sensor.last_event becomes periodically unavalable

maurizioandreotti60 commented 2 years ago

Version

0.10.1 (Default)

What happened?

I have just updated the add-on to latest version 0.12.0 and I noticed that sensor sensor.last_event becomes periodically unavailable. I noticed this issue because I have an automation that sends a Telegram message when the sensor changes.

Where are you running ialarm-mqtt?

Hass.io addon

Alarm panel model

Casasicura - Siqura web

Relevant log output

No response

maxill1 commented 2 years ago

Does only "last event" became unavailable or also other entities like alarm control panel or switches?

Do you have only one instance of ialarm-mqtt running? (I mean both ialarm-mqtt and ialarm-mqtt-dev)

Maybe your mqtt broker is kicking out the ialarm-mqtt client (sometimes it happens when there are two client with same ID). Please check the add-on logs for any mqtt related error.

In the meantime you can try to hit "clean discovery", it may help to cleanup any topic changes between versions. (keep in mind that cleaning discovery will remove all entities personalization you eventually did on home assistant side, names, icons, entity IDs, etc. Sorry about that)

maurizioandreotti60 commented 2 years ago

You're right, the issue occurs on other sensors as well. I have only one instance of ialarm-mqtt on the production HA. On the test HA I've both installaed but not running at the same time. Anyway I noticed the issue on the production HA where I have just on instance. I just hit "clean discovery" to execute a cleanup. I'll have at look at the log if the issue will occur again.

maurizioandreotti60 commented 2 years ago

To be sure I made a restart of HA, but the sensors went unavailable again. From the ialarm-mqtt log I see the following:

info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: Starting TCP connection... info: Error Client is connecting. New requests will be ignored until we receive a response. - "Error: Client is connecting. New requests will be ignored until we receive a response.\n at Object.error (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-events.js:52:40)\n at Object.executeCommand (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:524:21)\n at Timeout. (file:///app/ialarm-mqtt/index.js:53:24)\n at listOnTimeout (node:internal/timers:559:17)\n at processTimers (node:internal/timers:502:7)" info: con-288/2104: logged in to 192.168.0.99:18034 with response {"commandName":"Client","connectionId":"288","transactionId":"2104","encrypted":"@ieM0071000100000}<<\}0r\b~rk}_B1\u0004yWDxd^dY'BpptGy64x\u001ehec|xa\u001d0^|-xqFI%Xc\u001ejk2\u0003QYa0\u0017\u001c!\rL\u00130000","xml":"ERR|00","rawData":{"Root":{"Pair":{"Client":{"Err":{}}}},"Err":"ERR|00"}} info: logged in (1669495297012) info: Setting up first TCP command to retrieve mac address... info: First connection OK: alarm panel responded {"mac":"00:00:18:33:36:30","name":"TCPIP_PANEL","ip":"192.168.0.99","gate":"192.168.0.1","subnet":"","dns1":"8.8.8.8","dns2":"8.8.4.4","err":""} info: Retrieving zone info ... info: Caching ialarm/alarm/availability until Sat Nov 26 2022 21:46:37 GMT+0100 (Central European Standard Time) info: sending topic 'ialarm/alarm/availability' (changed: ["1(oldvalue=f,newvalue=n)","2(oldvalue=f,newvalue=l)","3(oldvalue=l,newvalue=i)","4(oldvalue=i,newvalue=n)","5(oldvalue=n,newvalue=e)","6(oldvalue=e,newvalue=undefined)","6(oldvalue=e,newvalue=undefined)"]): undefined info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: got 40 ' zones info' info: removeDisabledZones: filtering out zone 8 with typeId disabled {"id":8,"name":"Finestra mans","type":"Disabilitata","typeId":0,"voiceId":1,"voiceName":"Fisso","zone":8} info: removeDisabledZones: filtering out zone 17 with typeId disabled {"id":17,"name":"Sens porta met.","type":"Disabilitata","typeId":0,"voiceId":1,"voiceName":"Fisso","zone":17}

But the error occurred just after the start of the add-on, not at the time the sensors went unavailable. When this occurred no error messages were produced. The sensors remained unavailable for about 6 seconds.

maxill1 commented 1 year ago

The only parts of the code where ialarm-mqtt sends ialarm/alarm/availability=offline are:

at disconnection from the TCP alarm connection In this case you should see in the logs: "disconnected (type: something, errorCount: number)"

at disconnection from mqtt broker (as "Last Will and Testament") To check this you should monitor the messages received on ialarm/alarm/availability topic. You can do it with MQTT explorer or via home assistant "MQTT info":

maurizioandreotti60 commented 1 year ago

This is the last occurrence I had

immagine

This is the log at the time of the issue

info: Starting TCP connection... (node:150) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit info: Error Client is connecting. New requests will be ignored until we receive a response. - "Error: Client is connecting. New requests will be ignored until we receive a response.\n at Object.error (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-events.js:52:40)\n at Object.executeCommand (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:524:21)\n at Timeout. (file:///app/ialarm-mqtt/index.js:53:24)\n at listOnTimeout (node:internal/timers:559:17)\n at processTimers (node:internal/timers:502:7)" info: con-8111/7218: logged in to 192.168.0.99:18034 with response {"commandName":"Client","connectionId":"8111","transactionId":"7218","encrypted":"@ieM0071000100000}<<\}0r\b~rk}_B1\u0004yWDxd^dY'BpptGy64x\u001ehec|xa\u001d0^|-xqFI%Xc\u001ejk2\u0003QYa0\u0017\u001c!\rL\u00130000","xml":"ERR|00","rawData":{"Root":{"Pair":{"Client":{"Err":{}}}},"Err":"ERR|00"}} info: logged in (1670004028916) info: Setting up first TCP command to retrieve mac address... info: First connection OK: alarm panel responded {"mac":"00:00:18:33:36:30","name":"TCPIP_PANEL","ip":"192.168.0.99","gate":"192.168.0.1","subnet":"","dns1":"8.8.8.8","dns2":"8.8.4.4","err":""} info: Retrieving zone info ... info: Caching ialarm/alarm/availability until Fri Dec 02 2022 19:05:28 GMT+0100 (Central European Standard Time) info: sending topic 'ialarm/alarm/availability' (changed: ["1(oldvalue=f,newvalue=n)","2(oldvalue=f,newvalue=l)","3(oldvalue=l,newvalue=i)","4(oldvalue=i,newvalue=n)","5(oldvalue=n,newvalue=e)","6(oldvalue=e,newvalue=undefined)","6(oldvalue=e,newvalue=undefined)"]): undefined info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending "GetZone" (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined) info: got 40 ' zones info'

About the Avalability topic I cannot see anytrhingf strange:

immagine

maverick1982 commented 1 year ago

Some days ago I installed the 0.12.0 version (it is a fresh installation, not an upgrade from previous version) and I have the same problem of frequent unavailability of all iAlarm devices. I'm using a iAlarm-XR and in the add-on server configuration I set the remote antifurto365 host (47.91.74.102) Let me know if some log can help you in the debugging process.

maxill1 commented 1 year ago

Some days ago I installed the 0.12.0 version (it is a fresh installation, not an upgrade from previous version) and I have the same problem of frequent unavailability of all iAlarm devices. I'm using a iAlarm-XR and in the add-on server configuration I set the remote antifurto365 host (47.91.74.102) Let me know if some log can help you in the debugging process.

Sorry but this is not meant for XR version and external IP/cloud. You should not use their IP for many reasons (some time ago antifurto365 turned down another project focused on XR for using their IP). Actually I'm surprised it works.

The unavailability happens when:

the connection is closed by the host (reset, timeout, etc)
the host sends an error to the TCP socket
when another ialarm-mqtt internal error occours

Using cloud IP o external IP of the router may introduce latency, timeout or ISP routing error.

Surely some logs with evidence of disconnection will help.

maverick1982 commented 1 year ago

Where should I search the correct logs? In the main home-assistant.log I didn't find errors related to iAlarm connection

2023-01-05 12:25:50.953 WARNING (SyncWorker_2) [homeassistant.loader] We found a custom integration midea_dehumidifier_lan which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2023-01-05 12:25:50.953 WARNING (SyncWorker_2) [homeassistant.loader] We found a custom integration smartthinq_sensors which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2023-01-05 12:25:50.953 WARNING (SyncWorker_2) [homeassistant.loader] We found a custom integration powercalc which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2023-01-05 12:25:50.957 WARNING (SyncWorker_2) [homeassistant.loader] We found a custom integration hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2023-01-05 12:51:10.548 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:15:41.375 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:25:11.621 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:33:11.900 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:53:12.134 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:58:12.270 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 13:59:42.275 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-01-05 14:04:12.415 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}

neither in the ialarm-mqtt logs I can find in the GUI

info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending "GetZone" (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: got 24 ' zones info'
info: removeDisabledZones: filtering out zone 13 with empty name {"id":13,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":13}
info: removeDisabledZones: filtering out zone 14 with empty name {"id":14,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":14}
info: removeDisabledZones: filtering out zone 15 with empty name {"id":15,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":15}
info: removeDisabledZones: filtering out zone 16 with empty name {"id":16,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":16}
info: removeDisabledZones: filtering out zone 17 with empty name {"id":17,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":17}
info: removeDisabledZones: filtering out zone 18 with empty name {"id":18,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":18}
info: removeDisabledZones: filtering out zone 19 with empty name {"id":19,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":19}
info: removeDisabledZones: filtering out zone 20 with empty name {"id":20,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":20}
info: removeDisabledZones: filtering out zone 21 with empty name {"id":21,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":21}
info: removeDisabledZones: filtering out zone 22 with empty name {"id":22,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":22}
info: removeDisabledZones: filtering out zone 23 with empty name {"id":23,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":23}
info: removeDisabledZones: filtering out zone 24 with empty name {"id":24,"name":"","type":"Perimetrale","typeId":2,"voiceId":1,"voiceName":"Fisso","zone":24}
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: A request is in progress...we will wait for response before sending ["GetByWay","GetAlarmStatus"] (undefined)
info: Caching ialarm/sensors/state until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/state' (changed: ["expired"]): Array of 12 elements
info: Caching ialarm/sensors/zone_1 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_1' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_2 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_2' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_3 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_3' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_4 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_4' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_5 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_5' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_6 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_6' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_7 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_7' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_8 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_8' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_9 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_9' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_10 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_10' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_11 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_11' (changed: ["expired"]): Object with 12 keys
info: Caching ialarm/sensors/zone_12 until Thu Jan 05 2023 14:16:43 GMT+0100 (Central European Standard Time)
info: sending topic 'ialarm/sensors/zone_12' (changed: ["expired"]): Object with 12 keys

maxill1 commented 1 year ago

the last logs you posted are from the the ialarm-mqtt addon tab, but they are partial and I cant find any hint on the issue.

To get the full log you should logcat the image with docker or install portainer and fetch more logs from there.

maverick1982 commented 1 year ago

Thankyou for suggestions but unfortunately I've not a docker installation but an Home Assistant Operating System (VM) installation. Could you tell me where to find log file in this kind of installation?

maverick1982 commented 1 year ago

I noted this warning log when sensors become unavailable

WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}

Can this help to find the cause of the error?

maxill1 commented 1 year ago

The payload {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"} is the default payload that ialarm-mqtt creates when parsing a GetAlarmStatus or GetArea command response, normally status_1, status_2, status_3 and status_4 should take the values that the alarm panel sends back from those commands.

I assume that on your panel GetAlarmStatus or GetArea commands are returning an unexpected response and then ialarm-mqtt is publishing the default payload.

I've updated the development addon (ialarm-mqtt-dev version dev-5e82642) to print some more logs.

Install the dev addon then search for any of these logs:

1) "GetAlarmStatus and GetArea returned an empty response" if the alarm panel is sending empty data 2) "GetAlarmStatus and GetArea returned an unhandled response: { ...JSON_DATA }" if the alarm panel is sending a data in a different format than I expected.

Please report back the logs.

maverick1982 commented 1 year ago

Ok, I installed the development version. I have just 2 questions:

Which log level GetAlarmStatus and GetArea have?
Where i have to find this logs? In the home-assistant.log file where I found the previous log? (WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"})

maverick1982 commented 1 year ago

I can't find logs for GetAlarmStatus and GetArea. I found only this logs:

[...]
2023-02-04 15:13:55.703 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/state (qos=0): b'{"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}'
2023-02-04 15:13:55.704 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}' with variables {'entity_id': 'alarm_control_panel.alarm', 'name': 'Alarm', 'this': <template TemplateStateFromEntityId(alarm_control_panel.alarm)>} and Template("{{ value_json.status_1 }}")
2023-02-04 15:13:55.705 WARNING (MainThread) [homeassistant.components.mqtt.alarm_control_panel] Received unexpected payload: {"status_1":"UNKNOWN","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}
2023-02-04 15:14:33.271 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/availability (qos=0): b'offline'
2023-02-04 15:14:38.365 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/availability (qos=0): b'online'
2023-02-04 15:16:10.804 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/availability (qos=0): b'offline'
2023-02-04 15:18:33.346 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/configStatus (qos=0): b'{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}'
2023-02-04 15:18:33.347 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}' with variables {'entity_id': 'binary_sensor.alarm_comunication_status', 'name': 'Alarm comunication status', 'this': <template TemplateStateFromEntityId(binary_sensor.alarm_comunication_status)>} and Template("{{ value_json.connectionStatus | tojson }}")
2023-02-04 15:18:33.349 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}' with variables {'entity_id': 'switch.alarm_clean_cache', 'name': 'Alarm clean cache', 'this': <template TemplateStateFromEntityId(switch.alarm_clean_cache)>} and Template("{{ value_json.cacheClear }}")
2023-02-04 15:18:33.349 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}' with variables {'entity_id': 'switch.alarm_clean_discovery', 'name': 'Alarm clean discovery', 'this': <template TemplateStateFromEntityId(switch.alarm_clean_discovery)>} and Template("{{ value_json.discoveryClear }}")
2023-02-04 15:18:33.349 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}' with variables {'entity_id': 'switch.alarm_clean_triggered', 'name': 'Alarm clean triggered', 'this': <template TemplateStateFromEntityId(switch.alarm_clean_triggered)>} and Template("{{ value_json.cancel }}")
2023-02-04 15:18:33.350 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"cacheClear":"OFF","discoveryClear":"OFF","cancel":"OFF","connectionStatus":{"connected":false,"message":"Client is disconnected. New requests will be ignored until we receive a response.","stack":"","date":"2023-02-04T14:18:33.335Z"}}' with variables {'entity_id': 'binary_sensor.alarm_comunication_status', 'name': 'Alarm comunication status', 'this': <template TemplateStateFromEntityId(binary_sensor.alarm_comunication_status)>} and Template("{{value_json.connectionStatus.connected}}")
2023-02-04 15:20:12.880 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/availability (qos=0): b'online'
2023-02-04 15:21:53.971 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/alarm/state (qos=0): b'{"status_1":"disarmed","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}'
2023-02-04 15:21:53.972 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"status_1":"disarmed","status_2":"UNKNOWN","status_3":"UNKNOWN","status_4":"UNKNOWN"}' with variables {'entity_id': 'alarm_control_panel.alarm', 'name': 'Alarm', 'this': <template TemplateStateFromEntityId(alarm_control_panel.alarm)>} and Template("{{ value_json.status_1 }}")
2023-02-04 15:21:53.978 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/sensors/zone_1 (qos=0): b'{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}'
2023-02-04 15:21:53.979 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.zone_1_entrata', 'name': 'Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.zone_1_entrata)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:53.979 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.battery_zone_1_entrata', 'name': 'Battery Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.battery_zone_1_entrata)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:53.980 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.alarm_zone_1_entrata', 'name': 'Alarm Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.alarm_zone_1_entrata)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:53.980 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.connectivity_zone_1_entrata', 'name': 'Connectivity Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.connectivity_zone_1_entrata)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:53.980 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'switch.bypass_zone_1_entrata', 'name': 'Bypass Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(switch.bypass_zone_1_entrata)>} and Template("{{ '1' if value_json.bypass else '0' }}")
2023-02-04 15:21:53.980 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.zone_1_entrata', 'name': 'Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.zone_1_entrata)>} and Template("{{ '1' if value_json.fault else '0' }}")
2023-02-04 15:21:53.980 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.battery_zone_1_entrata', 'name': 'Battery Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.battery_zone_1_entrata)>} and Template("{{ '1' if value_json.lowbat else '0' }}")
2023-02-04 15:21:53.981 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.alarm_zone_1_entrata', 'name': 'Alarm Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.alarm_zone_1_entrata)>} and Template("{{ '1' if value_json.alarm else '0' }}")
2023-02-04 15:21:53.981 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":1,"name":"L0","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.connectivity_zone_1_entrata', 'name': 'Connectivity Zone 1 Entrata', 'this': <template TemplateStateFromEntityId(binary_sensor.connectivity_zone_1_entrata)>} and Template("{{  '0' if value_json.wirelessLoss else '1' }}")
2023-02-04 15:21:54.006 DEBUG (MainThread) [homeassistant.components.mqtt.client] Received message on ialarm/sensors/zone_2 (qos=0): b'{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}'
2023-02-04 15:21:54.008 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.zone_2_cucina_balcone', 'name': 'Zone 2 Cucina balcone', 'this': <template TemplateStateFromEntityId(binary_sensor.zone_2_cucina_balcone)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:54.008 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.battery_zone_2_cucina_balcone', 'name': 'Battery Zone 2 Cucina balcone', 'this': <template TemplateStateFromEntityId(binary_sensor.battery_zone_2_cucina_balcone)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:54.009 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.alarm_zone_2_cucina_balcone', 'name': 'Alarm Zone 2 Cucina balcone', 'this': <template TemplateStateFromEntityId(binary_sensor.alarm_zone_2_cucina_balcone)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:54.009 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'binary_sensor.connectivity_zone_2_cucina_balcone', 'name': 'Connectivity Zone 2 Cucina balcone', 'this': <template TemplateStateFromEntityId(binary_sensor.connectivity_zone_2_cucina_balcone)>} and Template("{{ value_json | tojson }}")
2023-02-04 15:21:54.009 DEBUG (MainThread) [homeassistant.components.mqtt.models] Rendering incoming payload '{"id":2,"name":"L1","status":1,"inUse":true,"ok":true,"alarm":false,"bypass":false,"lowbat":false,"fault":false,"wirelessLoss":false,"problem":false,"message":"OK"}' with variables {'entity_id': 'switch.bypass_zone_2_cucina_balcone', 'name': 'Bypass Zone 2 Cucina balcone', 'this': <template TemplateStateFromEntityId(switch.bypass_zone_2_cucina_balcone)>} and Template("{{ '1' if value_json.bypass else '0' }}")
[...]

maxill1 commented 1 year ago

You can find ialarm-mqtt-dev addon logs in the addon page, just select "log" tab ("registro" in italiano).

Go to your hassio store instance (http://localhost:8123/hassio/store), find and select alarm-mqtt-dev

In the alarm-mqtt-dev addon page, select "logs" (registro in italian)

Search for any useful error in there

maverick1982 commented 1 year ago

Yes, I know this but my problem is that in this place is visible just a little part of the log (more or less last 100 rows). How can I retrieve the whole logs?

maxill1 commented 1 year ago

Yeah the add-ons logs are limited on home assistant (if I remember correctly latest 50 entries).

Anyway those are docker container logs and the easiest way to check them is to install portainer add-on and browse ialarm-mqtt-dev addon logs from there or gain access to the host and go with docker logs command (harder to do on hassio systems).

maverick1982 commented 1 year ago

First of all thank you very much for the help and support!!

In the container log I found these two kinds of errors

2023-02-05T12:48:43.427100000Z error: GetAlarmStatus and GetArea returned an unhandled response: {"timeout":2000,"error":"Timeout: After 2000ms no response has been received by command GetAlarmStatus: {\"seq\":0,\"message\":\"@ieM0093000100000j!!\\u0016\\u0006\\u0011*aK:pxHDNTJJF_.\\u0003@M=\\u000er\\bR]C';xU0\\u0013+>\\u0006!8\\u000b6M6d$\\f\\u0016e2D)\\u001cy\\u0001\\u0010\\u0010\\u0006\\u0017pK]:\\u000f\\u000eY_\\u000f]L9,}]\\u001d\\u0010 pDK_2fMfW_Dp0000\"}"}

2023-02-05T13:04:13.817475000Z error: con-8025: throw an error: con-8025/55-comm-GetAlarmStatus: Client is currently waiting for a response. New requests will be ignored until we receive a response from previous message. {"stack":"Error: con-8025/55-comm-GetAlarmStatus: Client is currently waiting for a response. New requests will be ignored until we receive a response from previous message.\n    at file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:430:16\n    at new Promise (<anonymous>)\n    at sendMessage (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:423:12)\n    at sendCommands (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:156:30)\n    at async Object.executeCommand (file:///app/ialarm-mqtt/node_modules/ialarm/src/meian-socket.js:530:26)\n    at async Timeout.<anonymous> (file:///app/ialarm-mqtt/index.js:53:11)"}

maxill1 / ialarm-mqtt