Dilbert66 / esphome-vistaECP

This is an implementation of an ESPHOME custom component and ESP Library to interface directly to a Safewatch/Honeywell/Ademco Vista 15/20 alarm system using the ECP interface and very inexpensive ESP8266/ESP32 modules .
GNU Lesser General Public License v2.1
125 stars 21 forks source link

Error and Reset / hang when wireless sensor reports open #35

Closed jn3va closed 3 years ago

jn3va commented 3 years ago

I upgraded my panel to a Vista21IP. I have 8500 series wireless sensors (glassbreaks, contacts, motions, etc.) I'm monitoring the VistaECP output in the ESPHome log. When a wireless zone sends its open status, I get a small pause, and then a connection error. For things like doors the state will eventually show correctly e.g. "Fault Zone 11 Basement Door". For other sensors (like glassbreaks), HA never gets the open signal. It does this for every wireless zone. I'm guessing it's trying to decode something and can't pay attention to the logout put connection.

For a glassbreak - the HA History shows that the device is closed (C) until I trigger it, and then it shows unavailable for about 1 second. If there are too many of these failures in a row, the ESP32 seems to hang - in the dashboard all of the alarm devices change to unavailable; but eventually, things seem to resolve without intervention. I confirmed in the history for the glassbreak sensor I was testing with (see attached screenshot)

Not a huge deal for a glass-breaks, since that will trigger an alarm status, but I'm wondering when I add in devices like motions, or if people are going in and out of doors with wireless contacts if this might cause the board to crash frequently. An example of the log output with an error is below, and a longer log capture is included as an attached file.

Is there any other logging or detail I can gather to see if we can figure out what's happening when the wireless devices send their status?

vistaECP_21IP_fault.txt GlassBreak_HA_history ContactSensor_HA_history

[12:38:30][I][CMD:351]: F7 00 00 FF 10 08 00 5C 08 02 00 00 [12:38:30][D][text_sensor:015]: 'esp_vista Line1': Sending state 'DISARMED' [12:38:30][D][text_sensor:015]: 'esp_vista Line2': Sending state ' Ready to Arm ' [12:38:30][I][INFO:580]: Prompt: DISARMED [12:38:30][I][INFO:581]: Prompt: Ready to Arm
[12:38:30][I][INFO:582]: Beeps: 0

[12:38:34][I][CMD:351]: F7 00 00 FF 10 08 00 5C 08 02 00 00 [12:38:34][D][text_sensor:015]: 'esp_vista Line1': Sending state 'SYSTEM LO BAT ' [12:38:34][D][text_sensor:015]: 'esp_vista Line2': Sending state ' ' [12:38:34][I][INFO:580]: Prompt: SYSTEM LO BAT

[12:38:34][I][INFO:582]: Beeps: 0

[12:38:36][I][CMD:351]: F9 93 00 00 00 00 00 00 00 00 00 00 [12:38:36][I][CMD:351]: F9 83 00 00 00 00 00 00 00 00 00 00 [12:38:36][I][CMD:351]: 9E 02 20 F1 F2 00 00 00 00 00 00 00 [12:38:37][I][CMD:351]: 9E 02 20 80 63 00 00 00 00 00 00 00 [12:38:37][I][CMD:351]: 9E 02 20 F1 F2 00 00 00 00 00 00 00 [12:38:37][I][EXT:351]: 9E 04 06 18 98 B0 00 00 00 00 00 00

[12:38:37][D][info:552]: RFX: 0399512,b0 ERROR Error while reading incoming messages: Error while receiving data: [Errno 104] Connection reset by peer WARNING Disconnected from API: Error while receiving data: [Errno 104] Connection reset by peer INFO Connecting to 192.168.1.82:6053 (192.168.1.82) WARNING Couldn't connect to API (Timeout while waiting for message response!). Trying to reconnect in 1 seconds

INFO Connecting to 192.168.1.82:6053 (192.168.1.82) INFO Successfully connected to 192.168.1.82 [12:38:52][I][CMD:351]: F7 00 00 FF 10 08 00 5C 08 02 00 00 [12:38:52][D][text_sensor:015]: 'esp_vista Line1': Sending state 'SYSTEM LO BAT ' [12:38:52][D][text_sensor:015]: 'esp_vista Line2': Sending state ' ' [12:38:52][I][INFO:580]: Prompt: SYSTEM LO BAT

[12:38:52][I][INFO:582]: Beeps: 0

Dilbert66 commented 3 years ago

Looks like a reboot is happening. Not sure if it's traffic related or a bug in the code. I'll look at the rfx decode code to see if that's the issue.

Dilbert66 commented 3 years ago

Would you be able to get usb serial traffic log as well? That would show if it's a reboot. There is another report of the same issue in the discussion section. I will see what I can find. I can't duplicate the process since I don't have any rf devices to test with on my vista test system but I will simulate the issue. :(

Edit: don't worry about the serial log. I can see that it's consistent with the rfx processing.

Dilbert66 commented 3 years ago

Ok, I found the problem. Totally my fault. I forgot to push the new version of the YAML to handle rf messages. I will push the new viatalarm.yaml shortly.

jn3va commented 3 years ago

Cool! And no worries this is fun! Glad it was an easy fix. I went ahead and captured a USB serial log anyway. Let me know if you want me to upload it for more data.

it was rebooting. Looks like after a while it goes into safe mode reboot, which is what I suspected for the longer pauses

Dilbert66 commented 3 years ago

ok, updated files are pushed. Just use the new vistaalarm.yaml

Dilbert66 commented 3 years ago

The issue was that it was trying to call a non existent callback function in the yaml and causing the crash. The compilation step doesnt pick up on these things.

Dilbert66 commented 3 years ago

Your inital logs were very helpful as they showed the consistent point of failure.

jn3va commented 3 years ago

Worked like a charm! Thank you!

[14:26:51][I][CMD:351]: F7 00 00 FF 10 08 00 1C 08 02 00 00 [14:26:51][D][text_sensor:015]: 'esp_vista Line1': Sending state 'DISARMED' [14:26:51][D][text_sensor:015]: 'esp_vista Line2': Sending state ' Ready to Arm ' [14:26:51][I][INFO:580]: Prompt: DISARMED [14:26:51][I][INFO:581]: Prompt: Ready to Arm
[14:26:51][I][INFO:582]: Beeps: 0

[14:26:52][I][CMD:351]: 9E 02 25 F1 ED 00 00 00 00 00 00 00 [14:26:52][I][CMD:351]: F8 59 10 5A 00 03 0A 0A 00 00 00 00 [14:26:52][I][CMD:351]: F2 12 06 00 00 00 00 61 6C 02 45 6C [14:26:53][I][CMD:351]: F2 16 06 00 00 00 00 62 63 02 45 43 [14:26:53][I][CMD:351]: F7 00 00 FF 10 15 00 00 08 02 00 00 [14:26:53][D][text_sensor:015]: 'esp_vista Line1': Sending state 'FAULT 15 ' [14:26:53][D][text_sensor:015]: 'esp_vista Line2': Sending state 'BASEMENT DOOR ' [14:26:53][I][INFO:580]: Prompt: FAULT 15
[14:26:53][I][INFO:581]: Prompt: BASEMENT DOOR
[14:26:53][I][INFO:582]: Beeps: 0

[14:26:53][D][text_sensor:015]: 'esp_vista Basement Door': Sending state 'O' [14:26:53][D][text_sensor:015]: 'esp_vista System Status': Sending state 'unavailable' [14:26:53][D][binary_sensor:036]: 'esp_vista Ready': Sending state OFF [14:26:55][I][CMD:351]: 9E 02 20 F1 F2 00 00 00 00 00 00 00 [14:26:56][I][CMD:351]: F2 12 06 00 00 00 00 63 6C 02 45 6C [14:26:56][I][CMD:351]: F8 59 10 5A 00 03 0A 0A 00 00 00 00 [14:26:56][I][CMD:351]: F2 16 06 00 00 00 00 64 63 02 45 43 [14:26:56][I][CMD:351]: F7 00 00 FF 10 BF 00 12 08 02 00 00 [14:26:56][D][text_sensor:015]: 'esp_vista Line1': Sending state 'CHECK 103 LngRng' [14:26:56][D][text_sensor:015]: 'esp_vista Line2': Sending state 'Radio 000F' [14:26:56][I][INFO:580]: Prompt: CHECK 103 LngRng [14:26:56][I][INFO:581]: Prompt: Radio 000F [14:26:56][I][INFO:582]: Beeps: 0

[14:26:56][D][text_sensor:015]: 'esp_vista Basement Door': Sending state 'C' [14:26:56][D][text_sensor:015]: 'esp_vista System Status': Sending state 'disarmed' [14:26:56][D][binary_sensor:036]: 'esp_vista Ready': Sending state ON [14:26:59][I][CMD:351]: F9 D3 00 00 00 00 00 00 00 00 00 00 [14:27:00][I][CMD:351]: F7 00 00 FF 10 08 00 1C 08 02 00 00 [14:27:00][D][text_sensor:015]: 'esp_vista Line1': Sending state 'DISARMED' [14:27:00][D][text_sensor:015]: 'esp_vista Line2': Sending state ' Ready to Arm ' [14:27:00][I][INFO:580]: Prompt: DISARMED [14:27:00][I][INFO:581]: Prompt: Ready to Arm
[14:27:00][I][INFO:582]: Beeps: 0

jn3va commented 3 years ago

Alain Thanks for your help! Things have been working flawlessly! PM me at jn3va3@ g mail.com when you have a minute (not urgent), have something I wanted to send but not post on git. Thanks! Joe