haywirecoder / homebridge-envisalink-ademco

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

No TPI session - and doesn't seem to reconnect #29

Closed dtpanic closed 2 months ago

dtpanic commented 2 years ago

I'm running version 2.0.1.

It will work fine most of the time, but every now and then I notice it is non-responsive in the Home app. When I look at homebridge logs I see the following when I try to arm/disarm:

[Envisalink-Ademco] Envisakit Module: Command not successful, no TPI session established.

I understand that the connection with my Envisalink system may have been dropped. But I also have it set up to try to reconnect every 30 seconds (heartbeatinterval), so I wouldn't expect it to remain disconnected like this.

Any thoughts on how I can troubleshoot and/or assist with a fix? The network connection to my Envisalink system is wireless but pretty stable (~50ms and < 2% dropped packets).

Thanks in advance!

haywirecoder commented 2 years ago

Hi,

Few questions:

  1. Upon startup does the plug indicate heart beat monitoring has started?
  2. Does your log have any messages indicating missing heartbeats? and successful or unsuccessful reconnect?

If these messages are missing then the plug is not attempting to reconnect. Make sure the following items are set "heartbeatInterval": 30, "autoReconnect": true, "sessionWatcher": true,

dtpanic commented 2 years ago

I have confirmed that the settings you listed are correct.

I also confirmed that the plug-in logs that heartbeat monitoring has started when I restart it:

[24/09/2022, 16:19:59] [Envisalink-Ademco] Starting connection to envisalink module at: 192.168.1.57, port: 4025 [24/09/2022, 16:19:59] [Envisalink-Ademco] Successful TPI session established. [24/09/2022, 16:19:59] [Envisalink-Ademco] Checking for disconnected session every: 30 seconds.

I then tried unplugging the Envisalink module and I saw this in the logs:

[24/09/2022, 16:24:29] [Envisalink-Ademco] Missing Heartbeat - Time drift: 34.484 . Trying to re-connect session... [24/09/2022, 16:24:34] [Envisalink-Ademco] Starting connection to envisalink module at: 192.168.1.57, port: 4025

It failed with a connection error but kept trying until I plugged in the Envisalink, and then it re-connected successfully:

[24/09/2022, 16:25:26] [Envisalink-Ademco] Successful TPI session established. [24/09/2022, 16:25:26] [Envisalink-Ademco] Checking for disconnected session every: 30 seconds.

So the heartbeat and reconnection seems to be working perfectly. However, I checked old logs and there were no indications of a 'missing heartbeat' before the "[Envisalink-Ademco] Envisakit Module: Command not successful, no TPI session established" message.

Does the plugin log when a heartbeat is sent successfully? Perhaps in debug mode? I can wait until this happens again, and then check to see that it was performing the heartbeat every 30 seconds.

haywirecoder commented 2 years ago

Hi,

Interesting.. its seem the logic is working as expected. As far as heartbeat its actually works by monitoring the stream from the Envisalink module. The alarm panel is continuously sending messages to Envisalink module, in turn the plug-in is continuous listening and processing the events. If it doesn't see anything for during the heartbeat interval it determine something is wrong. With debug on you will see the time drift of check.

dtpanic commented 2 years ago

I understand. So in my case when I perform a command and it logs this:

[Envisalink-Ademco] Envisakit Module: Command not successful, no TPI session established.

It somehow hasn't noticed that the connection was dropped (i.e. there were no missing heartbeats). I'm guessing this situation is not supposed to happen. Is there anything I can do to help troubleshoot and identify root cause?

I will poke around the source code and see if I can figure it out too.

haywirecoder commented 2 years ago

Correct, it is odd that you're getting this error since the stream should have already timed out and logic to re-connect started. Everything related to connection is in the envisalink.js file. It uses javascript net library for communication. On another note: I did review the code and found a use case where Homekit was not updating quickly due to a missing connection. I am posting the new code in repo, but will not release until I have more time to make sure nothing broke as result of the fix. It does however fix the hang/long wait when you are trying to arm/disarm in HomeKit when TPI is disconnect The updates are changes in Envisalink.js and partitionAccessory.js in accessory file. This don't fix root of your issue however as why you have these random disconnect and auto re-connect doesn't work. Report back if you find anything...

github-actions[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

dtpanic commented 2 years ago

I've been running 2.0.2 for a while and this problem has not re-occurred. Thanks!

haywirecoder commented 2 years ago

Great...

dtpanic commented 7 months ago

This has started happening again. I have all the settings enabled as described here. Periodically, the plugin stops working and I see this log message:

[18/04/2024, 20:48:10] [Envisalink-Ademco] Command not successful. No TPI session establish.

But there is no attempt to re-establish the TPI connection.

If I could make a suggestion (I can also look at the code and see if I can put together a pull request). It seems that if for some reason the session watcher doesn't notice that the connection has been terminated, then the plugin should try to re-establish the TPI connection after it logs this error message.

haywirecoder commented 7 months ago

Hi

The "Command not successful. No TPI session established" comes from when the plug-in tries executing a command. What is the command is being executed? The error is generic. So, I posted a new envisalink.js it extends the message to know if the net connection is destroyed or the login isn't completed. As far as reconnecting during the send command, the easy part is requesting the plug-in to reconnect (if indeed that is an issue) the hard part is the retrying logic for the command and not causing the homekit to become unresponsive due to trying to reconnect and replay of command.

Monitoring code handles issues of this nature, the fact you do not see any message from that piece of code indicates some unique error case is not handled. Let me know to what extent the message returns.

dtpanic commented 7 months ago

Thanks for the additional details and for posting an update to Envisalink.js. I’ve applied that update, and if/when this condition occurs again I’ll let you know what it says.

On Apr 19, 2024, at 12:10 AM, haywirecoder @.***> wrote:

Hi

The "Command not successful. No TPI session establish" comes from when the plug-in tries executing a command. The command is being executed? The error is generic. So, I posted a new envisalink.js it extends the message to know if the net connection is destroyed or the login isn't completed. As far as reconnecting during the send command, the easy part is requesting the plug-in to reconnect (if indeed that is an issue) the hard part is retrying logic for the command and not causing homekit to become unresponsive due to trying to reconnect and replay of command.

Monitoring code handles issues of this nature, the fact you do not see any message from that piece of code indicates some unique error case is not handled. Let me know what extend the message returns.

— Reply to this email directly, view it on GitHub https://github.com/haywirecoder/homebridge-envisalink-ademco/issues/29#issuecomment-2065717351, or unsubscribe https://github.com/notifications/unsubscribe-auth/AZAELIVBLDUHIYPWI7EJFATY6CKMNAVCNFSM6AAAAAAQUWHJZCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANRVG4YTOMZVGE. You are receiving this because you authored the thread.

dtpanic commented 6 months ago

Hi @haywirecoder - this just occurred again, and I was able to grab the additional logging:

Command not successful. TPI connection status: ${actual.destroyed} and login session connected is: ${this.isConnected}.

Not sure if those variables were supposed to be populated?

haywirecoder commented 6 months ago

Hi,

No that shouldn't have been the output :( ... I have uploaded a new version, which will be part of an upcoming release. The new version is better-tuned re-connect logic now syncing with the send command (both are checking if the connection is active, not just a heartbeat). I have also reviewed the error message and tested it, so it should tell you that the stream got dropped (network) or that the object associated with Steam is been unallocated (e.g. undefined). What exactly is the command that is being requested when this appears?

dtpanic commented 6 months ago

Awesome, thanks!

I patched my install with the updated envisalink.js file. I will let you know if I can reproduce the issue again.

To answer your question - the command is always either disarming or arming the system.

On May 7, 2024, at 12:30 AM, haywirecoder @.***> wrote:

Hi,

No that shouldn't have been the output :( ... I have uploaded a new version, which will be deployed as part of an upcoming release. The new version is better-tuned re-connect logic now syncing with the send command. I have also reviewed the error message and tested it, so it should tell you that the stream got dropped (network) or that the object associated with Steam is been unallocated (e.g. undefined). What exactly is the command that is being requested when this appear?

— Reply to this email directly, view it on GitHub https://github.com/haywirecoder/homebridge-envisalink-ademco/issues/29#issuecomment-2097424008, or unsubscribe https://github.com/notifications/unsubscribe-auth/AZAELIQWKSVCSPAFTOFQETDZBBKGJAVCNFSM6AAAAAAQUWHJZCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAOJXGQZDIMBQHA. You are receiving this because you authored the thread.

github-actions[bot] commented 5 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

dtpanic commented 3 months ago

After several months of no issues, the connection stopped working with the following error:

[23/08/2024, 07:02:171 [Envisalink-Ademco] Disarming the alarm system with PIN, [Par tition 1]. [23/08/2024, 07:02:171 [Envisalink-Ademco] Command not successful, connection login session connected is: false and data stream object is defined: true

haywirecoder commented 3 months ago

Hi,

The enhanced error log paid off, knowing now that the connection handler is becoming false. I made the update Envisalink.js. You are welcome to update your installation with this new Envisalink.js file. If I am correct, you will receive the following error message. "EnvisaLink server connect closed due to a transmission error" In about 30 sec, you should see the plug-in attempt to reconnect.

dtpanic commented 3 months ago

Thanks! I copied over the latest envisalink.js, and will let you know if I run into this issue again.

On Aug 24, 2024, at 6:58 PM, haywirecoder @.***> wrote:

Hi,

The enhanced error log paid off, knowing now that the connection handler is becoming false. I made the update Envisalink.js. You are welcome to update your installation with this new Envisalink.js file. If I am correct, you will receive the following error message. "EnvisaLink server connect closed due to a transmission error" In about 30 sec, you should see the plug-in attempt to reconnect.

— Reply to this email directly, view it on GitHub https://github.com/haywirecoder/homebridge-envisalink-ademco/issues/29#issuecomment-2308565701, or unsubscribe https://github.com/notifications/unsubscribe-auth/AZAELIRKBYG7WLWUOZSFRB3ZTEF3FAVCNFSM6AAAAAAQUWHJZCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGMBYGU3DKNZQGE. You are receiving this because you authored the thread.

haywirecoder commented 2 months ago

Publish a new release with these updates. Please re-open if you encounter that same issue.