home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.14k stars 29.81k forks source link

Envisalink Integration Not Working 2022.3.5 #68317

Closed TheFuzz4 closed 1 year ago

TheFuzz4 commented 2 years ago

The problem

In version 2022.3.5 the envisalink integration is no longer working. It will talk to the module but it will not arm/disarm the alarm system. Rolled back to 2022.3.4 and there is no issue at this level.

The logs show that it connected to it and then the connection is closed immediately stating that no response was received and attempts to retry. It does semi work in that it is able to pull the current state of the alarm system but any attempts to run a command on the system fail.

What version of Home Assistant Core has the issue?

2022.3.5

What was the last working version of Home Assistant Core?

2022.3.4

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Envisalink

Link to integration documentation on our website

https://www.home-assistant.io/integrations/envisalink/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

RichieFrame commented 2 years ago
2022-04-10 15:02:49 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration nws_alerts 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
2022-04-10 15:02:49 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration feedparser 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
2022-04-10 15:02:49 WARNING (SyncWorker_2) [homeassistant.loader] We found a custom integration simpleicons 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
2022-04-10 15:02:49 WARNING (SyncWorker_3) [homeassistant.loader] We found a custom integration weatherbit 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
2022-04-10 15:02:49 WARNING (SyncWorker_4) [homeassistant.loader] We found a custom integration wiz_light 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
2022-04-10 15:02:49 WARNING (SyncWorker_0) [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
2022-04-10 15:02:49 WARNING (SyncWorker_5) [homeassistant.loader] We found a custom integration lutron_caseta_pro 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
2022-04-10 15:02:49 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration snoo 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
2022-04-10 15:02:49 ERROR (SyncWorker_1) [homeassistant.loader] The custom integration 'snoo' does not have a version key in the manifest file and was blocked from loading. See https://developers.home-assistant.io/blog/2021/01/29/custom-integration-changes#versions for more details
2022-04-10 15:02:49 WARNING (MainThread) [homeassistant.components.recorder] The 'purge_interval' option near /config/configuration.yaml:16 is deprecated, please remove it from your configuration
2022-04-10 15:02:49 WARNING (MainThread) [homeassistant.components.lovelace] Lovelace is running in storage mode. Define resources via user interface
2022-04-10 15:02:50 INFO (MainThread) [pyenvisalink.envisalink_base_client] Latching onto an existing event loop.
2022-04-10 15:02:50 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.0.6:4025
2022-04-10 15:02:50 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-04-10 15:02:50 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-04-10 15:02:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-04-10 15:02:51 WARNING (MainThread) [homeassistant.components.statistics.sensor] The configuration parameter 'state_characteristic' will become mandatory in a future release of the statistics integration. Please add 'state_characteristic: mean' to the configuration of sensor 'Temperature Smooth' to keep the current behavior. Read the documentation for further details: https://www.home-assistant.io/integrations/statistics/
2022-04-10 15:02:51 ERROR (MainThread) [homeassistant.setup] Unable to prepare setup for platform lutron_caseta_pro.fan: Platform not found (cannot import name 'SPEED_HIGH' from 'homeassistant.components.fan' (/usr/src/homeassistant/homeassistant/components/fan/__init__.py)).
2022-04-10 15:02:51 WARNING (MainThread) [homeassistant.components.statistics.sensor] The configuration parameter 'state_characteristic' will become mandatory in a future release of the statistics integration. Please add 'state_characteristic: mean' to the configuration of sensor 'Temperature Trend' to keep the current behavior. Read the documentation for further details: https://www.home-assistant.io/integrations/statistics/
2022-04-10 15:02:52 WARNING (MainThread) [homeassistant.helpers.template] Template warning: 'int' got invalid input 'unknown' when rendering template '{% if states('sensor.nws_alerts') | int > 0 %}
mdi:weather-lightning
{% else %}
mdi:weather-sunny
{% endif %}' but no default was specified. Currently 'int' will return '0', however this template will fail to render in Home Assistant core 2022.1
2022-04-10 15:02:53 WARNING (MainThread) [homeassistant.components.onvif] The date/time on the device (UTC) is '2022-04-10 21:02:53+00:00', which is different from the system '2022-04-10 20:02:53.237748+00:00', this could lead to authentication issues
2022-04-10 15:02:53 WARNING (MainThread) [homeassistant.components.onvif] The date/time on the device (UTC) is '2022-04-10 21:02:53+00:00', which is different from the system '2022-04-10 20:02:53.247843+00:00', this could lead to authentication issues
2022-04-10 15:02:53 WARNING (MainThread) [homeassistant.components.onvif] The date/time on the device (UTC) is '2022-04-10 21:02:53+00:00', which is different from the system '2022-04-10 20:02:53.162286+00:00', this could lead to authentication issues
2022-04-10 15:02:53 WARNING (MainThread) [homeassistant.components.onvif] The date/time on the device (UTC) is '2022-04-10 21:02:52+00:00', which is different from the system '2022-04-10 20:02:53.170787+00:00', this could lead to authentication issues
2022-04-10 15:02:54 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Brother MFC-J4535DW' for ipp integration not ready yet: Invalid response from API: Error occurred while communicating with IPP server.; Retrying in background
2022-04-10 15:02:54 WARNING (MainThread) [homeassistant.config_entries] Config entry '192.168.2.123' for shelly integration not ready yet: Cannot connect to host 192.168.2.123:80 ssl:default [Connect call failed ('192.168.2.123', 80)]; Retrying in background
2022-04-10 15:02:54 WARNING (MainThread) [homeassistant.config_entries] Config entry '192.168.2.131' for shelly integration not ready yet: Cannot connect to host 192.168.2.131:80 ssl:default [Connect call failed ('192.168.2.131', 80)]; Retrying in background
...... and so on

That is the start of the log as of the last restart, as you can see it is immediate. The rest of the log at restart is the common complaints about statistics changes, devices with times that differ from the system time, and devices that are not available (because they are not powered on)

ufodone commented 2 years ago

@RichieFrame : Okay, your situation is different than what's happening to @TheFuzz4 and @audymatic. You are never able to connect and their setup appears that multiple concurrent connections are being setup.

There was a change made to pyenvisalink a while back that could cause this immediate connect/disconnect loop if you upgraded HA but for some reason didn't get the latest pyenvisalink package. https://github.com/Cinntax/pyenvisalink/commit/58b095c49b58a2cd346e9772a90c7f3eb9ecdb03 I don't think that's actually the issue here because, at least in my testing, there won't actually be any network traffic to the EVL but you have indicated there is. But it's worth a check anyway.

@TheFuzz4 / @audymatic Since your issue appears to be different, a full startup log would also be helpful from your setups too. Thanks.

ufodone commented 2 years ago

@RichieFrame You might also try running a netstat on the host that is running your HA docker container both with HA running and without to confirm the connections to the EVL:

netstat -anp | grep -ư 4025
RichieFrame commented 2 years ago

Well, that commit was the trigger, I have it working now, however the problem presented identically in 2 ways when it should have not. I am using a custom pyenvisalink dependency (based on 4.1 but no changes on the connection side) that did not contain the fix for async_timeout.

However when the HA docker is updated it overwrites that dependency with the one specified in the docker container, which is apparently 4.0 and also does not have that fix (verified with pip list inside the container), so there is some other problem with the docker setup but that is out of scope here.

audymatic commented 2 years ago

So, I decided it may be time to update my HA setup from the rpi3 that it's been running on. I got a old lenovo m93p off ebay, installed proxmox, installed the HassOS VM

It's running: Home Assistant OS 8.0.rc2 Update Channel | stable Supervisor Version | supervisor-2022.04.0 Docker Version | 20.10.12

Version | core-2022.4.4 Installation Type | Home Assistant OS

So far the only thing I've added to the default config yaml is the Envisalink code. I haven't added any integrations yet. I've installed several addons but the only ones that are running are duckdns, file editor, and samba share.

It's been up for three days and hasn't thrown any errors to do with the envisalink and I've been able to arm/disarm without any issues so far.

In reference to the update to the pyenvisalink package above, In my previous setup I was getting a lot of async io errors in my log along with the envisalink errors.

ufodone commented 2 years ago

That's interesting to hear about the asyncio errors. From the logs I have seen, it would appear that the envisaging component is being told that a connection to the EVL is closed but that's not actually the case. As a result, it keeps getting updates from the existing connection but also goes into a loop trying to reconnect - which will not work because the EVL only will only allow a single connection at a time.

I figured it was a timing/race condition issue but I've been able to reproduce it or find any bug in the code as of yet which is why I thought it could be helpful to have a full log from the start to see what path it is that is triggering the apparent disconnect.

It's certainly possible that it's an issue with the underlying asyncio library but I'd love to rule out any bug in pyenvisalink.

Can you paste those asyncio errors you were seeing?

audymatic commented 2 years ago

Attached is a log from startup. The asyncio error is happening a little different from before. Before is seemed to be in the log in random places. Now it is directly following an arm command. It's different for Arm Away vs Arm Home

Arm Stay (One instance after sending the alarm code)

2022-04-18 16:07:23 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:07:23 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:07:23 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:07:23 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:07:23 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,3$'
2022-04-18 16:07:23 WARNING (MainThread) [asyncio] socket.send() raised exception.

Arm Away (One instance after sending each number of the code)

2022-04-18 16:10:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:10:04 WARNING (MainThread) [asyncio] socket.send() raised exception.
2022-04-18 16:10:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:10:04 WARNING (MainThread) [asyncio] socket.send() raised exception.
2022-04-18 16:10:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:10:04 WARNING (MainThread) [asyncio] socket.send() raised exception.
2022-04-18 16:10:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:10:04 WARNING (MainThread) [asyncio] socket.send() raised exception.
2022-04-18 16:10:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,xx$'
2022-04-18 16:10:04 WARNING (MainThread) [asyncio] socket.send() raised exception.

HA Log Dump.odt

ufodone commented 2 years ago

@audymatic Thanks for the full log file. It was very useful! While I don't understand exactly what's going on with your system, I think I can see how the envisalink component is getting into this bad state and can probably get a fix together.

Based on the logs, if I had to guess, I'd say either your system is overloaded or there is another integration that is causing the system to lag.

There are a number of components that are taking a long time to start up. For example:

2022-04-18 13:55:50 INFO (MainThread) [homeassistant.setup] Setup of domain system_health took 12.7 seconds
2022-04-18 13:55:51 INFO (MainThread) [homeassistant.setup] Setup of domain media_source took 13.4 seconds
2022-04-18 13:55:51 INFO (MainThread) [homeassistant.setup] Setup of domain logbook took 13.3 seconds
2022-04-18 13:55:51 INFO (MainThread) [homeassistant.setup] Setup of domain tag took 13.9 seconds
2022-04-18 13:55:51 INFO (MainThread) [homeassistant.setup] Setup of domain energy took 0.0 seconds
2022-04-18 13:55:51 INFO (MainThread) [homeassistant.setup] Setup of domain ffmpeg took 13.5 seconds

I suspect that the components listed above aren't the root cause but are instead victims of whatever is slowing the system down.

Googling around a bit also indicated to be that those asyncio errors could also be caused by system lag (something preventing the event loop from running). It is odd that they only show up when you arm the alarm though. But I can't see why Arm Away and Arm Stay would be different as it uses the same code to run both commands.

audymatic commented 2 years ago

@ufodone You may have been correct about the system being overloaded. I've since moved everything over to my new machine (Lenovo M93P i5 8gb, Proxmox 7, HA VM) and it all seems to be working fine now. I may have been asking too much of my little Raspberry Pi 3. I'll update if it falls apart again. Thanks for all the help.

ufodone commented 2 years ago

Thanks for the update and glad to hear it's working for you now.

An overloaded system might could cause intermittent problems but shouldn't cause the reconnect loop. That should be recoverable so I'd say there's still a bug. I suspect it's been there for a very long time but because it requires very specific timing to manifest, it's probably gone unnoticed.

Although I still can't reproduce it, I'll still have a go at getting a fix submitted.

TheFuzz4 commented 2 years ago

@ufodone just a heads up I sold the house that had the DSC in it so I cannot provide anymore insight into this from my end for the moment. My new house has a very old alarm system in it that I intend to replace with a DSC but its low on the priority list at the moment with other house projects taking priority.

ufodone commented 2 years ago

I have a proposed fix: https://github.com/Cinntax/pyenvisalink/pull/26

If anyone is still blocked by this issue and is available to try out the fix, please let me know.

crackers8199 commented 2 years ago

I have a proposed fix: Cinntax/pyenvisalink#26

If anyone is still blocked by this issue and is available to try out the fix, please let me know.

i just pulled your branch down and plugged it into my HA install to see if it helps. i'm out of ideas (haven't chimed in much on this thread, but i've been fighting with the envisalink for months now). it's frustrating because until late last year, it worked perfectly for literally YEARS...but in the months since, it has barely worked.

edit: forgot to mention, i'm currently on HA 2022.4.5.

envisalink: Firmware Version: 01.12.191

ufodone commented 2 years ago

@crackers8199 Let me know if the change helps your situation. If not, I'd be happy to try and help if you can send me debug logs, etc.

crackers8199 commented 2 years ago

@crackers8199 Let me know if the change helps your situation. If not, I'd be happy to try and help if you can send me debug logs, etc.

@ufodone at the risk of jinxing it, i haven't had a single disconnect since dropping your change into HA. not one. been rock solid for almost exactly four straight days.

ufodone commented 2 years ago

That's great to hear! If you have pyenvisalink debug logging on (or can turn it on), have a look for a entry that says:

Reconnect already scheduled.

If you see that then it means my fix is at play so it could be positive news.

crackers8199 commented 2 years ago

@ufodone tell me how to turn it on and I'm happy to do so and watch the logs...

ufodone commented 2 years ago

You can add something like this to your configuration.yaml:

 default: info
 logs:
   home assistant.components.envisalink: debug
   pyenvisalink: debug

Just be aware that with this logging on, your EVL password and alarm code may be logged so be careful if you post any snippets here.

crackers8199 commented 2 years ago

i don't see that line anywhere in the logs, not yet anyway. still haven't had any drops, though... (knock on wood)

with how bad it had gotten over the past few weeks/months, i definitely wouldn't have gone the past 5+ days without a disconnect like i have over the past week.

ufodone commented 2 years ago

I wouldn't typically expect that log line to show up more than once after a restart.

Have you done any Home Assistant restarts during the time that things have been working for you? Because the bug requires very specific timing, it's possible that sometimes when you startup HA, it will work fine. But if the bug does trigger then the envisalink integration will get into a bad state and things will likely not work until HA is restarted. SO if you haven't already, you could try a few restarts to ensure the issue does not reappear.

crackers8199 commented 2 years ago

I wouldn't typically expect that log line to show up more than once after a restart.

Have you done any Home Assistant restarts during the time that things have been working for you? Because the bug requires very specific timing, it's possible that sometimes when you startup HA, it will work fine. But if the bug does trigger then the envisalink integration will get into a bad state and things will likely not work until HA is restarted. SO if you haven't already, you could try a few restarts to ensure the issue does not reappear.

i've tried a few restarts the past few days, still haven't been able to break it but also still haven't gotten into the reconnect loop. at this point i'm not sure if your fix has done anything or if it's just something else that's in a version of pyenvisalink that's newer than what came with HA (not sure how that would happen), but all i can say for certain is that until i dropped your fix in it was constantly broken and since i put your fix in place it has been flawless (knock on wood, of course).

one thing i did notice on the restart i just did, was this line in the log (which previously would have indicated that it was going to bomb out at some point):

2022-05-24 15:48:21 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...

after that though, it just reconnected and seems to have gone on its merry way for now...

ufodone commented 2 years ago

You do have debug log on right? That log line I mentioned should only show up as a debug log.

That log entry you did see about the server closing the connection could be indicative of the issue happening.

I don't think there's anything else in that version of pyenvisalink that isn't already in the version used by HA. Reverting back to the official version and seeing if the probably comes back would be a good test - but I can certainly understand if you're reluctant to mess with something that's working now.

crackers8199 commented 2 years ago

yep, debug is on.

next time i do an update (probably this weekend) i'll go back to the official and see if the problem returns. i have my HA install in a vm on my proxmox server, so i can easily just do a snapshot before changing anything to easily get myself back to a working install if i need to go back.

crackers8199 commented 2 years ago

@ufodone I haven't gotten a chance to update yet, but knock on wood I'm gonna say whatever you did fixed my issue. I haven't had a single error message or reconnect issue in the logs since I last restarted my HA install, which was on may 24 (a little over a week ago). prior to this, it was breaking almost every day and would almost never work...

abarbaccia commented 2 years ago

I believe I am having the same issue. Any idea on when the new pyenvisalink will be pulled into HA?

ufodone commented 2 years ago

The latest pyenvisalink is already in HA (it went into 2022.7.1).

Can you provide more specific details of the issue you are seeing?

crackers8199 commented 2 years ago

@ufodone does that mean when i update past 2022.7.1 i can just go with the default and not have to have this custom version of pyenvisalink with your changes dropped in? i'm still on 6.7

abarbaccia commented 2 years ago

The system stopped responding to arm commands. It reflects proper status and state. Started happening a few months ago but haven’t traced back to specific version.

Nothing showing in my HA logs, but maybe I need to turn on more verbose.

I am on 2022.8 fyi

ufodone commented 2 years ago

@crackers8199 Yes, 2022.7.1 has the changes you have in the custom version.

@abarbaccia Could you turn on pyenvisalink debug logging and attach a log file from a clean startup of HA until the issue happens? There are details on how to do that earlier in the thread (May 21st).

abarbaccia commented 2 years ago

@ufodone thanks for helping here. Pasting the logs below. I pushed the armed button a few times during this period but cant seem the decipher it in the logs.

https://paste-bin.xyz/76603

ufodone commented 2 years ago

@abarbaccia It looks like the link you provided for the logs expired before I had a change to grab it. Could you post it again?

Damien2s commented 1 year ago

Like you I had this "ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting..." issue for several months. it was coming and going and for few weeks it's been completely off... For info my config worked for years without issues before that... Here is how I got it fixed:

  1. I upgraded the firmware to 01.04.176 (I had the 100) - You need to log in your Eyezon account for that
  2. I turned on the Syslog Client as per below (this option comes with firmware 108 or later):
    • Server IP Address = my home Assist server address
    • Facility = 16
  3. Save and reboot Envisalink
  4. Reboot Home Assistant

Since this change it has been working well. Actually it may be more responsive. Hope it works out for you too.

PS just in case my timeout is set to 15 in the configuration.yaml

ufodone commented 1 year ago

That's interesting to read about syslog. I know the EVL has a firewall of sorts and I've had cases where it becomes unresponsive for periods of time and I've often wondered whether something was triggering the firewall to block traffic for a period of time. I wonder if enabling syslog to your HA host is possibly preventing the firewall from block traffic to that host (because it has explicitly been declared as "good" due to the fact that it is the syslog target)?

abarbaccia commented 1 year ago

Sorry, coming back to this now.

I called the arm home command with debug on. Below is the logs from EVL:

2022-10-17 21:11:54.753 DEBUG (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones 2022-10-17 21:11:54.754 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.238 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script 2022-10-17 21:11:56.238 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service 2022-10-17 21:11:56.239 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,1$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,9$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,2$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,1$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,3$' 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.024 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.024 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:57.026 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.354 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.354 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:57.356 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:57.356 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

Any ideas? I dont see it throwing any errors, or noisy traffing on the line that may be interefering with the transmission…. Open to ideas

Tagging @ufodone in case you have any insight here> Big thanks in advance.

abarbaccia commented 1 year ago

Sorry, coming back to this now.

I called the arm home command with debug on. Below is the logs from EVL:

2022-10-17 21:11:54.753 DEBUG (MainThread) [homeassistant.components.envisalink] Envisalink sent a zone update event. Updating zones 2022-10-17 21:11:54.754 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.238 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script 2022-10-17 21:11:56.238 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service 2022-10-17 21:11:56.239 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,1$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,9$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,2$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,1$' 2022-10-17 21:11:56.240 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'^03,1,3$' 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.243 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.244 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.364 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:56.694 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:56.695 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.024 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.024 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:57.025 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:57.026 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.354 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ---------------------------------------- 2022-10-17 21:11:57.354 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < ^03,00$ 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Data received:^03,00$ 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Code:^03 Data:00 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response for code: ^03 with data: 00 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.honeywell_client] Envisalink response: Command Accepted 2022-10-17 21:11:57.355 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response 2022-10-17 21:11:57.356 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client. 2022-10-17 21:11:57.356 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

Any ideas? I dont see it throwing any errors, or noisy traffing on the line that may be interefering with the transmission…. Open to ideas

Tagging @ufodone in case you have any insight here> Big thanks in advance.

Disregard this please. I figured out my error. The alarm panel lost its config, and didnt have the EVL setup as a keypad. Hence it was ignoring commands sent with the EVL address. A quick run through the panel settings and all resolved (6+ months of debugging internet traffic…….)

issue-triage-workflows[bot] commented 1 year ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.