search

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.06k stars 29.73k forks source link

Envisalink Integration doesn't working only intermittently #66627

Closed ChirpyTurnip closed 2 years ago

ChirpyTurnip commented 2 years ago

The problem

Hi,

My Envisalink integration is unreliable - most of the time when I tell the system to arm or disarm it sits there and does NOTHING. I have used the alarm keypad more times than the HA app in the couple of months....which is ofcourse what I didn't want to be doing! It goes through periods of working (zones update, arm/disarm works) and then goes through periods where it pretty much does want to play at all.

In the log I see a lot of these messages:

2022-02-16 16:03:04 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure. 2022-02-16 16:04:22 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Received invalid message. Skipping.

I have an Envisalink EVL4 running the latest firmware (0.1.04.182). The Envisalink board is patched into the same switch as the HASSOS instance, and both are on the same logical LAN and in the same IP address space.

It just doesn't want to work reliably....

What version of Home Assistant Core has the issue?

2022.2.6

What was the last working version of Home Assistant Core?

2021.11

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 diagnostics for Envisalink (that I can see)

Example YAML snippet

host: 192.168.1.15
  panel_type: DSC
  user_name: !secret envisalink_user
  password: !secret envisalink_password
  code: !secret envisalink_code
  port: 4025
  evl_version: 4
  keepalive_interval: 60
  zonedump_interval: 30
  timeout: 10
  panic_type: Police
  zones:
    01:
      name: "Home_Alarm_Laundry"
      type: "motion"
    02:
      name: "Home_Alarm_Study"
      type: "motion"
    03:
      name: "Home_Alarm_Hallway"
      type: "motion"
    04:
      name: "Home_Alarm_Dining"
      type: "motion"
    05:
      name: "Home_Alarm_Lounge"
      type: "motion"
    06:
      name: "Home_Alarm_Garage"
      type: "motion"
    07:
      name: "Home_Alarm_Smoke_Downstairs"
      type: "fire"
    08:
      name: "Home_Alarm_Smoke_Upstairs"
      type: "fire"
  partitions:
    1:
      name: "Home Alarm"

Anything in the logs that might be useful for us?

Lots of these (roughly one set every ten minutes I think):

2022-02-16 16:03:04 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-16 16:04:22 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Received invalid message. Skipping.

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

envisalink documentation envisalink source (message by IssueLinks)

probot-home-assistant[bot] commented 2 years ago

Hey there @ufodone, mind taking a look at this issue as it has been labeled with an integration (envisalink) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

ufodone commented 2 years ago

Was this working for you reliably when you were on 2021.11? There was an issue introduced between then and 2022.2.6 which caused serious issues with the integration for users whose systems are setup to require a code to bypass zones. Although I haven't heard of this case, it might be possible it got your EVL into a bad state. That checksum error is odd. Have you tried rebooting the EVL4?

If an EVL reboot doesn't help, would it be possible for you to enable debug logging for the pyenvisalink component? That might give better insight into what's going on. Be aware though that that level of debugging might include your alarm system's code so please be careful about posting anything without first checking for the code in the logs

ChirpyTurnip commented 2 years ago

It was 99% reliable last year after it was first set up.... or perhaps more accurately I didn't have enough issues to remember having issues. :-)

Now I can tap the arm (or disarm) button again and again and nothing happens. It's like I have a completely flakey connection that just keeps dropping out...

There's no zone bypass required on my alarm, it's just on/off.... nice and simple.

I can reboot the envisalink, and I can enable debug logging for the integration.... however for that you'll need to provide some instructions as I've never had to do that before. I presume it's just a matter of adding a line or two to the yaml....

Can you point me in the right direction?

:-)

CP.

On Wed, 16 Feb 2022, 18:37 ufodone, @.***> wrote:

Was this working for you reliably when you were on 2021.11? There was an issue introduced between then and 2022.2.6 which caused serious issues with the integration for users whose systems are setup to require a code to bypass zones. Although I haven't heard of this case, it might be possible it got your EVL into a bad state. That checksum error is odd. Have you tried rebooting the EVL4?

If an EVL reboot doesn't help, would it be possible for you to enable debug logging for the pyenvisalink component? That might give better insight into what's going on. Be aware though that that level of debugging might include your alarm system's code so please be careful about posting anything without first checking for the code in the logs

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/66627#issuecomment-1041127610, or unsubscribe https://github.com/notifications/unsubscribe-auth/AUIP7ZULCB3MXS27VBVOZTDU3MZZFANCNFSM5OQNB2PA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>

ufodone commented 2 years ago

To reboot the EVL, you can connect to it with your browser. In your case, http://192.168.1.15 From there it should prompt you for username/password. Once logged in, click the "Network" link at the top right of the page and on the Network page there is a "Reboot envisalink" link at the bottom left of the page.

For the HA logging, you can add something like the following to your configuration.yaml:

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

You likely already have a logger section so it's likely you'll just need to add the two envisalink lines.

ChirpyTurnip commented 2 years ago

Done. Running debug now and will leave it on for a while (I have lots of disk space) until I test some arm/disarm actions (will be in a couple of hours) but that will give us a baseline.

After the reboot however I straight away got an odd message containing a NUL....so that might be our first clue.

2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 841 with data: 6
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 6) state has updated: {"trouble": false, "ac_present": true}
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 841 with data: 7
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 7) state has updated: {"trouble": false, "ac_present": true}
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 841 with data: 8
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 8) state has updated: {"trouble": false, "ac_present": true}
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 07:18:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:51 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D

I'll update later when I have more logs to post.

CP.

ChirpyTurnip commented 2 years ago

It seems log didn't copy and paste as expected......will update later....gotta run

ChirpyTurnip commented 2 years ago

OK.....I have figured out why I can't copy the logs.....every so often I get this:

2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**269635f5761796e65000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000EA
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**26, skipping...
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 07:18:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:19:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response

The NUL bits in the log above show a small red icon that just says 'NUL' - anytime I try to copy and paste the log data it always cuts off at the NUL icon and it cannot copy (or paste) past that point....so I have to manually copy either side of it....so that's weird.

It also shows up elsewhere (here I think we can ignore the Sonos part that was in the log as well):

2022-02-17 08:13:47 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 08:13:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 08:13:51 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 08:14:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 08:14:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 08:14:51 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**: 239.255.255.250:1900
CACHE-CONTROL: max-age = 1800
LOCATION: http://192.168.1.111:1400/xml/device_description.xml
NT: urn:schemas-upnp-org:device:ZonePlayer:1
NTS: ssdp:alive
SERVER: Linux UPnP/1.0 Sonos/67.1-25031 (ZPS12)
USN: uuid:RINCON_949F
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**: , skipping...
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for CAC, skipping...
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

Then, periodically I get the checksum errors:

2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-17 07:45:37 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response_error
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61550FF49FFEBFE04FE04FE17FF0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000EA
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: 50FF49FFEBFE04FE04FE17FF0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 07:45:37 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed

Sometimes there is a preceding NUL before the checksum error but that seems to be coincidental as there is no clear pattern.

Will keep an eye on it for now, then play with ARM/DISARM when I get a chance.

CP.

ufodone commented 2 years ago

Those logs are very bizarre. It looks like the Sonos info is actually part of the response data that HA is getting from the EVL and it is trying to process each line as a command from the EVL. But it is a mix of what looks like legitimate data from the EVL and whatever is generating that Sonos data.

It maybe looks like a UPnP response from some device on your network. Do you have the UPnP integration enabled?

Is there anything else you might have enabled/added around the time when the envisalink become unstable?

ChirpyTurnip commented 2 years ago

I don't have the uPNP integration and nothing (should) be using uPNP here as it is really insecure....

The Sonos data appears in there, but this copied from the for the log and there is a lot of other stuff in there....so it could be coincidental...or maybe not. Either way it's good that this isn't an obvious problem I should have seen myself. The curly ones are always the interesting ones!;-)

Here is my diagnostic data in case it helps:

System Health

version: core-2022.2.7
installation_type: Home Assistant OS
dev: false
hassio: true
docker: true
user: root
virtualenv: false
python_version: 3.9.7
os_name: Linux
os_version: 5.10.98
arch: x86_64
timezone: Pacific/Auckland

GitHub API: ok
Github API Calls Remaining: 5000
Installed Version: 1.22.0
Stage: running
Available Repositories: 1044
Downloaded Repositories: 24

logged_in: true
subscription_expiration: March 10, 2022, 13:00
relayer_connected: true
remote_enabled: true
remote_connected: true
alexa_enabled: false
google_enabled: true
remote_server: ap-southeast-1-0.ui.nabu.casa
can_reach_cert_server: ok
can_reach_cloud_auth: ok
can_reach_cloud: ok

host_os: Home Assistant OS 7.4
update_channel: stable
supervisor_version: supervisor-2022.01.1
docker_version: 20.10.9
disk_total: 457.7 GB
disk_used: 18.3 GB
healthy: true
supported: true
board: generic-x86-64
supervisor_api: ok
version_api: ok
installed_addons: MariaDB (2.4.0), Studio Code Server (4.1.0), Mosquitto broker (6.0.1), Samba share (9.5.1), Log Viewer (0.12.2), InfluxDB (4.3.0), Grafana (7.4.1), Node-RED (11.0.2), Home Assistant Google Drive Backup (0.105.2), SSH & Web Terminal (10.0.2), Check Home Assistant configuration (3.10.0), Network UPS Tools (0.9.1), ESPHome (2022.2.1)

dashboards: 2
resources: 11
views: 15
mode: storage

And my list of integrations:

Alarm control panel
Analytics
Home Assistant API
Auth
Automation
Binary sensor
Blueprint
Sony Bravia TV
Button
Camera
Google Cast
Climate
Home Assistant Cloud
CO2 Signal
Command Line
Configuration
Counter
Cover
Default Config
Device Automation
Device tracker
DHCP Discovery
Diagnostics
DLNA Digital Media Renderer
ECHONETLite
Energy
Envisalink
ESPHome
Fan
Flick Electric
Home Assistant Frontend
Garbage Collection
Google Assistant
Google Maps
Google Translate Text-to-Speech
Group
HACS
Home Assistant Supervisor
History
Home Assistant Core Integration
HTTP
Image
InfluxDB
Input boolean
Input Button
Input datetime
Input number
Input select
Input text
Light
Local IP Address
LocalTuya
Logbook
Logger
Lovelace
Map
Media player
Media Source
Meteorologisk institutt (Met.no)
Mobile App
MQTT
MQTT Room Presence
My Home Assistant
Network Configuration
Nmap Tracker
Notifications
Number
Network UPS Tools (NUT)
Home Assistant Onboarding
Persistent Notification
Person
pfSense
Pi-hole
Ping (ICMP)
Plex Media Server
Profiler
Pushover
Recorder
Remote
SamsungTV Smart
Scene
Scheduler integration
Script
Search
Select
Sensor
Shell Command
Shelly
Sonos
SQL
Simple Service Discovery Protocol (SSDP)
Stream
Speech-to-Text (STT)
Sun
Switch
System Health
System Log
System Monitor
Tag
Template
Time & Date
Timer
Trace
Text-to-Speech (TTS)
UniFi Network
UniFi Protect
Updater
Uptime
USB Discovery
Wake on LAN
Weather
WeatherFlow Weather
Webhook
Home Assistant WebSocket API
Zero-configuration networking (zeroconf)
Zone

Still no arm/disarm data sorry. Still working.....being a wage slave and all. :-)

CP.

ufodone commented 2 years ago

It doesn't look to me like the Sonos stuff is coincidental. The interesting bit from one of those log snippets you posted, this line:

2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**: 239.255.255.250:1900
CACHE-CONTROL: max-age = 1800
LOCATION: http://192.168.1.111:1400/xml/device_description.xml
NT: urn:schemas-upnp-org:device:ZonePlayer:1
NTS: ssdp:alive
SERVER: Linux UPnP/1.0 Sonos/67.1-25031 (ZPS12)
USN: uuid:RINCON_949F

is showing what the pyenvisalink had read off the network. The first part (5000082D) looks like a valid EVL response packet. The rest looks like it's coming from somewhere else. I don't think it is coincidental because of the log lines a little further along:

2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**: , skipping...
.
.
2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for CAC, skipping...

Notice that the two commands is doesn't have handlers for are **NUL** and CAC which are the first three characters of the two lines following the 500 response. The pyenvisalink package received the data and processes each line as a command. So this looks like the library is actually processing that data from the log file. I suspect if you look a little further past that log snippet you'll find similar log entries referring to having no handlers for LOC, NT:, NTS, etc. as it works its way through each line.

I suspect the checksum errors are a similar situation but in the opposite direction (e.g. "extra" data is being sent to the EVL somehow that isn't properly formatted and it's failing the basic packet validation).

Looking at that "extra" data a bit more and your list of integrations, my guess would be that it's data from SSDP. How it's ending up on your EVL connection though is a mystery to me.

You could try temporarily disabling SSDP and see if that makes any difference. Alternately, if you have an easy-ish way to stand up a temporary HA instance that only has the envisalink integration running that could help determine if there is something funny going on with your network or if the issue is somehow related to the HA software.

Sorry I don't have any better suggestions at the moment...

ChirpyTurnip commented 2 years ago

Well that is bizarre.....why would that data be mashed in with the EVL process?

I can't stand up another instance of HA so that's off the table for now...a complete rebuild would be the only way and that would take days.... I can disable the SSDP (not adding anything anyway) - is there an easy way to do this or will I have to replace the default_config: with a user define list of everything? I'm hoping there's a stop button somewhere I can push or a couple of lines in the yaml to exclude it....

I can also (separately or together) disable the Sonos integration to see if that makes a difference....

Thoughts?

ufodone commented 2 years ago

I definitely wouldn't recommend a complete rebuild at this point as you may very well end up with the same problem.

As for disabling SSDP, I'm not sure what the best way to approach that would be. To be honest, my knowledge of it is limited to what I googled on it specific to this issue. :)

I suspect that Sonos stuff in the log file is just your Sonos devices responding to the SSDP discovery requests so I don't think disabling the Sonos integration would change anything since the discovery would still be happening. You'd have to take your Sonos devices off the network temporarily to stop that traffic. But even if that fixed it, it probably wouldn't get to whatever the root cause is.

This is probably a stretch but is there any chance you have the ability to get a network capture of the traffic to/from the EVL? That could help at least determine if it's an issue on the network or in HA.

We might be able to get a bit more info from the logs though. Similar to the "RX" entries there are "TX" entries which log what is being sent to the EVL. Could you have a look for those entries - especially where they precede the checksum errors? I'm curious to know if there's the "extra" info there similar to the RX logs. But please have a careful look at those logs before you post them as they could contain your alarm code.

ChirpyTurnip commented 2 years ago

OK.....a bit of Googling later and....

To turn off a default integration you need to replace the default_config: in the configuration.yaml with your own list of services (which you can cobble together from the listed services provided on the referring page: https://www.home-assistant.io/integrations/default_config/.

A bit of hacking to comment out the default config and list all the services that should be started. Then comment out the ones I want to disable (like SSDP), and also comment out the ones defined already elsewhere. That leaves me with this:

# Configure a default setup of Home Assistant (frontend, api, etc)
#default_config:

#Default_Config Override
#See https://www.home-assistant.io/integrations/default_config/ for the full list of current options

#automation: [See below]
cloud:
config:
counter:
dhcp:
energy:
#history: [See below]
image:
input_boolean: 
input_button:
input_datetime:
input_number: 
input_select:
input_text:
logbook:
map:
media_source:
mobile_app:
my:
person:
#scene: [See below]
#script: [See below]
#ssdp:
#stream: [See below]
sun:
system_health:
tag:
#timer: [See below]
updater:
usb:
webhook:
zeroconf:
zone:

A quick restart and we're away....now I had to iterate a few times as the post is borrowed from was about a year old so things like the energy dashboard failed to show up until I added energy: to the config. On the plus side that did show that this was one way of stopping services.

BUT

In the logs I still saw this:

2022-02-17 19:16:05 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'dhcp', 'flick_electric', 'dlna_dmr', 'plex', 'hacs', 'blueprint', 'input_datetime', 'stream', 'input_boolean', 'input_select', 'updater', 'scheduler', 'unifi', 'input_text', 'weatherflow', 'co2signal', 'tag', 'system_health', 'localtuya', 'energy', 'samsungtv_smart', 'met', 'wake_on_lan', 'media_source', 'zeroconf', 'pfsense', 'esphome', 'counter', 'nut', 'zone', 'envisalink', 'local_ip', 'template', 'device_tracker', 'shelly', 'tts', 'nmap_tracker', 'garbage_collection', 'binary_sensor', 'timer', 'history', 'sun', 'network', 'trace', 'sensor', 'cover', 'mqtt', 'usb', 'map', 'profiler', 'mobile_app', 'pi_hole', 'input_number', 'influxdb', 'switch', 'scene', 'logbook', 'cast', 'echonetlite', 'persistent_notification', 'sonos', 'braviatv', 'notify', 'group', 'automation', 'input_button', 'ssdp', 'unifiprotect', 'shell_command', 'script', 'my'}
2022-02-17 19:16:06 INFO (MainThread) [homeassistant.setup] Setting up ssdp
2022-02-17 19:16:06 INFO (MainThread) [homeassistant.setup] Setup of domain ssdp took 0.0 seconds

So it seems that maybe SSDP is still running....not cool.

I also saw these errors again:

2022-02-17 08:15:15 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**: 239.255.255.250:1900
CACHE-CONTROL: max-age = 1800
LOCATION: http://192.168.1.111:1400/xml/device_description.xml
NT: urn:schemas-upnp-org:device:ZonePlayer:1
NTS: ssdp:alive
SERVER: Linux UPnP/1.0 Sonos/67.1-25031 (ZPS12)
USN: uuid:RINCON_949F

So side trip to integrations, click Sonos integration menu, hit disable, and another HA restart....check that all the Sonos stuff is really dead.....and then we wait.

Everything comes up OK....but one thing I keep seeing a lot is this:

2022-02-17 19:17:17 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:17:17 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:17:17 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:17:17 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:17:17 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.

I googled that too and it seems to be redundant messages relating the control panel LED status (e.g. the 'Ready' or 'Zone' light is on/off....can you confirm we can ignore?

Anyway, while writing up the above I capture 1000 lines of normal looking logs until the NUL made a return:

2022-02-17 19:19:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:19:16 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:16 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 51080FE
6511CD
6100052C
51081FF
6501CC
50000025
5000082D
60900534
51080FE
6511CD
6100052C
51081FF
6501CC
5000082D
50000025
5000082D
**NUL**000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004A
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 005
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 5) state has updated: {"open": false}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 005
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 5) state has updated: {"open": true}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 005
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 5) state has updated: {"open": false}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**00, skipping...
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:19:18 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:36 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:19:39 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:19:40 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Received invalid message. Skipping.
2022-02-17 19:20:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 19:20:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 615C7FFC7FFCAFFD9FFEAFF7DFD000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000058
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: C7FFC7FFCAFFD9FFEAFF7DFD0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 10) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 11) closed
2022-02-17 19:20:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 12) closed

Then a while later:

2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 51080FE
6511CD
61000229
51081FF
6501CC
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:49:38 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:49:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**29FF27FF27FF1DFC000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000012
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**29, skipping...
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 615CCFFF1FF28FF26FF26FF1CFC00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000C
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: CCFFF1FF28FF26FF26FF1CFC0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed
2022-02-17 19:49:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 10) closed

And again:

2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:59:32 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**B5FEB3FEB3FEA9FB000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000030
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**B5, skipping...
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:59:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:36 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 60900231
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 002
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": true}
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 51080FE
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 6511CD
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:59:44 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61000229
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 51081FF
6501CC
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 19:59:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 20:00:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 20:00:36 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 60900231
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 002
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": true}
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 51080FE
6511CD
61000229
51081FF
6501CC
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:00:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61548FFF9FFA4FEA2FEA2FE98FB000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000014
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: 48FFF9FFA4FEA2FEA2FE98FB0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-17 20:00:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed

So it is safe to say the NUL problem persists with the Sonos and SDDP integrations disabled.

And the checksum error is there as well:

2022-02-17 20:46:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 20:46:55 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 20:47:05 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Received invalid message. Skipping.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
5000082D
5000082D
50000025
5000082D
5000082D
50000025
5000082D
5000082D
60900231
51080FE
6511CD
61000229
51081FF
6501CC
60900231
51080FE
6511CD
50202029
50196
61000229
51081FF
6501CC
50000025
5000082D
60900231
51080FE
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 002
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": true}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 002
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": true}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 651 with data: 1
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": false, "alpha": "Not Ready"}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 502, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-17 20:47:05 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response_error
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 609 with data: 002
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": true}
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 615BAFFFDFFBDFF3EFF3EFF6EF9000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000055
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: BAFFFDFFBDFF3EFF3EFF6EF90000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) open
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 10) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 11) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 12) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 13) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 14) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 15) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 16) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 17) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 18) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 19) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 20) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 21) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 22) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 23) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 24) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 25) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 26) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 27) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 28) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 29) closed
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 30) closed

A lot of logs sorry..... and we haven't even got to the good bit yet! In bot the NUL and checksum case it is the pyenvisalink.dsc_client that seems to have the problem....but you probably already know that.

Is this any help?

CP

ChirpyTurnip commented 2 years ago

And yes....I did manage to do a packet capture....waited until I'd captured this error:

2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61000128
51081FF
6501CC
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 001
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 1) state has updated: {"open": false}
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_partition_state_change for code: 650 with data: 1
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.dsc_client] (partition 1) state has updated: {"ready": true, "alpha": "Ready"}
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_partition_state_change
2022-02-17 22:11:16 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:20 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-17 22:11:20 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 22:11:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
**NUL**DBFF8CFF8DFF7AF5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000058
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for **NUL**DB, skipping...
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 22:11:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 615F6FFF6FFD6FF87FF88FF75F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: F6FFF6FFD6FF87FF88FF75F50000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-17 22:11:50 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed

The error can be found in the attached PCAP. I didn't stick around for the checksum error...past my bed time now....

EVL Capture - Packets.zip

ufodone commented 2 years ago

Two interesting things in that packet capture:

  1. The bad data that is causing the errors is present.
  2. There are a lot of retransmissions by the EVL when sending data to the HA host.

For the first item, I believe this eliminates the HA core software and envisalink integration as being the root cause.

For the second item, the packets from the EVL aren't being acknowledged by the network stack on your HASSOS host in a timely fashion. This could be due to a bad network cable or a variety of other reasons. It may or may not be related to the first item depending on what is causing the retransmissions.

Where did you take the network capture from? Was it from the HASSOS host itself or a point between such as the switch the two devices are attached to?

ChirpyTurnip commented 2 years ago

I have a managed switch so I used a port mirror to export all the data on the port to which the EVL is connected. The EVL is co-located with the switch so plugged in directly, the HA instance is also connected to the same switch but does so via a patch panel as it is at the opposite end of the house. On the plus side there will be no WiFi, routing, or other intermediary issues.

If we think it is a physical problem that would then narrow it down to the patch cable, switch, or something between the switch and HA. Or of course the EVL itself....

I'll swap out the patch cable as that's an easy one.....and then I'll compare the switch port stats to the packet capture to see if the switch detects any packet errors versus the traffic in the capture. TCP Retransmission messages can be spurious....but if it is really bad then the switch should start registering errors.....

ufodone commented 2 years ago

Okay, capturing via port mirroring helps narrow the problem down further. While a bad cable could cause the retransmissions, I don't think it couldn't cause the bad data from entering the stream as that would cause TCP checksums to fail. In frames where the bad state is sent, I see the HASSOS host ACK'ing the packet and it's also being delivered to HA which would not happen if the data was corrupted on the wire.

The only way bad data could be introduced would be either at the EVL itself or the HASSOS host. Since the network capture was done "in-between" that means to me that it is unfortunately your EVL that's actually sending bad data. It may also potentially be corrupting the inbound data in the case of the checksum errors you're seeing the HA logs.

I assume you previously tried to reboot the EVL? You might try power cycling it as well to see if that helps.

I'd definitely try swapping out the cables but I'm just not confident at this point that it would actually help the packet corruption.

ChirpyTurnip commented 2 years ago

I have swapped the cables, rebooted the EVL, and power cycled the whole alarm box, and the network switch (it had been up for 3 years, 6 months...not bad!).

Nothing seem to makes a difference....there are still a lot of packet-related errors but in the last three hours I've not seen any more NUL or Checksum errors....it could be have improved matter...or it could just be mocking us.

In the meantime I separately logged a ticket with eyez-on to see if they had any advice.... They came back quickly and there was a bit of back and forth but ultimately their response is:

_This is way beyond our level of technical support and we cannot support the TPI. The TPI's support is between Envisacor and Home Assistant.

Your module is functioning normally and I just ran the factory tests on it and it passed. All is good.

I would contact that manufacturer of your Home Assistant and have them take up the issue with their developer rep at Envisacor._

Which is some ways is good, having run a diagnostic they think that the module is operating correctly....leaving only the chance that the Ethernet module itself is faulty...and I'm not sure how I can isolate and test that separately. I assume that they didn't see any errant traffic from the module when they tested it...

I'll see what come sup in the logs in the next few hours.....

ufodone commented 2 years ago

What do you mean by "packet related errors"? Things like this:

2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 510, skipping...
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.

If so, that's totally normal. The EVL sends some updates that the pyenvisalink module just doesn't process and those logs just indicate that one of those was received. The NULs/other odd data in the RX lines or checksum errors are the things that are problematic.

ChirpyTurnip commented 2 years ago

Cool...that answer that....I was expecting them to be spurious.

But no, not what I was referring to....I'm talking the TCP Retransmission and RST/ACK messages in the WireShark packet capture - that is still very much happening.

In HA logs still plenty of this:

2022-02-18 15:42:53 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-18 15:42:56 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-18 15:42:56 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-18 15:42:56 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-18 15:43:26 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-18 15:43:29 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-18 15:43:29 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-18 15:43:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-18 15:43:59 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-18 15:44:02 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-18 15:44:02 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-18 15:44:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-18 15:44:04 WARNING (SyncWorker_11) [homeassistant.components.sonos] Failed to connect to discovered player '192.168.1.115': HTTPConnectionPool(host='192.168.1.115', port=1400): Max retries exceeded with url: /MediaRenderer/RenderingControl/Control (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fc9a14405b0>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
2022-02-18 15:44:07 WARNING (SyncWorker_0) [homeassistant.components.sonos] Failed to connect to discovered player '192.168.1.113': HTTPConnectionPool(host='192.168.1.113', port=1400): Max retries exceeded with url: /MediaRenderer/RenderingControl/Control (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fc9a3b9eee0>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
2022-02-18 15:44:32 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-18 15:44:35 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-18 15:44:35 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-18 15:44:35 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-18 15:44:45 INFO (MainThread) [hole] Response from *hole: 200
2022-02-18 15:44:48 WARNING (SyncWorker_10) [homeassistant.components.sonos] Failed to connect to discovered player '192.168.1.113': HTTPConnectionPool(host='192.168.1.113', port=1400): Max retries exceeded with url: /MediaRenderer/RenderingControl/Control (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fc9b3eb2e50>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
2022-02-18 15:45:05 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-18 15:45:06 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5053CD
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login for code: 505 with data: 3
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'005SQldezJ86A'
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-18 15:45:06 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

So the interfaces remains very slow and many sensor detections are not reported to the UI....it can sit on 'Detected' for 3-4 minutes before it goes back to clear, and then site like that for 3-4 minutes before it again registers motion. So none of the linked automation work reliably...and I expect neither will the arm/disarm function for the same reason....

But on the plus side still no sign of NUL or checksum errors.

ufodone commented 2 years ago

FYI that last log you posted includes a login command and contains your EVL password so you might want to change it now. :)

Have those initial connection errors always been happening or is that new? I assume the RSTs you are seeing are being issued by the EVL? The EVL only supports a single connection to port 4025 at a time and getting a RST back could indicate an existing connection. But the fact that it eventually connects would imply that if something else was connected to it that it wasn't staying connected.

Are the retransmissions you're still seeing being sent from the EVL or the HA host? In the capture you attached earlier they were all being sent by the EVL - which in itself is a bit odd since it would imply that the HA host isn't ACK'ing the packets quickly enough or they aren't getting to the host at all.

I had another look at the capture you sent and and noticed what maybe looks like a portscan of sorts originating from your HA host and hitting the EVL. It's later in the capture after the corrupted packets so it's probably unlikely to be related but thought I'd mention it in case it is unexpected on your end (maybe coming from nmap tracker?).

ChirpyTurnip commented 2 years ago

I know the password is there - it's a temporary one....there was a chance of it slipping through in the log posts (and definitely in the PCAP) so I swapped it out with a random one before starting.....

Those connection interrupts in the log have been there all along albeit it sporadically. It could be a connection attempt from nmap as that is running.....I've added the EVL IP to the exclusion list....and restarted HA. But from my reading (and recollection) it is the EVL that hangs up:

2022-02-18 17:30:14 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2022-02-18 17:30:14 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...

With me restarting HA repeatedly I don't currently have a long log to check as I didn't export the logs before restarting.

As for the retransmissions they are almost all coming from the EVL:

1   0.000000    192.168.1.15    192.168.1.10    TCP 64  4025 → 45982 [PSH, ACK] Seq=1 Ack=1 Win=1300 Len=10
135 4.509409    192.168.1.15    198.61.170.85   UDP 394 5257 → 4021 Len=352
234 10.000583   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=1 Ack=1 Win=1300 Len=10
946 22.502023   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=1 Ack=1 Win=1300 Len=10
947 22.502194   192.168.1.10    192.168.1.15    TCP 60  45982 → 4025 [ACK] Seq=8 Ack=11 Win=63784 Len=0
949 22.502979   192.168.1.15    192.168.1.10    TCP 98  4025 → 45982 [PSH, ACK] Seq=11 Ack=1 Win=1300 Len=44
950 22.503120   192.168.1.10    192.168.1.15    TCP 60  45982 → 4025 [ACK] Seq=8 Ack=55 Win=63784 Len=0
978 22.571927   192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 45982 → 4025 [PSH, ACK] Seq=1 Ack=55 Win=63784 Len=7
979 22.572278   192.168.1.15    192.168.1.10    TCP 60  4025 → 45982 [ACK] Seq=55 Ack=8 Win=1300 Len=0
980 22.573365   192.168.1.15    192.168.1.10    TCP 64  4025 → 45982 [PSH, ACK] Seq=55 Ack=8 Win=1300 Len=10
981 22.573827   192.168.1.10    192.168.1.15    TCP 60  45982 → 4025 [ACK] Seq=8 Ack=65 Win=63784 Len=0
982 22.575160   192.168.1.15    192.168.1.10    TCP 317 4025 → 45982 [PSH, ACK] Seq=65 Ack=8 Win=1300 Len=263
983 22.575189   192.168.1.10    192.168.1.15    TCP 60  45982 → 4025 [ACK] Seq=8 Ack=328 Win=63784 Len=0
1821    26.614277   192.168.1.15    192.168.1.10    TCP 64  4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
1823    28.502609   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
1825    30.502734   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
1889    33.012036   192.168.1.15    198.61.170.85   UDP 394 5258 → 4021 Len=352
1891    34.002991   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
2050    40.503611   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
2252    53.005347   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
4090    77.508157   192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
5586    102.011709  192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
6011    121.523341  192.168.1.15    198.61.170.85   UDP 394 5260 → 4021 Len=352
6154    126.514641  192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 45982 [PSH, ACK] Seq=328 Ack=8 Win=1300 Len=10
6156    127.014758  192.168.1.15    8.8.8.8 DNS 81  Standard query 0xf7e9 A alerts0.envisacor.com
7654    137.516968  192.168.1.15    8.8.8.8 DNS 81  Standard query 0xfcee A alerts0.envisacor.com
7952    148.018604  192.168.1.15    8.8.8.8 DNS 81  Standard query 0x0cf0 A alerts0.envisacor.com
7955    151.019106  192.168.1.15    192.168.1.10    TCP 60  4025 → 45982 [RST, ACK] Seq=328 Ack=8 Win=1300 Len=0
8099    157.028992  192.168.1.15    198.61.170.85   UDP 394 5262 → 4021 Len=352
8150    162.529553  192.168.1.15    198.61.170.85   UDP 394 5262 → 4021 Len=352

I can packet capture until the cows come home now that I've patched into the switch....maybe I should have a crack and seeing what is happening on the HA port. That might be interesting too....

The HA instance is an Intel NUC and the only thing it is running is HA + addons, so it shouldn't be struggling to send out acknowledgements since it has little else to do....

ufodone commented 2 years ago

Yes, the "The server close the connection..." logs are very likely a direct response to the RSTs coming from the EVL.

A network capture from the NUC via tcpdump/wireshark on the host itself might be interesting. Capturing there vs switch mirroring will show what the OS network stack is actually seeing and you could compare it to a capture from the EVL to see if the retransmission behaviour and timing is the same.

The retransmissions are likely somehow linked to the main problem but the fact that the previous capture was showing bad data in the packets means to me the root cause still lies somehow with the EVL. From my limited experimentation with the TPI API, it did feel like the unit had pretty limited capability so I could imagine that maybe if there is too much traffic(?) to/from the EVL (related or unrelated to HA) that it could potentially cause issues. This is just pure speculation on my part though. Maybe if there was a way to further isolate the EVL from other traffic that could be something to try. I'm just not sure how you'd do that.

It will be interesting to see if the bad data (NULs/bad checksums) do show up again.

Sorry but I don't have any more ideas at the moment...

ChirpyTurnip commented 2 years ago

That's OK....just having someone to bounce ideas off is useful in and of itself....

So I have now got both the HA and EVL ports mirrored out to a single port and I'm sniffing there....the first incidental finding is that my Canon printer is a noisy beast....fully 40% of the captured packets (by count) is this:

2128    0.826177    192.168.1.20    224.0.0.251 MDNS    126 Standard query response 0x0000 A, cache flush 192.168.1.20 PTR, cache flush CANON-PIXMA.local
2131    0.828671    192.168.1.20    224.0.0.251 MDNS    447 Standard query response 0x0000 A, cache flush 192.168.1.20 PTR, cache flush CANON-PIXMA.local SRV, cache flush 0 0 8611 CANON-PIXMA.local TXT, cache flush PTR _canon-bjnp1._tcp.local PTR Canon MP990 series _5EE1996DE4F2._canon-bjnp1._tcp.local
2132    0.830734    192.168.1.20    224.0.0.251 MDNS    376 Standard query response 0x0000 A, cache flush 192.168.1.20 PTR, cache flush CANON-PIXMA.local SRV, cache flush 0 0 8612 CANON-PIXMA.local TXT, cache flush PTR _scanner._tcp.local PTR Canon MP990 series _5EE1996DE4F2._scanner._tcp.local
2134    0.833755    192.168.1.20    224.0.0.251 MDNS    261 Standard query response 0x0000 A, cache flush 192.168.1.20 PTR, cache flush CANON-PIXMA.local SRV, cache flush 0 0 80 CANON-PIXMA.local TXT, cache flush PTR _http._tcp.local PTR Canon MP990 series _5EE1996DE4F2._http._tcp.local

I'm surprised any one else can get a word in at all.....so that's been turned off.

Next thing was that the HA traffic was crap tons of SYN packets followed RST/ACK....spraying across pretty much the whole IP range....I'm taking that nmap tracker.....so I've turned that off too....and now the trace is a little less colorful and noisy. I'll leave it running for a bit and see if we catch anything. ;-)

ChirpyTurnip commented 2 years ago

Here is the pcap for both ends of the connection. The

ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...

cycle occurred at least four times and on some occasions it took multiple attempts to reestablish the connection. There were no checksum errors, no NUL errors either that I could see (because you cannot search for them).

Reconnections happened at these times:

First connection 18:11 Disconnect @ 18:21, Reconnect @ 18:23 on fourth attempt Disconnect @ 18:33, Reconnect @ 18:33 on first attempt Disconnect @ 18:39, Reconnect @ 18:39 on first attempt Disconnect @ 18:43, Reconnect @ 18:45 on third attempt Disconnect @ 18:55, Reconnect @ 18:58 on fifth attempt

So in round numbers every ten minutes.....I do get the idea that it tends to reset less if there activity on the zones...that is, once a connection is established it sustains the link better than if there are no reports to make....

Anyway, have a ponder if you can and tell me if you see anything odd (useful odd obviously). I can also do only HA, or only TX from the EVL and RX from the HA port.....but as for isolating it I'm with you....really hard.....so for now the port mirroring is going to be the best bet.....

EVL-HA Dual TX-RX Capture.zip

ufodone commented 2 years ago

I haven't had a chance to look at those capture yet but I was doing a bit of experimentation with my own EVL and was able to reproduce a similar non-responsive behaviour when making connections.

If try and connect to the EVL's admin page by putting http:// into a browser, it will try preemptively make some connections behind the scenes which appear to repond correctly but then will get stuck retransmitting SYN packets because the EVL becomes non-responsive. While it's in this state, I get the same non-responsive behaviour when I try to connect directly to the 4025 port.

So it seems that it's possible to make the EVL temporarily stop responding to network input when maybe a small burst of connection attempts or traffic comes into it.

When you've been going network captures, have you been capturing all the traffic in/out of the EVL or only between the EVL and your HA host? I wonder if there's something else that's periodically hitting the EVL and causing it to go non-responsive and triggering that disconnect/reconnect pattern?

ChirpyTurnip commented 2 years ago

The good news, no more nul errors overnight - so rebooting the EVL seems to have done the trick on that front (or the switch....though if the switch was having issues I think I'd have notice problems elsewhere). The bad news though, further checksum errors were detected...but on the plus side now that the log has run for longer (see attached) there is a clear pattern now - all of them seem to be referring to exactly the same preceding message:

2022-02-19 06:35:11 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50196
2022-02-19 06:35:11 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-19 06:35:11 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.

This is because in all eight cases we always see 'RX < 50196 ' before the checksum error....looking back at the logs I posted previously in most cases I didn't have the preceding data, but in at least one case this value was hidden in the middle of block of data:

2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
5000082D
5000082D
50000025
5000082D
5000082D
50000025
5000082D
5000082D
60900231
51080FE
6511CD
61000229
51081FF
6501CC
60900231
51080FE
6511CD
50202029
50196 <------- HERE
61000229
51081FF
6501CC
50000025
5000082D
60900231
51080FE
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
<snip>
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-17 20:47:05 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response_error
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-17 20:47:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
<snip>

And, better yet, searching through the old logs I have where there were no checksum errors the 50196 data string is also not found. So I think here at least we can be pretty certain that we have found the issue...even though the underlying cause remains unclear....and given that there is a consistent value every time that seems to make a network issue less likely as a cause.

But then thinking about it, the neither the checksum nor the NUL really seemed to have much impact....in the logs you can just see the system plowing on regardless....so perhaps we've been barking up the wrong tree altogether? The symptom is that I can't reliably arm/disarm and that connection seems really lagged.....I think maybe we should switch focus to the disconnection issue instead because that happened 23 times in about 12 hours - so every half hour on average....and in many cases it takes between 1 - 5 minutes to reconnect....which are some pretty big dead zones. Even with an average of 2.5 minutes that means I'm offline for 1 hour in that 12 hour log...or two hours per day - that's almost 10% of the time....

Here's a classic case:

2022-02-19 02:18:21 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2022-02-19 02:18:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:18:51 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:18:54 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:18:54 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:18:54 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:19:24 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:19:27 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:19:27 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:19:27 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:19:57 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:20:00 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:20:00 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:20:00 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:20:30 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:20:33 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:20:33 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:20:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:21:03 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:21:05 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2022-02-19 02:21:05 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2022-02-19 02:21:05 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:21:35 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:21:45 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:21:45 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:21:45 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:22:15 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:22:19 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:22:19 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:22:19 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:22:49 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:22:52 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 02:22:52 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 02:22:52 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 02:23:01 INFO (MainThread) [hole] Response from *hole: 200
2022-02-19 02:23:22 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 02:23:22 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5053CD
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login for code: 505 with data: 3
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'005SQldezJ86A'
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 02:23:22 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

So...question - why does the server hang up? Because it is ALWAYS the EVL pulling the pin on the connection....

Thanks for bearing with me.... :-)

home-assistant-log.zip

ChirpyTurnip commented 2 years ago

I haven't had a chance to look at those capture yet but I was doing a bit of experimentation with my own EVL and was able to reproduce a similar non-responsive behaviour when making connections.

If try and connect to the EVL's admin page by putting http:// into a browser, it will try preemptively make some connections behind the scenes which appear to repond correctly but then will get stuck retransmitting SYN packets because the EVL becomes non-responsive. While it's in this state, I get the same non-responsive behaviour when I try to connect directly to the 4025 port.

So it seems that it's possible to make the EVL temporarily stop responding to network input when maybe a small burst of connection attempts or traffic comes into it.

When you've been going network captures, have you been capturing all the traffic in/out of the EVL or only between the EVL and your HA host? I wonder if there's something else that's periodically hitting the EVL and causing it to go non-responsive and triggering that disconnect/reconnect pattern?

For the PCAP I grabbed everything, but applied this filter ip.address == 192.168.1.15 - that simply filters out the noise but should retain every packet coming or going to the EVL (since that is its IP address).

Something might be hitting it, but I wouldn't know what as it isn't on a regular cycle (e.g. nmap every x minutes). There's certainly no mobile app or other device talking to the EVL....only the eyez-on service but that shouldn't have any effect from what I understand. And, remember, nmap now specifically excludes the the EVL address.

Elsewhere on on my network I run a pfSense firewall and Ubiquiti Cloud Key Gen 2 (Unifi video and Unifi Wifi) but I haven't got anything else that would want to snoop.....

ufodone commented 2 years ago

This is because in all eight cases we always see 'RX < 50196 ' before the checksum error

This is the response from the EVL indicating that there was a checksum error with the last command that was sent to it. So it is expected that this would always precede the checksum error since that's what's triggering it. The TX line that precedes the 501 is likely what would be triggering the checksum error. I quick look in the log file you attached and it seems to be the 008 command which tells the EVL to dump its zone timers. You could try and disable that by setting zonedump_interval to 0 in your config. I seem to recall that this might be okay for normal operation as it's a bit of a backup in case an explicit zone state change was somehow missed (but don't quote me on that).

That might help reduce the checksum errors but likely isn't a root cause. Do any of the network captures you provided contain a checksum error so I could inspect what was actually sent to the EVL?

So...question - why does the server hang up? Because it is ALWAYS the EVL pulling the pin on the connection....

Yes, that's the million dollar question. My guess is that something happens periodically that get the EVL into a temporary bad state which can cause it to become non-responsive and/or trigger disconnects.

ChirpyTurnip commented 2 years ago

I've got another PCAP running but no new checksum errors yet. I'll just let it run until I capture it, then I'll restart HA with the zonedump_interval set to 0.

Trawling through the captures we have I see the EVL is getting traffic from the follow locations:

192.168.1.10 --> HA 8.8.8.8 --> DNS response 198.61.170.85 --> eyez-on 192.168.1.50 --> Plex (random source port hitting 51220 on the EVL, no response sent that I can see)

There are no other devices talking to the EVL......

The disconnect in the logs goes like this:

2022-02-19 10:22:28 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:22:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:23:01 INFO (MainThread) [hole] Response from *hole: 200
2022-02-19 10:23:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 10:23:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:23:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:24:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 10:24:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:24:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:25:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 10:25:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:25:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:26:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 10:26:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:26:33 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 10:27:00 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2022-02-19 10:27:00 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:27:30 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:27:40 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:27:40 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:27:40 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:28:01 INFO (MainThread) [hole] Response from *hole: 200
2022-02-19 10:28:01 INFO (MainThread) [custom_components.hacs] Loading known repositories
2022-02-19 10:28:10 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:28:13 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:28:13 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:28:13 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:28:43 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:28:46 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:28:46 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:28:46 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:29:16 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:29:19 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:29:19 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:29:19 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:29:49 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:29:53 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:29:53 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:29:53 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:30:23 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:30:26 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:30:26 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:30:26 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:30:56 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:30:59 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 10:30:59 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 10:30:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 10:31:29 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 10:31:29 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5053CD
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login for code: 505 with data: 3
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'005SQldezJ86A'
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000052A
5051CB
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 005
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login_success for code: 505 with data: 1
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Password accepted, session created
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'010103102192286'
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00191'
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login_success
2022-02-19 10:31:29 INFO (MainThread) [homeassistant.components.envisalink] Established a connection with the Envisalink
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50001026
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 010
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000126
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 001
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 10:31:29 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

And the corresponding packet trace:

No. Time    Source  Destination Protocol    Length  Info
8350075 10:22:26.698840 192.168.1.15    8.8.8.8 DNS 81  Standard query 0x5451 A alerts0.envisacor.com
8357540 10:22:29.241939 192.168.1.10    192.168.1.15    TCP 74  37662 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=325930149 TSecr=0 WS=128
8357541 10:22:29.241939 192.168.1.10    192.168.1.15    TCP 74  [TCP Out-Of-Order] [TCP Port numbers reused] 37662 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=325930149 TSecr=0 WS=128
8357542 10:22:29.242376 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [SYN, ACK] Seq=0 Ack=1 Win=1300 Len=0 MSS=1260
8357543 10:22:29.242376 192.168.1.15    192.168.1.10    TCP 60  [TCP Out-Of-Order] 4025 → 37662 [SYN, ACK] Seq=0 Ack=1 Win=1300 Len=0 MSS=1260
8357544 10:22:29.242456 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=1 Ack=1 Win=64240 Len=0
8357545 10:22:29.242456 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357544#1] 37662 → 4025 [ACK] Seq=1 Ack=1 Win=64240 Len=0
8357546 10:22:29.242885 192.168.1.15    192.168.1.10    TCP 62  4025 → 37662 [PSH, ACK] Seq=1 Ack=1 Win=1300 Len=8
8357547 10:22:29.242885 192.168.1.15    192.168.1.10    TCP 62  [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=1 Ack=1 Win=1300 Len=8
8357548 10:22:29.243071 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=1 Ack=9 Win=64232 Len=0
8357549 10:22:29.243071 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357548#1] 37662 → 4025 [ACK] Seq=1 Ack=9 Win=64232 Len=0
8357559 10:22:29.244259 192.168.1.10    192.168.1.15    TCP 69  37662 → 4025 [PSH, ACK] Seq=1 Ack=9 Win=64232 Len=15
8357560 10:22:29.244259 192.168.1.10    192.168.1.15    TCP 69  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=1 Ack=9 Win=64232 Len=15
8357576 10:22:29.244734 192.168.1.15    192.168.1.10    TCP 72  4025 → 37662 [PSH, ACK] Seq=9 Ack=16 Win=1300 Len=18
8357577 10:22:29.244734 192.168.1.15    192.168.1.10    TCP 72  [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=9 Ack=16 Win=1300 Len=18
8357579 10:22:29.245035 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=16 Ack=27 Win=64214 Len=0
8357580 10:22:29.245035 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357579#1] 37662 → 4025 [ACK] Seq=16 Ack=27 Win=64214 Len=0
8357581 10:22:29.246214 192.168.1.10    192.168.1.15    TCP 71  37662 → 4025 [PSH, ACK] Seq=16 Ack=27 Win=64214 Len=17
8357582 10:22:29.246214 192.168.1.10    192.168.1.15    TCP 71  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=16 Ack=27 Win=64214 Len=17
8357583 10:22:29.246296 192.168.1.10    192.168.1.15    TCP 61  37662 → 4025 [PSH, ACK] Seq=33 Ack=27 Win=64214 Len=7
8357584 10:22:29.246296 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=33 Ack=27 Win=64214 Len=7
8357585 10:22:29.246296 192.168.1.15    192.168.1.10    TCP 317 4025 → 37662 [PSH, ACK] Seq=27 Ack=16 Win=1300 Len=263
8357586 10:22:29.246377 192.168.1.15    192.168.1.10    TCP 317 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=27 Ack=16 Win=1300 Len=263
8357587 10:22:29.246478 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=290 Win=63951 Len=0
8357588 10:22:29.246478 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357587#1] 37662 → 4025 [ACK] Seq=40 Ack=290 Win=63951 Len=0
8357589 10:22:29.246813 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [ACK] Seq=27 Ack=33 Win=1300 Len=0
8357590 10:22:29.246813 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [ACK] Seq=27 Ack=33 Win=1300 Len=0
8357591 10:22:29.246895 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357587#2] 37662 → 4025 [ACK] Seq=40 Ack=290 Win=63951 Len=0
8357592 10:22:29.246895 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357587#3] 37662 → 4025 [ACK] Seq=40 Ack=290 Win=63951 Len=0
8357593 10:22:29.247261 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [ACK] Seq=27 Ack=40 Win=1300 Len=0
8357594 10:22:29.247261 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [ACK] Seq=27 Ack=40 Win=1300 Len=0
8357620 10:22:29.249533 192.168.1.15    192.168.1.10    TCP 64  4025 → 37662 [PSH, ACK] Seq=290 Ack=40 Win=1300 Len=10
8357621 10:22:29.249533 192.168.1.15    192.168.1.10    TCP 64  [TCP Fast Retransmission] 4025 → 37662 [PSH, ACK] Seq=290 Ack=40 Win=1300 Len=10
8357622 10:22:29.249846 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=300 Win=63951 Len=0
8357623 10:22:29.249846 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357622#1] 37662 → 4025 [ACK] Seq=40 Ack=300 Win=63951 Len=0
8357626 10:22:29.250681 192.168.1.15    192.168.1.10    TCP 64  4025 → 37662 [PSH, ACK] Seq=300 Ack=40 Win=1300 Len=10
8357627 10:22:29.250681 192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=300 Ack=40 Win=1300 Len=10
8357628 10:22:29.250781 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=310 Win=63951 Len=0
8357629 10:22:29.250781 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8357628#1] 37662 → 4025 [ACK] Seq=40 Ack=310 Win=63951 Len=0
8358915 10:22:29.702810 192.168.1.15    192.168.1.10    TCP 294 4025 → 37662 [PSH, ACK] Seq=310 Ack=40 Win=1300 Len=240
8358916 10:22:29.702810 192.168.1.15    192.168.1.10    TCP 294 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=310 Ack=40 Win=1300 Len=240
8358917 10:22:29.702810 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=550 Win=63784 Len=0
8358918 10:22:29.702810 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8358917#1] 37662 → 4025 [ACK] Seq=40 Ack=550 Win=63784 Len=0
8360408 10:22:30.247473 192.168.1.15    192.168.1.10    TCP 64  4025 → 37662 [PSH, ACK] Seq=550 Ack=40 Win=1300 Len=10
8360410 10:22:30.247473 192.168.1.15    192.168.1.10    TCP 64  [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=550 Ack=40 Win=1300 Len=10
8360413 10:22:30.247708 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=560 Win=63784 Len=0
8360414 10:22:30.247708 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8360413#1] 37662 → 4025 [ACK] Seq=40 Ack=560 Win=63784 Len=0
8360649 10:22:30.326429 192.168.1.15    192.168.1.10    TCP 63  4025 → 37662 [PSH, ACK] Seq=560 Ack=40 Win=1300 Len=9
8360650 10:22:30.326429 192.168.1.15    192.168.1.10    TCP 63  [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=560 Ack=40 Win=1300 Len=9
8360651 10:22:30.326737 192.168.1.10    192.168.1.15    TCP 60  37662 → 4025 [ACK] Seq=40 Ack=569 Win=63784 Len=0
8360652 10:22:30.326737 192.168.1.10    192.168.1.15    TCP 60  [TCP Dup ACK 8360651#1] 37662 → 4025 [ACK] Seq=40 Ack=569 Win=63784 Len=0
8365569 10:22:32.198263 192.168.1.15    8.8.8.8 DNS 81  Standard query 0x6f52 A alerts0.envisacor.com
8366827 10:22:32.698680 192.168.1.15    192.168.1.10    TCP 292 4025 → 37662 [PSH, ACK] Seq=569 Ack=40 Win=1300 Len=238
8372685 10:22:34.698459 192.168.1.15    192.168.1.10    TCP 292 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=569 Ack=40 Win=1300 Len=238
8373511 10:22:34.941765 192.168.1.10    192.168.1.15    TCP 61  37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8373758 10:22:35.150665 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8374755 10:22:35.558617 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8376811 10:22:36.422575 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8377360 10:22:36.706833 192.168.1.15    198.61.170.85   UDP 394 7004 → 4021 Len=352
8381252 10:22:38.086679 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8390014 10:22:41.350720 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8393288 10:22:42.706361 192.168.1.15    198.61.170.85   UDP 394 7006 → 4021 Len=352
8393289 10:22:42.706567 192.168.1.15    8.8.8.8 DNS 81  Standard query 0xb358 A alerts0.envisacor.com
8405692 10:22:47.705754 192.168.1.15    198.61.170.85   UDP 394 7006 → 4021 Len=352
8405694 10:22:47.705945 192.168.1.15    8.8.8.8 DNS 81  Standard query 0xdd5d A alerts0.envisacor.com
8406661 10:22:48.070883 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8419568 10:22:53.195947 192.168.1.15    8.8.8.8 DNS 81  Standard query 0x0d5f A alerts0.envisacor.com
8435090 10:22:58.695357 192.168.1.15    8.8.8.8 DNS 81  Standard query 0x4264 A alerts0.envisacor.com
8442153 10:23:01.382921 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8447471 10:23:03.694903 192.168.1.15    8.8.8.8 DNS 81  Standard query 0x7c69 A alerts0.envisacor.com
8447486 10:23:03.729316 8.8.8.8 192.168.1.15    DNS 97  Standard query response 0x7c69 A alerts0.envisacor.com A 198.61.170.85
8454384 10:23:06.203697 192.168.1.15    198.61.170.85   UDP 394 7007 → 4021 Len=352
8469342 10:23:11.702752 192.168.1.15    198.61.170.85   UDP 394 7007 → 4021 Len=352
8495488 10:23:21.692985 192.168.1.15    192.168.1.10    TCP 292 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=569 Ack=40 Win=1300 Len=238
8510364 10:23:27.495242 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
8517828 10:23:30.200960 192.168.1.15    198.61.170.85   UDP 394 7009 → 4021 Len=352
8532069 10:23:35.700591 192.168.1.15    198.61.170.85   UDP 394 7009 → 4021 Len=352
8559011 10:23:46.191149 192.168.1.15    192.168.1.10    TCP 292 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=569 Ack=40 Win=1300 Len=238
8625435 10:24:10.689065 192.168.1.15    192.168.1.10    TCP 292 [TCP Retransmission] 4025 → 37662 [PSH, ACK] Seq=569 Ack=40 Win=1300 Len=238
8631100 10:24:11.197502 192.168.1.15    198.61.170.85   UDP 394 7010 → 4021 Len=352
8647862 10:24:16.697195 192.168.1.15    198.61.170.85   UDP 394 7010 → 4021 Len=352
8648156 10:24:16.874906 198.61.170.85   192.168.1.15    UDP 74  4021 → 7010 Len=32
8671811 10:24:24.696217 192.168.1.15    198.61.170.85   UDP 394 7010 → 4021 Len=352
8700205 10:24:35.185606 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [RST, ACK] Seq=569 Ack=40 Win=1300 Len=0
8705682 10:24:37.194329 192.168.1.15    198.61.170.85   UDP 394 7011 → 4021 Len=352
8720373 10:24:42.693705 192.168.1.15    198.61.170.85   UDP 394 7011 → 4021 Len=352
8786143 10:25:06.691437 192.168.1.15    198.61.170.85   UDP 394 7012 → 4021 Len=352
8801213 10:25:11.690892 192.168.1.15    198.61.170.85   UDP 394 7012 → 4021 Len=352
8816848 10:25:17.689951 192.168.1.15    198.61.170.85   UDP 394 7013 → 4021 Len=352
8830518 10:25:22.689069 192.168.1.15    198.61.170.85   UDP 394 7013 → 4021 Len=352
8848553 10:25:29.188230 192.168.1.15    198.61.170.85   UDP 394 7014 → 4021 Len=352
8849091 10:25:29.363931 198.61.170.85   192.168.1.15    UDP 74  4021 → 7014 Len=32
8855757 10:25:32.188533 192.168.1.15    198.61.170.85   UDP 394 7014 → 4021 Len=352
8899795 10:25:49.690566 192.168.1.15    198.61.170.85   UDP 394 7015 → 4021 Len=352
8926977 10:25:59.191413 192.168.1.15    198.61.170.85   UDP 394 7016 → 4021 Len=352
8942409 10:26:04.692248 192.168.1.15    198.61.170.85   UDP 394 7016 → 4021 Len=352
8942601 10:26:04.870414 198.61.170.85   192.168.1.15    UDP 74  4021 → 7016 Len=32
9010601 10:26:28.195380 192.168.1.15    198.61.170.85   UDP 394 7016 → 4021 Len=352
9067115 10:26:48.698030 192.168.1.15    198.61.170.85   UDP 394 7017 → 4021 Len=352
9101313 10:27:02.025792 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
9101314 10:27:02.025792 192.168.1.10    192.168.1.15    TCP 61  [TCP Retransmission] 37662 → 4025 [PSH, ACK] Seq=40 Ack=569 Win=63784 Len=7
9101315 10:27:02.026149 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [RST, ACK] Seq=569 Ack=41 Win=63784 Len=0
9101316 10:27:02.026149 192.168.1.15    192.168.1.10    TCP 60  4025 → 37662 [RST, ACK] Seq=569 Ack=41 Win=63784 Len=0
9162261 10:27:24.704460 192.168.1.15    198.61.170.85   UDP 394 7018 → 4021 Len=352
9181170 10:27:32.029016 192.168.1.10    192.168.1.15    TCP 74  42866 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=326232934 TSecr=0 WS=128
9184103 10:27:33.065665 192.168.1.10    192.168.1.15    TCP 74  [TCP Retransmission] [TCP Port numbers reused] 42866 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=326233970 TSecr=0 WS=128
9190136 10:27:35.113852 192.168.1.10    192.168.1.15    TCP 74  [TCP Retransmission] [TCP Port numbers reused] 42866 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=326236018 TSecr=0 WS=128
9201879 10:27:39.145853 192.168.1.10    192.168.1.15    TCP 74  [TCP Retransmission] [TCP Port numbers reused] 42866 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=326240050 TSecr=0 WS=128
9239470 10:27:53.200329 192.168.1.15    8.8.8.8 DNS 81  Standard query 0xac6a A alerts0.envisacor.com
9239858 10:27:53.414588 8.8.8.8 192.168.1.15    DNS 97  Standard query response 0xac6a A alerts0.envisacor.com A 198.61.170.85
9260540 10:28:00.210499 192.168.1.15    198.61.170.85   UDP 394 7019 → 4021 Len=352
9276742 10:28:05.711431 192.168.1.15    198.61.170.85   UDP 394 7019 → 4021 Len=352
9316221 10:28:17.213067 192.168.1.15    198.61.170.85   UDP 394 7021 → 4021 Len=352
9331041 10:28:22.713767 192.168.1.15    198.61.170.85   UDP 394 7021 → 4021 Len=352
9362903 10:28:34.215455 192.168.1.15    198.61.170.85   UDP 394 7022 → 4021 Len=352
9377510 10:28:39.716031 192.168.1.15    198.61.170.85   UDP 394 7022 → 4021 Len=352
9469691 10:29:15.220734 192.168.1.15    198.61.170.85   UDP 394 7023 → 4021 Len=352
9524093 10:29:34.222656 192.168.1.15    198.61.170.85   UDP 394 7024 → 4021 Len=352
9539463 10:29:39.723420 192.168.1.15    198.61.170.85   UDP 394 7024 → 4021 Len=352
9540045 10:29:39.900058 198.61.170.85   192.168.1.15    UDP 74  4021 → 7024 Len=32
9545595 10:29:42.223712 192.168.1.15    198.61.170.85   UDP 394 7024 → 4021 Len=352
9545978 10:29:42.401267 198.61.170.85   192.168.1.15    UDP 74  4021 → 7024 Len=32
9619691 10:30:09.225932 192.168.1.15    198.61.170.85   UDP 394 7024 → 4021 Len=352
9620345 10:30:09.410006 198.61.170.85   192.168.1.15    UDP 74  4021 → 7024 Len=32
9639896 10:30:14.726476 192.168.1.15    198.61.170.85   UDP 394 7024 → 4021 Len=352
9728433 10:30:50.230564 192.168.1.15    198.61.170.85   UDP 394 7025 → 4021 Len=352
9780661 10:31:11.733435 192.168.1.15    198.61.170.85   UDP 394 7026 → 4021 Len=352
9798351 10:31:16.734029 192.168.1.15    198.61.170.85   UDP 394 7026 → 4021 Len=352
9849010 10:31:30.559469 192.168.1.10    192.168.1.15    TCP 74  47386 → 4025 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=326471461 TSecr=0 WS=128

It really does look like the EVL close out it just 'happening' there doesn't appear to be any odd traffic as far as source/destination is concerned....so then it has to be:

  1. A firmware fault in the EVL; or
  2. Something in the TX data from eyez-on; or
  3. Something in the TX data from HA.

The packets from above should be in the attached pcap.

EVL Disconnect.zip

ChirpyTurnip commented 2 years ago

OK - found two more checksum errors:

2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_timer_dump
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000082D
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61597FE94FEB4FFB1FFB2FF86FE000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000009
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: 97FE94FEB4FFB1FFB2FF86FE0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 10) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 11) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 12) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 13) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 14) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 15) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 16) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 17) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 18) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 19) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 20) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 21) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 22) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 23) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 24) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 25) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 26) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 27) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 28) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 29) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 30) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 31) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 32) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 33) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 34) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 35) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 36) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 37) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 38) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 39) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 40) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 41) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 42) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 43) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 44) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 45) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 46) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 47) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 48) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 49) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 50) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 51) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 52) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 53) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 54) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 55) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 56) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 57) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 58) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 59) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 60) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 61) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 62) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 63) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 64) closed
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_timer_dump
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:09:49 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50202029
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 502, skipping...
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50196
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-19 13:10:02 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response_error
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-19 13:10:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

and 

2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000025
5000082D
5000082D
50000025
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 008
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 000
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 61534FE31FE51FF4EFF4FFF23FE0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000EA
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_timer_dump for code: 615 with data: 34FE31FE51FF4EFF4FFF23FE0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 1) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 2) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 3) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 4) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 5) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 6) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 7) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 8) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 9) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 10) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 11) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 12) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 13) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 14) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 15) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 16) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 17) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 18) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 19) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 20) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 21) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 22) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 23) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 24) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 25) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 26) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 27) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 28) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 29) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 30) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 31) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 32) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 33) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 34) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 35) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 36) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 37) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 38) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 39) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 40) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 41) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 42) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 43) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 44) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 45) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 46) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 47) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 48) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 49) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 50) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 51) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 52) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 53) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 54) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 55) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 56) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 57) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 58) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 59) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 60) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 61) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 62) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 63) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] (zone 64) closed
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_timer_dump
2022-02-19 13:18:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:18:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 13:18:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 13:18:05 WARNING (SyncWorker_5) [homeassistant.components.sonos] Failed to connect to discovered player '192.168.1.115': HTTPConnectionPool(host='192.168.1.115', port=1400): Max retries exceeded with url: /MediaRenderer/RenderingControl/Control (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f9fa2f90400>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
2022-02-19 13:18:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 13:19:02 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 13:19:04 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 13:19:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00898'
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50202029
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.dsc_client] No handler defined in config for 502, skipping...
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No handler configured for evl command.
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] KeyError: 'handler'
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50196
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_command_response_error for code: 501 with data: 
2022-02-19 13:19:47 ERROR (MainThread) [pyenvisalink.dsc_client] The previous command resulted in a checksum failure.
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_command_response_error
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] No callback configured for evl command.
2022-02-19 13:19:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

Still no NUL errors, but in the past 6 hours there have been another 23 disconnection events.

I'm going to restart HA now and run without the zone dumps.

Packet capture is attached. EVL Checksum Error.zip

ufodone commented 2 years ago

Do you have the full HA log that the above two checksum errors are from? I see a bit of an odd thing in the capture where there are bunches of 008 commands in a single request to the EVL. I don't think that should be happening and would like to compare the timing in the capture file with that of the HA logs.

ChirpyTurnip commented 2 years ago

I do....here they are in all their ugliness....

Checksum Errors - HA Log.zip

ChirpyTurnip commented 2 years ago

I also found an old post somewhere that related to a similar server disconnection problem on the old EVL3 where the issue was related to password length....it's a long shot but since I've got nothing else to do and I'm running a bogus password anyway I've simplified it down to 'abcd' just in case....you never know.... ;-)

ufodone commented 2 years ago

According to the docs, the EVL3 supports passwords up to 6 characters and the EVL4 supports up to 10 characters. If your password was too long, I suspect you'd be seeing the login command fail and then the disconnect.

Thanks for that log. I've figured out why all those 008 commands were batched together. I believe it's due to the retransmissions causing big delays. HA will send that command (based on your config) every 30 seconds but because there is unACK'd data on the connection, they aren't actually sent to the EVL until there is an ACK from the previous data that had been sent. This causes multiple of these commands to queue up and then when the EVL finally ACKs the previous data, the bunch of them are all sent together.

I don't see any bad data in the capture that should cause a checksum error but it's possible that with the data coming into the EVL in batches maybe there's some circumstance where it thinks it gets an invalid request.

In any case, I think the priority should be to figure out where all these retransmissions are coming from as they are, at best, causing big delays and at worst triggering the checksum, etc. errors. I'm seeing retransmissions in BOTH directions.

Are you able to do a network capture directly on the NUC and a parallel one using port mirroring on the NUC's network port? Comparing those two captures could help narrow down where the packets are being lost. E.g. if the port mirror capture sees the packets but the NUC capture doesn't then the issue is likely with the NUC's network card/stack. Conversely if both captures look the same then the issue is likely between the NUC's switch port and the EVL.

ufodone commented 2 years ago

I'll also add that I think it's unlikely an issue with your NUC as the retransmissions are so pervasive that it's hard to believe it wouldn't be causing other issues with HA.

An alternative could be to disable the envisalink integration in HA and then run the pyenvisalink test app on a different computer. That could help isolate the problem away from HA and the host it is running on.

ChirpyTurnip commented 2 years ago

Ah yes...the gift that keeps on giving!

I know the password shouldn't have made a difference...and despite starting with almost 90 minutes with no disconnections after the change (which almost made me stupidly hopeful) it came back with a vengeance. So no miracle cure.... And it was a pain to do too - you have to turn off HA so you're not fighting for the EVL web interface, and when you get into it the pages are so super slow that they time out and you have refresh the browser to get it load....it's hopeless.

I'm not sure if I can do a packet capture from the NUC as I'm running HASSOS so it is all pretty much a closed shop by design. I've swapped the switch ports used for a few things just in case I have a bad patch...but again a long shot.

I can however easily disable the HA integration and run a test app on another PC if you can point me to the test app (and some instructions)?

Also, as I write this I'm doing some more fiddling as there's some weirdness now as the EVL is talking to eyez-on but is completely ignoring HA and not picking up a connection. 

2022-02-19 21:35:31 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:36:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:37:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:38:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:39:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:40:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:41:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:42:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:43:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:45:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:46:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:47:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:48:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:49:03 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00090'
2022-02-19 21:49:41 ERROR (MainThread) [pyenvisalink.envisalink_base_client] The server closed the connection. Reconnecting...
2022-02-19 21:49:41 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:50:11 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:50:21 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:50:21 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:50:21 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:50:51 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:51:01 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:51:01 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:51:01 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:51:31 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:51:34 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:51:34 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:51:34 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:52:04 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:52:07 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:52:07 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:52:07 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:52:37 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:52:41 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:52:41 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:52:41 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:53:11 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:53:14 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:53:14 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:53:14 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:53:44 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:53:44 WARNING (SyncWorker_13) [homeassistant.components.sonos] Failed to connect to discovered player '192.168.1.115': HTTPConnectionPool(host='192.168.1.115', port=1400): Max retries exceeded with url: /MediaRenderer/RenderingControl/Control (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f77126dbdc0>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
2022-02-19 21:53:47 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:53:47 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:53:47 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...
2022-02-19 21:54:04 INFO (MainThread) [hole] Response from *hole: 200
2022-02-19 21:54:07 WARNING (SyncWorker_11) [homeassistant.components.sonos] Failed to connect to discovered player 
2022-02-19 21:54:17 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:54:27 ERROR (MainThread) [pyenvisalink.envisalink_base_client] Unable to connect to envisalink. Reconnecting...
2022-02-19 21:54:27 ERROR (MainThread) [homeassistant.components.envisalink] Could not establish a connection with the Envisalink- retrying
2022-02-19 21:54:27 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Closing connection with server...

Just gone and not coming back......until suddenly....

2022-02-19 21:54:57 INFO (MainThread) [pyenvisalink.envisalink_base_client] Started to connect to Envisalink... at 192.168.1.15:4025
2022-02-19 21:54:59 INFO (MainThread) [pyenvisalink.envisalink_base_client] Connection Successful!
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5053CD
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login for code: 505 with data: 3
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'005abcd1F'
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 5000052A
5051CB
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 005
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_login_success for code: 505 with data: 1
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Password accepted, session created
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'01021540219228D'
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] TX > b'00191'
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_login_success
2022-02-19 21:54:59 INFO (MainThread) [homeassistant.components.envisalink] Established a connection with the Envisalink
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50001026
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 010
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] RX < 50000126
61000128
61000229
6100032A
6100042B
6100052C
6100062D
6100072E
6100082F
61000930
61001028
61001129
6100122A
6100132B
6100142C
6100152D
6100162E
6100172F
61001830
61001931
61002029
6100212A
6100222B
6100232C
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_poll_response for code: 500 with data: 001
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] DSC ack recieved.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_poll_response
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.alarm_panel] Callback has not been set by client.
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 001
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 1) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 002
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 2) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 003
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 3) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 004
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 4) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 005
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 5) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 006
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 6) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 007
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 7) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 008
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 8) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 009
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 9) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 010
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 10) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 011
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 11) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 012
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 12) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 013
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 13) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 014
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 14) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 015
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 15) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 016
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 16) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 017
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 17) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 018
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 18) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 019
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 19) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 020
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 20) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 021
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 21) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 022
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 22) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] calling handler: handle_zone_state_change for code: 610 with data: 023
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.dsc_client] (zone 23) state has updated: {"open": false}
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] Invoking callback: callback_zone_state_change
2022-02-19 21:54:59 DEBUG (MainThread) [pyenvisalink.envisalink_base_client] ----------------------------------------

The pcap (only from the EVL side) is attached (but it doesn't start until 21:46).

And yes, time for bed here!

EVL TX-RX ONLY - Long Outage Period.zip

ufodone commented 2 years ago

That capture is interesting in the sense that there appears to be a bunch of connection attempts that the HA logs show that aren't showing up the capture - specifically between when the connection is lost at 21:49:41 and then nothing again until around 21:53:48. The HA logs show a good number of connection attempts between those time periods but they aren't in the capture file. This could definitely be due to packet loss.

There appears to be packet loss or delays in BOTH directions which makes me think this is not a software issue on the EVL or HA side. The bad data we saw earlier likely was but the EVL reboot seems to have addressed that.

What exactly does your wiring setup look like? You initially indicated that the EVL and HA host are patched into the same switch but what's in-between? Maybe something like:

EVL <-> Wall Jack <-> Cable to patch panel <-> Patch Panel <-> Switch <-> Patch Panel <-> Wall Jack <-> HA

I know you've swapped some patch cables previous but did that cover all hops along the way?

I can however easily disable the HA integration and run a test app on another PC if you can point me to the test app (and some instructions)?

This would require you to have a computer with python3 installed. Once that's setup, you could do something like:

> mkdir evltest
> cd evltest
> python3 -m venv .
> pip install pyenvisalink
> pip install async_timeout
> python lib/python3.9/site-packages/pyenvisalink/test_harness.py

You might need to adjust these commands a bit depending on what OS, etc. you are using. That last command will run the test harness and prompt you for your EVL IP, port, etc. info and then connect up to the EVL. At that point it should be pretty similar to how it runs in HA.

ChirpyTurnip commented 2 years ago

Ok....initial answer:

EVL <--> Patch Cable <--> Switch #1 HA <--> Patch Cable <--> Wall Jack <--> Cable to Patch Panel <--> Patch Panel <--> Patch Cable <--> Switch #1

For the EVL I have changed the patch lead

For HA I have changed the wall jack to another port (which then automatically switches out the Wall Jack <--> Cable to Patch Panel <--> Patch Panel <--> Patch Cable <--> Switch #1 chain as the adjacent port has it's own path.

I have now also:

EVL --> Move to a new port on the switch HA --> Replaced patch lead from HA to wall jack

So at this point technically I don't think there is anything else I can replace.

Now the really interesting thing is having just done this I updated my port mirrors so that the new EVL port and HA port are both exporting data again to Wireshark...and wouldn't you it...but I've done it right at the time that there is another one of those long outage periods!

In the HA logs we once again see normal traffic to EVL, and then suddenly a series of "TX > b'00090'" messages that go unanswered.

Now I can confirm that I'm seeing a lot of traffic from HA going all over the place....and I can see traffic for the EVL going to eyez-on.....but I CANNOT see traffic from HA going to the EVL....so it doesn't appear to be sending anything even though the logs claim that it is sending data....

So thinking logically, if HA is putting messages on the wire for everything else there is no reason why it wouldn't be sending the EVL traffic. So here am I thinking that maybe there's a problem in HA not actually sending what it is supposed to be sending.

But then it got weirder....I figured why not ping the EVL and see what I get because that's a good way to prove it is online! The answer is lots of lost packets.... From my PC I got 43% - 68% loss (via WiFi connection) and when I decided to ping from pfSense (directly wired into the switch) I got progressively worse results based on sets of 10 pings sent 1 second apart:

  1. 50% loss
  2. 60% loss
  3. 90% loss
  4. 100% loss

I've attached the log snippet from HA and some pcaps:

  1. Full pcap (with this filter: not arp and not dns and ip) but obviously due to the size only for about 3 seconds to show the full traffic (13:54:03 to 13:54:06 to coincide with this - 2022-02-20 13:54:04 DEBUG (MainThread) pyenvisalink.envisalink_base_client] TX > b'00090')
  2. Just the EVL-related traffic (ip.addr==192.168.1.15) which included the ping loss.

Lastly there are no checksum errors since turning off the zone dump.

So...where does this leave us? The NUL and checksum errors seem to have gone away, which is a win, but we still have issues as the connection is still bad.

  1. HA claims to be doing a TX but we can't see it on the wire...so it is probably lying because we can see all the other HA traffic.
  2. EVL keeps closing connections, and doesn't respond to pings (even with HA shut down).

The ping thing bothered me....a LOT. So dust off an old LevelOne Gigabit switch.....and change the layout so that HA and the EVL connect directly to a dumb switch, then uplink to the one of the uplink ports on the linksys switch. See what happens.

The results are surprising.....the ping improves but we are still losing 40-60% of the pings from the pfSense box. BUT, the web interface is completely different now - it's actually snappy! Before it was timing out, now I can jump from the home page to the network page and back again and it just works. So WTF?

Undeterred, now try ping from HA console, which is on the same dumb switch:

PING 192.168.1.15 (192.168.1.15): 56 data bytes
64 bytes from 192.168.1.15: seq=0 ttl=64 time=0.908 ms
64 bytes from 192.168.1.15: seq=3 ttl=64 time=0.985 ms
64 bytes from 192.168.1.15: seq=4 ttl=64 time=0.865 ms
64 bytes from 192.168.1.15: seq=5 ttl=64 time=0.949 ms
64 bytes from 192.168.1.15: seq=6 ttl=64 time=1.025 ms
64 bytes from 192.168.1.15: seq=7 ttl=64 time=0.889 ms
64 bytes from 192.168.1.15: seq=10 ttl=64 time=0.871 ms
64 bytes from 192.168.1.15: seq=11 ttl=64 time=0.866 ms
64 bytes from 192.168.1.15: seq=12 ttl=64 time=0.829 ms
64 bytes from 192.168.1.15: seq=15 ttl=64 time=0.805 ms
64 bytes from 192.168.1.15: seq=16 ttl=64 time=0.608 ms
64 bytes from 192.168.1.15: seq=17 ttl=64 time=0.903 ms
64 bytes from 192.168.1.15: seq=18 ttl=64 time=0.711 ms
64 bytes from 192.168.1.15: seq=19 ttl=64 time=2.794 ms
64 bytes from 192.168.1.15: seq=22 ttl=64 time=0.727 ms
64 bytes from 192.168.1.15: seq=23 ttl=64 time=0.707 ms
64 bytes from 192.168.1.15: seq=24 ttl=64 time=0.847 ms
64 bytes from 192.168.1.15: seq=27 ttl=64 time=2.004 ms
64 bytes from 192.168.1.15: seq=30 ttl=64 time=0.882 ms
64 bytes from 192.168.1.15: seq=31 ttl=64 time=0.894 ms
64 bytes from 192.168.1.15: seq=34 ttl=64 time=0.743 ms
64 bytes from 192.168.1.15: seq=35 ttl=64 time=0.743 ms
64 bytes from 192.168.1.15: seq=36 ttl=64 time=0.788 ms
^C
--- 192.168.1.15 ping statistics ---
38 packets transmitted, 23 packets received, 39% packet loss
round-trip min/avg/max = 0.608/0.971/2.794 ms

So even taking out everything simple pinging to the EVL is resulting in abject failure. Even if I run ha core stop so that there is no connection to the EVL I get the same result:

PING 192.168.1.15 (192.168.1.15): 56 data bytes
64 bytes from 192.168.1.15: seq=0 ttl=64 time=0.645 ms
64 bytes from 192.168.1.15: seq=1 ttl=64 time=0.945 ms
64 bytes from 192.168.1.15: seq=2 ttl=64 time=0.903 ms
64 bytes from 192.168.1.15: seq=3 ttl=64 time=1.000 ms
64 bytes from 192.168.1.15: seq=8 ttl=64 time=0.941 ms
64 bytes from 192.168.1.15: seq=9 ttl=64 time=0.913 ms
64 bytes from 192.168.1.15: seq=10 ttl=64 time=0.895 ms
64 bytes from 192.168.1.15: seq=12 ttl=64 time=0.954 ms
64 bytes from 192.168.1.15: seq=13 ttl=64 time=1.001 ms
64 bytes from 192.168.1.15: seq=14 ttl=64 time=0.940 ms
64 bytes from 192.168.1.15: seq=15 ttl=64 time=0.897 ms
64 bytes from 192.168.1.15: seq=20 ttl=64 time=0.922 ms
64 bytes from 192.168.1.15: seq=21 ttl=64 time=0.919 ms
64 bytes from 192.168.1.15: seq=22 ttl=64 time=0.927 ms
64 bytes from 192.168.1.15: seq=24 ttl=64 time=0.809 ms
64 bytes from 192.168.1.15: seq=25 ttl=64 time=0.938 ms
64 bytes from 192.168.1.15: seq=26 ttl=64 time=0.937 ms
64 bytes from 192.168.1.15: seq=27 ttl=64 time=0.987 ms
64 bytes from 192.168.1.15: seq=32 ttl=64 time=0.943 ms
64 bytes from 192.168.1.15: seq=33 ttl=64 time=0.913 ms
64 bytes from 192.168.1.15: seq=34 ttl=64 time=0.924 ms
^C
--- 192.168.1.15 ping statistics ---
36 packets transmitted, 21 packets received, 41% packet loss
round-trip min/avg/max = 0.645/0.916/1.001 ms

So:

  1. Replaced the cables
  2. Replaced the switch
  3. Restarted/rebooted everything
  4. Pinged from multiple locations to the EVL

And the result is bad, bad, and more bad.

What are we missing?

:-(

HA Log Snippet.txt HA-EVL No HA TX (full capture)_3s.zip HA-EVL TX-RX including ping loss.zip

ChirpyTurnip commented 2 years ago

Because the interface is so much better running on the dumb switch I'll leave all of it running on there for a bit and we'll see what happens. If the disconnections continue then it isn't the switch....

If there are no server disconnections I'm going to move HA back onto the main switch but leave the EVL on the dumb switch..... and then leave it for a few hours....you can see where this is going.

I can't packet capture now unfortunately as well...dumb switch and all HA <--> EVL traffic is now local to the switch...

ufodone commented 2 years ago

Thanks for the info. It definitely sounds like you've tried enough wiring combinations to eliminate that as an issue.

So thinking logically, if HA is putting messages on the wire for everything else there is no reason why it wouldn't be sending the EVL traffic. So here am I thinking that maybe there's a problem in HA not actually sending what it is supposed to be sending.

It's not quite that simple unfortunately. The application (HA in this case) sends data via the OS's kernel. The network stack in the kernel takes care of packaging all that up and sending it over the TCP connection. To the application can successfully send data even if it hasn't actually been put out on the wire yet. What I believe is happening here (which I confirmed by looking back at the EVL Checksum Error.pcapng capture) is that the HA host is sending data but the EVL is not acknowledging it (and in fact continues to acknowledge previous packets). In the case I looked at, this went on for over 3.5 minutes. During this time, HA kept merrily writing data - which was accepted by the OS and buffered. When the EVL eventually acknowledged the previous packet, the HA OS was then able to send more data. This is why we see a single packet with a bunch of the keep alive (000) and zone dump (008) commands in it. So, definitely not an HA problem in my mind.

In case you're interested in following along in the capture on this, the 000 & 008 commands are sent in frame 536:

14:19:05.151790 IP 192.168.1.10.36468 > 192.168.1.15.4025: Flags [P.], seq 54:61, ack 1151, win 63784, length 7

This will expect an ACK back from the EVL for seqno 61. But instead you'll see a series of packets from the EVL pushing new data to HA but only ACKing the previous packet (seqno 47). They look like this:

14:19:45.881713 IP 192.168.1.15.4025 > 192.168.1.10.36468: Flags [P.], seq 1161:1170, ack 47, win 1300, length 9

Minutes later, the HA host finally retransmits the previous packet (the one after the one the EVL is constantly ACKing):

14:22:41.326469 IP 192.168.1.10.36468 > 192.168.1.15.4025: Flags [P.], seq 47:61, ack 1340, win 63784, length 14

And finally the EVL ACKs it (seqno 61):

14:22:41.326900 IP 192.168.1.15.4025 > 192.168.1.10.36468: Flags [.], ack 61, win 1300, length 0

The HA host is finally able to "catch up" and all those commands that the envisalink integration has been sending that have been queued up in the kernel are sent as a single packet:

14:22:41.327193 IP 192.168.1.10.36468 > 192.168.1.15.4025: Flags [P.], seq 61:131, ack 1340, win 63784, length 70

Sorry, it's probably a little hard to follow along with just little snippets from the capture file. :)

The behaviour you saw when putting the dumb switch in and eliminating the port mirroring got me curious about exactly how you have your port mirroring setup. If, for example, you had your EVL on switch port 1 and HA on switch port 2, are you mirroring both of them to switch port 3? Or are you just mirroring one of the ports? And is switch port 3 dedicated to mirroring or is it the primary connection for the host you are running wireshark on? If the latter, I've seen that be problematic before. It may vary between switch vendors but my past attempts at port mirroring have required that the port you are mirror TO needs to be dedicated and not used for any other traffic (and thus typically requires a computer with dual NICs). What can happen is that the packets arrive on the mirror port and then get reflected back out - which could potentially manifest in what appears to be duplicates or retransmissions. I'm just mentioning this as it sounded like things got better (but not good) once the port mirroring was removed from the equation.

With all this latest info you provided, this feels to me like it is increasingly likely that there is an actual problem with the EVL. Not really a conclusion either of us would like to get to but I'm running out of ideas here. If you haven't already, it might be worth reseating all the connections from the EVL to your actual DSC system. It's been a while since I looked at mine so I don't remember what connections it has but maybe something is a little flaky there (e.g. a suspect power connection that causes voltage fluctuations and causes the EVL to do weird things). While the checksum errors haven't appeared in quite a while, they also led me to believe an issue with the EVL unit.

ChirpyTurnip commented 2 years ago

I have say that analyzing the packet capture in detail is not something I've tried to do....I can the do the simple "it goes in there and and comes out here" stuff....but your write up is actually pretty sweet to follow and makes sense:

14:22:41.327193 IP 192.168.1.10.36468 > 192.168.1.15.4025: Flags [P.], seq 61:131, ack 1340, win 63784, length 70

That's the queued sequence 61:131...and because that's a catch up that's also why the length has blown out to 70....so I think I get at least the basic principle.

For the port mirror I had it set up like this:

GE:24 (EVL) --> TX/RTX --> GE:4 GE:2 (HA) --> TX/RTX --> GE:4

GE:4 is then connecting to my desk PC on the Ethernet connection. I'm using an independent WiFi connection from the same PC back onto the network for all my other connectivity....so....the Ethernet interface on my PC is dedicated to receiving the mirrored traffic. Which is dual NIC....it's just that the NICs are not both RJ45. :-)

If the mirror is down and I capture the traffic there is only ARP, STP, and LLDP traffic....no IP traffic. It's also worth noting that I don't keep the mirror up....I drop it when I'm not capturing....but the EVL problem doesn't go away....

It's only been 2.5 hours on the dumb switch (not long) and I haven't had a single "Server closed the connection...." error yet....so we will see.

It could be the switch....though I don't know why there would be such a massive difference between the dumb and managed switches....I have other things running at 100MBps and they run fine on the same switch...the EVL seems 'special'....

One thing that would be really useful is if you could run a ping test to your EVL - does it always reply? I think that would be the acid test for me....if I have a huge packet lost point-to-point on a dumb switch and yours just works that would be pretty definitive that the EVL is borken.

I can reset the cables in the alarm box, but it is all screw connectors and it seems unlikely that this would cause issues...unless the alarm is just so low on power (I think the panel can only supply 500mA) that it would just partially drop out....

Anyway...time for dinner!

ufodone commented 2 years ago

That's the queued sequence 61:131...and because that's a catch up that's also why the length has blown out to 70....so I think I get at least the basic principle

Yes, that's right. It's easier to diagnose using wireshark than tcpdump but also hard for me to cut-and-paste from there. The EVL connection isn't encrypted and it's protocol is plain text and that makes it easier to pin things down. Load up the capture file in wireshark, under the Statistic menu choose Conversations and that will break down all the different connections in the file. Identify one of the connections to 4025, click on it, right click and choose Apply Filter A<->B. Then go back to the main window, right click one of the frames and select Follow->TCP Stream. Now you'll have a nice window that shows the actual EVL protocol traffic. From there you can click on any spot and it will automatically select the frame that matches in the main window. So in that case of the 61:131 packet, you'll be able to see that it's a bunch of 000/008 commands all in the same packet.

Anyway... I ran a ping to my EVL for 131 packets and got 0 packet loss. Response times were largely sub millisecond but I'd periodically see a spike up to between 10ms and 30ms. During this time I also tried to connect to the EVL web interface. The first few times it was quick. The last time it did the stall thing where it would sit there for quite a while and then eventually connect. The pings were not affected during this time period. But in the past I have seen that when it does this, it's also not possible to connect to port 4025. So while my unit isn't exhibiting the same behaviour as yours, I would say the overall it's networking capability is a bit fragile.

but it is all screw connectors and it seems unlikely that this would cause issues.

Ah yes, that sounds familiar. I know I've had issues in the past with those screw terminal (in general) coming loose (or probably I didn't tighten them properly). I wasn't think that the alarm couldn't provide enough power to the EVL but maybe if the power connection to the EVL board was a little loose it could cause it to see a fluctuating voltage which could in turn result in the board being unreliable due to following periodically below the minimum required voltage. But maybe that's just desperation talking...

ChirpyTurnip commented 2 years ago

So sixteen hours in and there are no checksum errors, and not a single "Server closed the connection..." messages....and the detections are reported super quick to the UI.

Also, unbelievably, this morning the ping test works with minimal loss, even with two concurrent pings running, and detections are still fast. 

Ping statistics for 192.168.1.15:
    Packets: Sent = 252, Received = 249, Lost = 3 (1% loss),
Approximate round trip times in milli-seconds:
    Minimum = 1ms, Maximum = 4ms, Average = 1ms

And. I've. Changed. Nothing. It's enough to make you cry.

The only thing that really changes overnight is the temperature....but not by much. I'll tighten all the screws today.....

I'll keep you posted. :-(

ChirpyTurnip commented 2 years ago

So it turns out something has changed.....I'm muttering to my colleague about our fruitless search for answers this weekend and how nothing has changed and I noticed that the PC that run Plex is now off.....it reboots every Sunday night and then runs a powershell script to go to sleep if there is no network activity.

When I turned is back on the problems came back.....straightaway....ping loss at 60%....

So then the next logical step is to start turning things on inside the environment....and sure enough....at one magical point I found that when the PowerShield NetGuard software (it monitors the UPS) is closed the problem immediately resolved....

Turn it back on, the problem comes back, turn it off, the problem goes away:

Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=3ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=3ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Request timed out.
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=3ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128
Reply from 192.168.1.15: bytes=32 time=1ms TTL=128

I'm not going to pretend I can understand how the heck UPS software on another machine is causing the EVL to flake out....

I went back to the packet captures and indeed there is some traffic from the Plex box to the EVL:

296 14:02:32.531215 192.168.1.50    192.168.1.15    UDP 60  57825 → 51220 Len=7
304 14:02:44.517482 192.168.1.50    192.168.1.15    UDP 60  54620 → 51220 Len=7
315 14:02:56.519227 192.168.1.50    192.168.1.15    UDP 60  55562 → 51220 Len=7
325 14:03:08.515324 192.168.1.50    192.168.1.15    UDP 60  55817 → 51220 Len=7
417 14:05:44.500744 192.168.1.50    192.168.1.15    UDP 60  55066 → 51220 Len=7
418 14:05:44.500744 192.168.1.50    192.168.1.15    UDP 60  55066 → 51220 Len=7
431 14:05:56.506526 192.168.1.50    192.168.1.15    UDP 60  55533 → 51220 Len=7
433 14:06:08.511344 192.168.1.50    192.168.1.15    UDP 60  55788 → 51220 Len=7
464 14:06:20.507072 192.168.1.50    192.168.1.15    UDP 60  63221 → 51220 Len=7

There's no response from the EVL as it's UDP....but it must be enough to kill it.....and this traffic is pervasive as I can find it in every pcap I've checked.

I am assuming here of course that there is a fixed relationship between dropped pings and the poor performance of the EVL...and there is still the oddness of the dumb switch to explain....but perhaps all that did was create a slightly quieter space for the HA <--> EVL comms.

I have now upgraded the NetGuard software from what was a classic standalone Windows app to a Java-based app. The new app doesn't have the same behavior as when running it now doesn't interfere with the ping trace.

Next step is to try and move things back to the main switch.....

I'm still lost for words.....

ufodone commented 2 years ago

Well, that's great to hear! As frustrating as I'm sure it has been for you, it's good that it looks like you have a resolution now.

Looking at the payloads of those 51220 packets, they all seem to just contain the string "getip" so I assume it's some sort of discovery mechanism. I'd be curious if it was sending those packets to other devices on your network or if there was something special about the EVL's IP. E.g. maybe that IP used to be a device the UPS software was interested in? Anyway, probably not something that needs to be answered at this point. :)

ChirpyTurnip commented 2 years ago

It was sending that traffic to everything on the subnet....I suspect it was looking for other UPS-connected devices on the network as there is a feature to shutdown other hosts via a network connection. There was no way to turn that off....

Everything is back on the main switch now....so far so good....who knows...someone else may stumble o this at some point and find they have a similar problem. It certainly never occurred to me that a random process on a random other device on the network could be causing this sort of problem, particularly as the UPS and EVL have nothing to do with each other logically or physically.

All I can say is I'm glad it's over (there's a weekend I will never get back), and thank you SO much for your help!

ufodone commented 2 years ago

I suspect you could probably do something fancy with VLANs to protect the EVL from this in the future but it's probably more trouble than it's worth now that you know what to look for should it occur again.

If the issue doesn't come back after you've soaked it for a while longer, please close out this bug. Cheers!

ChirpyTurnip commented 2 years ago

That's not a bad idea! I already run vLANs so it's not like that will be hard, and then just restrict traffic to HA....wouldn't even need to bother with TCP/UDP ports as just locking it down to a single host will be enough to secure it. :-)

Will close the bug in a day or two. I'm 99.99% we're over it.

On Mon, 21 Feb 2022 at 14:54, ufodone @.***> wrote:

I suspect you could probably do something fancy with VLANs to protect the EVL from this in the future but it's probably more trouble than it's worth now that you know what to look for should it occur again.

If the issue doesn't come back after you've soaked it for a while longer, please close out this bug. Cheers!

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/66627#issuecomment-1046395637, or unsubscribe https://github.com/notifications/unsubscribe-auth/AUIP7ZRRJVTL27NNUF2F2SDU4GLOHANCNFSM5OQNB2PA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>