Jump to content

Already Subscribed Error - Check the log

Adam Ant

By Adam Ant
in ISY994

Go to solution Solved by Adam Ant,

Recommended Posts

  • Solution
Adam Ant Experienced

Adam Ant

Posted
  • Solution
Posted

This is really meant to possibly help others - I recently spent several weeks trying to chase down an "Already Subscribed" error when I was trying to login to my ISY.   I also was having sporadic MobiLinc issues with connect timeouts etc.  I had recently added Home Assistant and Polisy so I was thinking it might be related to crossing a threshold of the 10 connections allowed into the ISY..   It turns out it was completely unrelated!   In checking the logs I discovered that I was getting a bunch of "[FileOpen    ] Open failed for [/CONF..." errors.  My system was generally working ok with only an occasional glitch.  I'm guessing the file read issues were causing connections to become phantom thus using up all the connections.   Regardless, I reseated the SD card and all has been fine since!  I am going to replace the card in case it is going bad.  So Lesson learned: even if you think it is unrelated, always check the logs for errors.. may save yourself allot of trouble!  Hope this helps someone!

  • Like 1
  • Thanks 2
MrBill Advanced

MrBill

Posted
Posted

The "Already subscribed" bug is indeed a tough one to solve... for better than 6 months probably I blamed Mobilinc because it seemed to only show its ugly head AFTER mobilinc had been open. 

I never did track down exactly what caused it, however unrelated to that bug I attacked errors in the error log... I had pages and pages daily... I drove @Michel Kohanim nuts with a ticket... he kept telling me not to worry about this or that and I kept saying but it's an error log and I want to clean these up-- we literally drove each other crazy and we both got mad at each other.  Eventually I got it down to where the error log only had about a half dozen entries of random warnings or informational entries per day....  Oddly after that, the "Already Subscribed" bug went away. 

I've thought about creating a very simple nodeserver to monitor the number of lines in the error log, just so that I can create a program that sends a notification to review the error log if there is a sudden growth. 

  • Like 1
Adam Ant Experienced

Adam Ant

Posted
  • Author
Posted
1 hour ago, MrBill said:

The "Already subscribed" bug is indeed a tough one to solve... for better than 6 months probably I blamed Mobilinc because it seemed to only show its ugly head AFTER mobilinc had been open. 

I never did track down exactly what caused it, however unrelated to that bug I attacked errors in the error log... I had pages and pages daily... I drove @Michel Kohanim nuts with a ticket... he kept telling me not to worry about this or that and I kept saying but it's an error log and I want to clean these up-- we literally drove each other crazy and we both got mad at each other.  Eventually I got it down to where the error log only had about a half dozen entries of random warnings or informational entries per day....  Oddly after that, the "Already Subscribed" bug went away. 

I've thought about creating a very simple nodeserver to monitor the number of lines in the error log, just so that I can create a program that sends a notification to review the error log if there is a sudden growth. 

I would be interested in  that node server! :)  Meanwhile, I still have other errors in my log.  Maybe I should use this as a bonding opportunity with @Michel Kohanim as well!  ;-)

  • Haha 1
Javi Advanced

Javi

Posted
Posted

Are any of you using software which has the PyISY library? I believe the Home Assistant Plugin and Hue emulator use this library.

I have seen reports that this library was causing issues with subscriptions. I took a look last week and the unsubscribe call was incorrect, so it is possible that this library has never closed a subscription correctly. I put in a pull request, but this may not be the root cause of the issue.  If anybody encounters this issue please first try disconnecting any services which use PyISY to isolate the issue. Reboot may be required if there was a subscription loop without closing gracefully for a long duration of time.

Note that we are still waiting for a pull so the user which isolated PyISY as the cause can see if fixing the unsubscribe function fixed the errors.

MrBill Advanced

MrBill

Posted
Posted
15 minutes ago, Javi said:

Are any of you using software which has the PyISY library? I believe the Home Assistant Plugin and Hue emulator use this library.

I use Home Assistant and I believe you are correct that it uses PyISY... that said... I have no problem... HA works perfectly even when its rebooted which should close the subscription. 

(I may or may not have a method to get the PR some attention.... I'll try and see what happens...)

Javi Advanced

Javi

Posted
Posted

Thanks @MrBill,

A reboot would not close the subscription gracefully. If there are plenty of other subscription slots available then nobody would notice and eventually the ISY will terminate the subscription if it does not get an ACK.   The problem would arise if the library loses connection or misses a heartbeat, at this point it should send unsubscribe with the subscription ID on another thread. If it does not unsubscribe and somehow gets in a loop of subscriptions without unsubscribing the subscription queue may fill causing already subscribed error. Our app was guilty of this in the early days, and days of debugging this single issue is memorable. 

I don't use anything with this library so I'm unsure if it is unsubscribing correctly when it loses a connection/heartbeat. The unsubscribe function is incorrect so even if the library is calling unsubscribe it is not happening.  

  • Like 1
shbatm Advanced

shbatm

Posted
Posted
6 hours ago, Javi said:

I have seen reports that this library was causing issues with subscriptions. I took a look last week and the unsubscribe call was incorrect, so it is possible that this library has never closed a subscription correctly.

Versions v2.1.2 and v3.0.1 have been released with the corrected unsubscribe code. 

@Javi would you mind also checking the reconnect strings (same file further down) to make sure those are correct? 

  • Like 2
Javi Advanced

Javi

Posted
Posted

Hi @shbatm,

Thank you.  Reconnect looks correct, although I do not use reconnect as mobile disconnects are mostly due to poor network conditions.  I find it easier to unsubscribe when encountering network issues  in case the device loses network soon after, this way no subscriptions are left hanging.  

@Jimbo , I have found that a good test for subscription closing is to set your heartbeat value to a low number, such as 10-15 sec.  This will force a reconnect loop.  Being that ISY is less powerful than Polisy, ISY may eventually throw an error but should recover quickly and allow subscriptions again in the next loop iteration. The reconnect loop should have a short delay. I have found that 3 second works well as a stress test and only throws the occasional error, shorter delay throws many errors, longer delay rarely throws an error. If ISY does not recover quickly after an error is thrown, it is very possible the program needs to unsubscribe and is creating too many new subscriptions without closing existing subscriptions.

  • Like 3
Jimbo.Automates Advanced

Jimbo.Automates

Posted
Posted

Thanks @Javi I just got the already subscribed error just now, and my HueEmulator log has a lot of recoonects...

  

[admin@polisy /var/polyglot/nodeservers/HueEmulator]$ grep pyisy logs/debug.log | grep reconnect
2021-12-23 09:21:50,288 Thread-8646 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 09:21:50,292 Thread-8646 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 09:32:08,831 Thread-8769 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 09:32:08,835 Thread-8769 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 09:48:57,448 Thread-8968 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 09:48:57,454 Thread-8968 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 09:54:12,147 Thread-9032 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 09:54:12,152 Thread-9032 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:04:58,254 Thread-9162 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:04:58,258 Thread-9162 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:05:04,788 Thread-9166 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:05:04,791 Thread-9166 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:05:15,447 Thread-9170 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:05:15,450 Thread-9170 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:05:15,465 Thread-9171 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 10:06:15,482 Thread-9184 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:06:15,486 Thread-9184 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:06:22,623 Thread-9186 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:06:22,626 Thread-9186 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:06:22,641 Thread-9187 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 10:07:22,653 Thread-9200 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:07:22,658 Thread-9200 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 10:07:23,226 Thread-9201 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 10:08:23,243 Thread-9214 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 10:08:23,246 Thread-9214 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 11:03:55,059 Thread-9871 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 11:03:55,064 Thread-9871 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 11:11:33,228 Thread-9963 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 11:11:33,232 Thread-9963 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 11:51:14,621 Thread-10431 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 11:51:14,625 Thread-10431 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 11:57:08,759 Thread-10503 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 11:57:08,763 Thread-10503 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:01:29,966 Thread-10556 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:01:29,975 Thread-10556 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:09:05,041 Thread-10647 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:09:05,045 Thread-10647 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:25:29,338 Thread-10842 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:25:29,342 Thread-10842 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:35:07,101 Thread-10958 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:35:07,105 Thread-10958 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:41:46,715 Thread-11036 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:41:46,719 Thread-11036 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:50:44,105 Thread-11143 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:50:44,109 Thread-11143 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 12:55:56,757 Thread-11207 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 12:55:56,761 Thread-11207 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:04:52,492 Thread-11312 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:04:52,497 Thread-11312 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:05:03,050 Thread-11316 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:05:03,053 Thread-11316 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:05:03,068 Thread-11317 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 13:06:03,075 Thread-11330 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:06:03,080 Thread-11330 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:06:09,447 Thread-11333 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:06:09,450 Thread-11333 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:06:15,572 Thread-11337 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:06:15,575 Thread-11337 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:06:15,590 Thread-11338 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 13:07:15,601 Thread-11350 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:07:15,605 Thread-11350 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:07:15,620 Thread-11351 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 13:08:15,637 Thread-11364 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:08:15,641 Thread-11364 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:13:25,364 Thread-11427 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:13:25,368 Thread-11427 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:25:53,324 Thread-11575 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:25:53,328 Thread-11575 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 13:34:05,254 Thread-11674 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 13:34:05,258 Thread-11674 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:04:53,843 Thread-12040 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:04:53,847 Thread-12040 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:27:46,237 Thread-12311 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:27:46,241 Thread-12311 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:27:52,583 Thread-12314 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:27:52,586 Thread-12314 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:27:52,616 Thread-12315 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 14:28:52,619 Thread-12328 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:28:52,624 Thread-12328 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:28:58,254 Thread-12329 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 14:29:58,276 Thread-12343 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:29:58,280 Thread-12343 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:29:58,295 Thread-12344 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 14:30:58,300 Thread-12356 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:30:58,304 Thread-12356 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-12-23 14:30:58,319 Thread-12357 pyisy.events       ERROR    events:watch: PyISY reached maximum connections, delaying reconnect attempt by 60 seconds.
2021-12-23 14:31:58,329 Thread-12370 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-12-23 14:31:58,334 Thread-12370 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
[

 

Javi Advanced

Javi

Posted
Posted

Hi @Jimbo,

Can you check the ISY error log to see if a new subscription ID is created during each "PyISY reconnected to the event stream." log event?  Also looking for unsubscribe events.

  • Like 1
Jimbo.Automates Advanced

Jimbo.Automates

Posted
Posted

I don't think the connections are getting closed.  I open AC and then when I come back after a few minutes it forces me to log in again, then says "Maximum Subscribers Reached" or something like that...  Then I try to bring it back up again and it says already subscribed.  Will reboot :(

 

inovermyhead Member

inovermyhead

Posted
Posted

Another subscription problem, possibly related:  My iPhone (iOS14.7.1) is not/will not connect to the Portal (UD Mobile 0.6.1):  When I open the app I get two error notifications "System: Valley Lane (the name of my system) Error, then "Could not get get Portal credentials.  Portal is not set".   When I go to Settings/ ISY Portal Accounts and click on the account there and then "continue", I get "Starting subscription", then again quickly  "Could not get get Portal credentials.  Portal is not set".  I do have a Portal subscription, recently renewed - and UD Mobile and the Portal connection are working fine on my iPad (iOS14.8.1) with no error messages .  On the account page (on the iPhone) and clicking "login", I get the circular icon, then eventually "ERROR Authorization Tokens are Null"   Clearly something amiss with my Portal account settings on the iPhone but how do I fix this?  Other than this hiccup, UD Mobile has been flawless and getting better with each update.  Thanks,  John

Javi Advanced

Javi

Posted
Posted

Hi @Jimbo,

I'll take a look.

@inovermyhead,

This appears to be unrelated to this thread. UD Mobile lost login creds somehow, it should have prompted for login, but a few of these classes were updated recently so there may be an issue.   Logout of all portal accounts in the app, then login. After login then go to Systems and for each ISY reestablish the portal connection as it was removed when logged out.

 

 

 

  • Like 2
Javi Advanced

Javi

Posted
Posted
15 minutes ago, inovermyhead said:

@javi. Sorry, I did not mean to hijack this thread.  I will start a new one.  Unfortunately, your instructions did not resolve the problem….

Thanks

Guest
This topic is now closed to further replies.
Go to topic listing
×
×
  • Create New...