haywirecoder / homebridge-envisalink-ademco

Homebridge plug-in for Envisalink Ademco module
MIT License
16 stars 6 forks source link

'Session closed unexpectedly. Re-establishing Session" after Homebridge 1.1.3 update #7

Closed ghost closed 4 years ago

ghost commented 4 years ago

Last night I updated Homebridge to 1.1.3 on on restart I get this in the logs every 5 seconds it looks like:


...
[9/5/2020, 10:54:18 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:18 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:23 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:23 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:28 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:28 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:33 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:33 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:38 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:38 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:43 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:43 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:48 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:48 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:54 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:54 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:54:59 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:54:59 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:55:04 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:55:04 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:55:09 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:55:09 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:55:14 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:55:14 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:55:19 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:55:19 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[9/5/2020, 10:55:24 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[9/5/2020, 10:55:24 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
...
ghost commented 4 years ago

The TPI interface reset on its own for some reason and the issue resolved itself. Not sure why.

ghost commented 4 years ago

Turns out not fixed after all. I was able to get it working for a while by either restarting both homebridge and the envisalink together or just waiting about 24 hours or so for the TPI to seemingly reset for a while, but now even that doesn’t work. It’s been days and nothing I try gets past this error now. Envisalink shows a TPI logout and login (I get emails) but the plug-in never syncs back up and just repeats this error every 5 seconds.

haywirecoder commented 4 years ago

Hi,

You are running few version behind, the current version is 1.1.8. There are a few configuration changes you can change including timeout value, enabling or disabling the auto re-connect within the configuration file. This error occurs at the TCP/IP level when your homebridge is loses connection to Envisakit. When this occur I would recommend you login into your homebridge and try doing a ping to your Envisakit module.

ghost commented 4 years ago

I am on 1.1.8 now I reopened the old issue but I will try a few things and report back. I did already try the auto reconnect both on and off and that didn’t seem to help much.

haywirecoder commented 4 years ago

Hmm... NodeJS TCP error "ECONNRESET" usually happens when one end of the TCP connections closes its end due to any protocol-related errors. Remember only one process can connect to Envisakit module at a time. Envisakit terminate this session and another process starts the Envisakit module will reject connects from module.

Few questions:

  1. Are you getting a missing heartbeat error prior? if so what is your heartbeat value?
  2. What is autoreconnect value in your configuration file. A false value would just terminate auto connect and cause a shutdown module upon an TCP error, rather than restart it.
  3. Have you set your Envisalink to a static IP address?
ghost commented 4 years ago

I dont see any messages about a heartbeat, no. It is a static IP, technically a DHCP reservation.

I've tried several different settings, but his is how it stands now:

            "openZoneTimeout": 30,
            "heartbeatInterval": 120,
            "commandTimeOut": 10,
            "autoreconnect": false,

Maybe there is another setting I'm missing? Interesting that it drops at 5 seconds each time, but all the timeouts are higher than that so it does seem to be earlier than any of the timeouts.

ghost commented 4 years ago

It does look like the issue is on my envisalink side... it kills the connection almost immediately if I attempt to telnet to that port.

apple:.homebridge [redacted]$ telnet [redacted] 4025
Trying [redacted]...
Connected to envisalink.[redacted]
Escape character is '^]'.
Connection closed by foreign host.

I'll see what I can track down on that end...

ghost commented 4 years ago

So I noticed my EVL4 module had a firmware update available. I did that and it reconnected after the reboot for a bit but went back to this every 5 seconds issue shortly later... I have verified that there is nothing else on that network using the TPI that may be blocking it so I'm wondering if maybe something about my config is screwy enough to cause it to fail the first time then it can't reconnect because EVL4 thinks the TPI is still "in use"

It did indeed miss a heartbeat which triggered the loop again after looks like 4 minutes after the successful reconnect on the EVL reboot (12:40:58 -> 12:44:59) -- any thoughts on what might cause a heartbeat miss? Ping is OK from that machine.

[10/14/2020, 12:40:58 PM] [Envisalink] Successful TPI session established
HAP Warning: Characteristic 00000066-0000-1000-8000-0026BB765291 not in required or optional characteristics for service 00000049-0000-1000-8000-0026BB765291. Adding anyway.
[10/14/2020, 12:44:59 PM] [Envisalink] Missing Heartbeat: Trying to re-connect session...
[10/14/2020, 12:44:59 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/14/2020, 12:45:04 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/14/2020, 12:45:09 PM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/14/2020, 12:45:09 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/14/2020, 12:45:14 PM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/14/2020, 12:45:14 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/14/2020, 12:45:19 PM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/14/2020, 12:45:19 PM] [Envisalink] Error: connect ECONNRESET 192.168.173.42:4025
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1144:16)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'connect',
  address: '[redacted]',
  port: 4025
}
[10/14/2020, 12:45:24 PM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/14/2020, 12:45:24 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/14/2020, 12:45:29 PM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/14/2020, 12:45:29 PM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:207:27)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
haywirecoder commented 4 years ago

Hi A missing heartbeat indicates that virtual panel (Envisalink) is not providing updates. Based on your setting above that would about 2mins with no communication, thus the module try to re-create the connect since Envisalink module has a habit of dropping connections without any notification.

  1. I will look into why the auto-connect false is not being enforce, it shouldn't try to re-connect base on your configuration.
  2. The max heartbeat set to 120 seconds... I will allow the setting to be higher. Maybe, your panel is not as talkative as mine. So, will set the max to about 10 mins (e.g. 600 seconds).
  3. I will also look at the disconnect logic. Maybe something is left open.

I will post a new envisalink.js sometime this evening. You will need to manually replace that file and let me know if it fixes the issue, will include a little more logging detail so we track whats going on.

ghost commented 4 years ago

Thanks for checking it out! It is really odd how it sort of degraded over time, too. Was fine for a long, then all of a sudden when I'd restart homebridge for code updates it would do this, but rebooting Envisalink fixed it every time for a while. Then, in 24 hours it would fix itself... and now it just never works. Very odd!

Thanks again for the help!

haywirecoder commented 4 years ago

Hi, Upload a new envisalink.js, it contain a fix to autoreconnect option being ignored. However, I added a new option to the module to control the session watcher specifically. A new property call sessionwatch that allow you to disable session watcher feature. In addition increase the heart beat interval max value to 10 mins. You will need to copy envisalink.js and .json file if you want update to the configuration UI. I usually let the code run on my homebridge for a few day prior to packaging and releasing as package update. I did try to trigger the same issue as above, even forcing random disconnect but the module always reconnected.

To disable sessionwatcher: "autoreconnect": true, "sessionwatcher": false,

Or to increase heart beat interval check to 5 mins. "heartbeatInterval": 300, "autoreconnect": true, "sessionwatcher": true,

haywirecoder commented 4 years ago

In addition confirm that - Enable TPI Session Alerts is check on the web console.

ghost commented 4 years ago

So with the new envisalink.js file it acts the same, if I disable the session watcher obviously it stays "connected" -- but it doesnt work. If I try to arm for example, then it shows it's not actually connected (shown below). It seems like something else is going on here on my network at this point and the plugin is most likely working correctly. I'll dig into that angle more... I found some threads about similar issues using Unifi gear (which I am) so I'm wondering if that's what's going on here.

[10/16/2020, 11:13:35 AM] [Envisalink] Arming alarm to Stay (Home).
[10/16/2020, 11:13:35 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/16/2020, 11:13:40 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/16/2020, 11:13:40 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
[10/16/2020, 11:13:45 AM] [Envisalink] Alarm request did not return successful in allocated time. Current alarm status is  READY
[10/16/2020, 11:13:45 AM] [Envisalink] Session closed unexpectedly. Re-establishing Session...
[10/16/2020, 11:13:45 AM] [Envisalink] Error: read ECONNRESET
    at TCP.onStreamRead (internal/stream_base_commons.js:209:20)
 {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}
haywirecoder commented 4 years ago

Unfortunately it does sound like it is a network connection issue with Envisalink module. I am also running Unifi as my backbone of my network - not using the router however...just the switch, NVR and APs. Would love to understand if there are known issues that I may encounter in the future.

I have uploaded a raw debug nodejs script for envisalink located in /Debug folder. I used this in my development of the module. It opens a connect with envisalink module and dump all data that it receives from envisalink module to the screen until control break is issued. Useful to see if you are getting any raw string from envisalink prior to disconnect. This also enable all debug statement in envisalink.js script so you can also see the modules errors.

Copy cid.js, envisalink.js, helper.js, tpi.js and your config.json into same folder as raw-envisalink.js on a system with Nodejs installed and issue nodejs raw-envisalink.js

You can also just create a new config.json file with following entries to keep it simple { "name": "Envisalink-Ademco", "host": "YOUR IP", "port": 4025, "deviceType": "Honeywell Vista", "password": "YOUR MODULE PASSWORD", "pin": "0000", "openZoneTimeout": 30, "heartbeatInterval": 30, "commandTimeOut": 10, "autoreconnect": true, "sessionwatcher": true

}

ghost commented 4 years ago

Finally had time to dig in. I appreciate the debug script, it was helpful! I was able to finally get port mirroring of my EVL4 up and going and was able to find something else on the network communicating with it after all. Turned out to be a long uninstalled instance of homeassistant that came back to life apparently just enough to race to the TPI and lock it out.

Thanks again for the help, I'm all set now so I'll close the issue.