Envisalink seems spotty after latest upgrades

bdf0506 · August 1, 2018, 9:18pm

I am running 0.74.2, and it seems that ever since I crossed over into .74.x, I seem to be having instability issues with the Envisalink module. To be frank, I don’t recall what version in particular I was previously on, but know that I keep having some issues. For all I know, it can be another environmental issue that has caused this.

Usually, it is a motion detector that will appear to stay in a forever open state according to HA. If I look at the Envisalink module itself, it will show that the zone closes, the syslog from Envisalink will confirm it. Though, for some reason it is not getting the close event sent over the HA. I am using this with a Honeywell Vista20P system. It’s been running for ~6 months without an issue, until this started appearing.

Config is as such, not sure if it is relevant at this point. Would be curious to know if anyone else is seeing an issue in this lately. Will post more info/logs as I come across the conditions again.

envisalink:
  host: envisalink.home
  panel_type: HONEYWELL
  user_name: user
  password: <redacted>
  code: '<redacted>'
  port: 4025
  evl_version: 4
  keepalive_interval: 60
  zonedump_interval: 15
  panic_type: Police
  zones:
    1:
      name: 'Fire'
      type: 'smoke'
    2:
      name: 'Front Door'
      type: 'door'
    3:
      name: 'Carport Door'
      type: 'door'
    4:
      name: 'Laundry Door'
      type: 'door'
    5:
      name: 'Back Porch Door'
      type: 'door'
    6:
      name: 'Motion Detector'
      type: 'motion'
  partitions:
    1:
      name: 'Alarm'

bdf0506 · August 2, 2018, 3:13pm

Here’s some more indication of things not working correctly. It looks like the close events aren’t being reported consistently. Sometimes they are, sometimes they aren’t.

From the syslog of Envisalink, for the carport zone, i see an open/close event, and a matching one in HA. I know that the way Envisalink works with the Honeywell panel is that closes aren’t reported immediately to the Envisalink, and they are on somewhat of a delay.

Aug 2 07:38:16 Alarm.home ENVISALINK[001C2A010000]: Zone Open: 3

From Homassistant logs:

2018-08-02 07:38:16 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones…

2018-08-02 07:38:16 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent new alarm info. Updating alarms…

2018-08-02 07:38:16 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.carport_door, old_state=<state binary_sensor.carport_door=off; last_tripped_time=2018-08-01T20:58:58-04:00, friendly_name=Carport Door, device_class=door, custom_ui_state_card=state-card-custom-ui, show_last_changed=True @ 2018-08-01T20:59:37.627918-04:00>, new_state=<state binary_sensor.carport_door=on; last_tripped_time=2018-08-02T07:38:16-04:00, friendly_name=Carport Door, device_class=door, custom_ui_state_card=state-card-custom-ui, show_last_changed=True @ 2018-08-02T07:38:16.835672-04:00>>

2018-08-02 07:38:16 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.alarm_sensors, old_state=<state group.alarm_sensors=off; entity_id=(‘alarm_control_panel.alarm’, ‘sensor.alarm_keypad’, ‘binary_sensor.fire’, ‘binary_sensor.front_door’, ‘binary_sensor.carport_door’, ‘binary_sensor.back_porch_door’, ‘binary_sensor.laundry_door’, ‘binary_sensor.motion_detector’), order=1, control=hidden, friendly_name=Alarm System @ 2018-08-01T22:26:53.022083-04:00>, new_state=<state group.alarm_sensors=on; entity_id=(‘alarm_control_panel.alarm’, ‘sensor.alarm_keypad’, ‘binary_sensor.fire’, ‘binary_sensor.front_door’, ‘binary_sensor.carport_door’, ‘binary_sensor.back_porch_door’, ‘binary_sensor.laundry_door’, ‘binary_sensor.motion_detector’), order=1, control=hidden, friendly_name=Alarm System @ 2018-08-02T07:38:16.845978-04:00>>

But then Envisalink reports the zone closed, but no matching event in Home Assistant.

Aug 2 07:39:12 Alarm.home ENVISALINK[001C2A010000]: Zone Closed: 3

Matching up the timestamps in HA, closest I see is this, which is typically a message that I see displayed every 10 seconds or so. Nothing was sent to HA that mentions anything about a zone close event.

2018-08-02 07:39:07 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent new alarm info. Updating alarms…

2018-08-02 07:39:17 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent new alarm info. Updating alarms…

It seems that if I trigger an unrelated zone, then it will finally sent a zone closed alert. This is behavior that I haven’t seen in HA in the past, so I am wondering if the module has changed at all.

mattlebaugh · August 3, 2018, 12:27pm

They were trying to fix another issue… Seems they caused you one.

https://github.com/home-assistant/home-assistant/issues/15407#issuecomment-409351586

I’ve just rolled back to 69.1 to avoid all of it for now.

bdf0506 · August 3, 2018, 1:02pm

In doing more testing yesterday, it looks like close events aren’t reported at all, or intermittently. Instead, a close event is really only recorded when another open event is created.

There is a zonedump_interval configuration item on Envisalink which is needed in order to query the envisalink to see what is open, since Honeywell systems don’t really report zone closed events. I believe the issue lies within this configuration, and with the latest update, it may be ignoring this option.

digiblur · August 3, 2018, 2:32pm

Why is there a delay between the 20p and EVL as you said? I use the Alarmdecoder solution but it is the same type of solution where it reads the keypad bus. I see the events immediately.

bdf0506 · August 3, 2018, 3:03pm

This is what the zonedump_interval is for, I believe. Since the Envisalink/Honeywell Vista 20P doesn’t report on closure events, the zonedump is for a re-read of current status from the system.

digiblur · August 3, 2018, 3:23pm

No closure? Trying to wrap my head around this. Shouldn’t it read from the panel and push the closure when the event happens?

bdf0506 · August 3, 2018, 3:40pm

Honeywell Vista 20P doesnt really alert on closure events. Rather, the Envisalink or your Alarmdecoder is polling the alarm again after x seconds, and sees that a zone is closed, so then agrees that a zone is closed, and then will show it is closed.

That functionality seems to have stopped working in the most recent update. I am seeing that a zone will report closed when another zone is open, since at that point it appears to grab the latest status of all the zones.

So, most of the time I am seeing behavior like this:
Zone 2 opens at 2:00 ----> reports at 2:00 to HA that Zone 2 is open.
Zone 2 closes at 2:04 —> never gets reported to HA
Zone 3 opens at 2:06 ----> At 2:06, Zone 3 is reported open to HA, and at this point, Zone 2 is reported closed to HA, even though it closed 2 min early, and zonedump_interval is set to something much lower than 2 min.

digiblur · August 3, 2018, 3:59pm

I have a Vista 20p. It doesn’t poll from what I’ve seen, it’s only listening on the keypad bus just like a keypad would. You don’t even have to be a registered keypad to see the packets aka, you are in read only mode. That just seems troublesome why an event is not being recorded by EVL from the 20p itself.

cameronr · August 3, 2018, 4:52pm

The fixes for that issue haven’t been merged into master yet (they’re not even in 0.75.0). You can see that pyenvisalink 2.2 instead of 2.3 is still referenced here:

github.com

home-assistant/core/blob/0.75.0/homeassistant/components/envisalink.py

"""
Support for Envisalink devices.

For more details about this component, please refer to the documentation at
https://home-assistant.io/components/envisalink/
"""
import asyncio
import logging

import voluptuous as vol

from homeassistant.core import callback
import homeassistant.helpers.config_validation as cv
from homeassistant.const import EVENT_HOMEASSISTANT_STOP
from homeassistant.helpers.entity import Entity
from homeassistant.helpers.discovery import async_load_platform
from homeassistant.helpers.dispatcher import async_dispatcher_send

REQUIREMENTS = ['pyenvisalink==2.2']

This file has been truncated. show original

So this is likely a separate, unrelated issue.

mattlebaugh · August 3, 2018, 5:32pm

Ah ok. I was just watching the other issue as it was causing me issues when I saw this thread.

bdf0506 · August 3, 2018, 8:37pm

So maybe after all, I do need the fix that was referenced. Looked closer today and found these:

2018-08-03 16:35:51 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink… at alarm.home:4025
2018-08-03 16:35:51 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2018-08-03 16:35:51 INFO (MainThread) [homeassistant.components.envisalink] Established a connection with the Envisalink
2018-08-03 16:35:51 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport
Traceback (most recent call last):
File “uvloop/handles/stream.pyx”, line 827, in uvloop.loop.__uv_stream_on_read_impl
File “/usr/local/lib/python3.6/site-packages/pyenvisalink/envisalink_base_client.py”, line 179, in data_received
callbackFunc(result)
File “/usr/local/lib/python3.6/site-packages/homeassistant/components/envisalink.py”, line 127, in connection_success_callback
sync_connect.set_result(True)
asyncio.base_futures.InvalidStateError: invalid state
2018-08-03 16:35:51 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting…
2018-08-03 16:35:56 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink… at alarm.home:4025
2018-08-03 16:35:56 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2018-08-03 16:35:56 INFO (MainThread) [homeassistant.components.envisalink] Established a connection with the Envisalink
2018-08-03 16:35:56 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport
Traceback (most recent call last):
File “uvloop/handles/stream.pyx”, line 827, in uvloop.loop.__uv_stream_on_read_impl
File “/usr/local/lib/python3.6/site-packages/pyenvisalink/envisalink_base_client.py”, line 179, in data_received
callbackFunc(result)
File “/usr/local/lib/python3.6/site-packages/homeassistant/components/envisalink.py”, line 127, in connection_success_callback
sync_connect.set_result(True)
asyncio.base_futures.InvalidStateError: invalid state
2018-08-03 16:35:56 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting…

Cinntax · August 4, 2018, 12:14am

Hello everyone, been reading the back and forth- I think everyone is on the right track.

First of all- yes i can confirm that the vista panels simply don’t report closure events, and the envisalink is actually doing some interpretation of the zone timers (transparent to us) to report zone statuses.

The zonetimer dump is another way to “reconcile” the states of all the zones in addition to what the envisalink already does. The pyenvisalink library is looking at those to assist with zone status. The pyenvisalink library does do polling there according to the interval defined, and when it polls- it does a live callback to HA. So it’s polling, but HA isn’t polling, if that makes sense.

The latest issue reported here is due to some changes made a while back to support asynchronous setup. The HA component is essentially is assuming that the only time a connection can be made to the evl is during the initial system setup, which is not really true, as you’re finding out. So I do have a fix that people have been testing but it hasnt been pushed into the main HA line yet. So I can get this pushed ASAP to help.

bdf0506 · August 7, 2018, 4:26pm

I upgraded to 0.75.2 and it might be better, since I do in fact see a reconnect happening. But I did see this message now, expected?

2018-08-07 12:22:31 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones...
2018-08-07 12:22:32 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent new alarm info. Updating alarms...
    2018-08-07 12:22:36 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones...
2018-08-07 12:22:43 ERROR (MainThread) [pyenvisalink.honeywell_client] Unrecognized data recieved from the envisalink. Ignoring.
2018-08-07 12:22:43 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport
Traceback (most recent call last):
  File "uvloop/handles/stream.pyx", line 827, in uvloop.loop.__uv_stream_on_read_impl
  File "/usr/local/lib/python3.6/site-packages/pyenvisalink/envisalink_base_client.py", line 165, in data_received
    _LOGGER.debug(str.format('calling handler: {0} for code: {1} with data: {2}', cmd['handler'], cmd['code'], cmd['data']))
TypeError: 'NoneType' object is not subscriptable
2018-08-07 12:22:43 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2018-08-07 12:22:48 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at alarm.home:4025
2018-08-07 12:22:48 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2018-08-07 12:22:48 INFO (MainThread) [homeassistant.components.envisalink] Established a connection with the Envisalink
2018-08-07 12:22:51 INFO (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones...

Cinntax · August 13, 2018, 3:30am

Ahh- i see. Yeah so basically what’s happening here is that when the connection fails, immediately before that we get junk sent over, and the message parser is (correctly) ignoring it, but after that i have some logic that is supposed to print a nicer message in this scenario, but it’s not catching it. Does everything still recover properly?

Cinntax · August 13, 2018, 4:49am

While working on another enhancement, i went ahead and added the additional logic for this as well- so if you were to pull https://github.com/Cinntax/home-assistant/tree/dev it should not throw that error anymore (it will upgrade pyenvisalink to version 3.4).

digiblur · August 13, 2018, 12:44pm

Thanks for the confirmation. Looks like they need to implement the virtual relay to correct the issue.

mcaminiti · October 20, 2018, 5:13am

I’m not sure if my issue is related to this but I happened to have a loose ethernet cable to my Envisalink panel. When this occurred I noticed that Home-Assistant fails to start and just hangs.

This is the error I see and HA will just fail to start. I haven’t seen any other components prevent HA from starting if unreachable.

2018-10-19 23:57:21 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File “uvloop/loop.pyx”, line 1881, in create_connection
File “uvloop/loop.pyx”, line 1860, in uvloop.loop.Loop.create_connection
OSError: [Errno 113] No route to host

I can reproduce this issue just by using a bad IP in the config or making it a host that is unreachable with a cable unplug.

4romany · January 1, 2019, 3:13pm

Newbie here. I just setup HA communicating to my DCS 1832 alarm panel via the Envislink board and I can confirm there some work that needs to be done. So if I open an zone I’ll get that status change in HA almost immediately - but few seconds later you see HA send a packet to the panel (I’m running a tcpdump at the time) and the status changes to clear…if I clear the alarm (close the window) I see the panel (in tcpdump) alerts HA - alarm clears - few seconds later packet from HA to panel - and the alarm comes back. It does clear after a few seconds after that.

I need to point out that I’m NOT communicating directly to the Envislink board - I’m going thru an Android server app called DCSSERVER. DCSSERVER talks to the envislink - and will proxies other sessions. So my HA and Vera setup BOTH talks to the panel via DCSSERVER. I have no issues at all with Vera seeing DCS alarms correctly - but I do with HA. But have not tried to commuicate directly to envislink from HA - but I doubt that I’ll see a difference in behavior since what I’m seeing appears to be happenging to others…

Cinntax · January 1, 2019, 10:23pm

I think this might be in relation to the zone timer dump functionality- the envisalink board is used not only for DSC panels, but for Honeywell panels also. Honeywell panels are not nearly as “event based” as the DSC ones are, and so there’s essentially a polling mechanism that’s enabled by default that queries the board. I’m pretty sure that’s what packets you’re seeing.
What happens if you set, in your configuration.yaml entry for the envisalink, your zonedump interval to -1?

zonedump_interval: 0

Also just thought i’d mention in there that I’m in the middle of committing new changes to the component with this release, adding the ability to trigger the PGM1-4 functions from HA, and bolstering the error handling when a poor network connection is present.