Error when opening app

[macjeff]

I thought it was just cellular but its wifi also. It seems to be when the app is in the background and I open it up the error is on screen but then in about 5-10 seconds goes away (See screenshot).

I had the issue where the latest Python update crashed my ISY and Michel brought it back. That same day is when I started gett

ing the errors BUT I think there was an app update also so dont know which one.

FYI- I am running iOS 16 beta 3 now (Came out today) And still doing it.

[macjeff]

I noticed when its doing it under the ISY it says CLOSED instead of CONNECTED.
It may be an iOS 16 issue but it started after the big update with python changes and Michel had to rebuild my polisy.

[JavierRefuerzo]

Hi Jeff,

Thanks. It's good to hear that the app/ISY are recovering from the error in less than 10 seconds. Does this only happens when app is in memory? If you swipe the app from recents before opening do you get the same error? It's possible iOS 16 is stopping network before the app closes the connection gracefully which causes an already subscribed (817) when reopening the app.

[macjeff]

I have been testing and it did happen once after a fresh launch. WELL it happened in memory and I did the force quit. (Swipe up) and usually opening again works but this time it was stuck. A few min later tried again and it worked. Today I just tried and worked first time. Its so random.

[JavierRefuerzo]

Thanks, at this point I think there is a low probability this is caused by iOS 16. Are you familiar with ISY logs?

First clear the error log from a browser:
http://ipaddress:port/rest/log/error?reset=true

Recreate the issue.

Get error log from a browser:
http://ipaddress:port/rest/log/error

[macjeff]

One thing FYI. I have had issue since moving to ISY on Polisy where on port 8080 I get Already Subscribed. Michel said its a session eft open. At first I thought it was Homebridge but ruled that out. Then Pg3 but they said it does not. I thought maybe SSH sessions so I purposely used LOGOFF command. Its still doing it and I am thinking maybe its my phone losing internet with UD Mobile in the background.
That could explain because a session times out after a period so the already subscribed i get (only on 8080 not 8443) goes away if I try again in an hour.

But I cleared logs both using URL and inside admin console

When I opened UD Mobile I got the error. All I did is close app (NOT FORCE QUIT) and open back and 5 seconds later it went away.

this is all that is there

Fri 2022/07/15 11:37:48 AM	0	-170001	<s:Envelope><s:Body><u:UDIService xmlns:u="urn:udi-com:service:X_Polisy_Service:1"><control>DOF</control><action></action><flag>65531</flag><node>15 FA 86 1</node></u:UDIService></s:Body></s:Envelope>

Fri 2022/07/15 11:37:49 AM	0	-170001	<s:Envelope><s:Body><u:GetSystemStatus xmlns:u="urn:udi-com:service:X_Polisy_Service:1"></u:GetSystemStatus></s:Body></s:Envelope>

Fri 2022/07/15 11:38:26 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:38:29 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:38:36 AM	0	-170001	<s:Envelope><s:Body><u:Unsubscribe xmlns:u="urn:udicom:service:X_Insteon_Lighting_Service:1"><SID>uuid:107</SID></u:Unsubscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:38:37 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:39:12 AM	0	-170001	<s:Envelope><s:Body><u:GetCurrentSystemStatus xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><SID>uuid:0</SID></u:GetCurrentSystemStatus></s:Body></s:Envelope>

It just happened again a minute later after a force quit so we can rule out idle time

Fri 2022/07/15 11:40:34 AM	0	-170001	<s:Envelope><s:Body><u:Unsubscribe xmlns:u="urn:udicom:service:X_Insteon_Lighting_Service:1"><SID>uuid:108</SID></u:Unsubscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:40:36 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:40:40 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:40:43 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

Fri 2022/07/15 11:40:46 AM	0	-170001	<s:Envelope><s:Body><u:Subscribe xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1"><reportURL>REUSE_SOCKET</reportURL><duration>infinite</duration></u:Subscribe></s:Body></s:Envelope>

**** I noticed a quick message flash by. Looked like redirecting or retrying or something. I will try and record a video of it.
GOT IT!!! attached

RPReplay_Final1657899763.MP4

[JavierRefuerzo]

It appears there is something else requesting connections. Please swipe app from recents, close AC, clear error log, wait a few minutes, request error log. Do this without opening the app so we can see if there is something requesting subscriptions that is not the app.

Note: When pasting the error log add ``` before and after the log so chars are not removed.

[macjeff]

This is the entire log after 20 min

Fri 2022/07/15 12:39:26 PM 0 -170001 <s:Envelope><s:Body><u:GetCurrentSystemStatus xmlns:u="urn:udi-com:service:X_Insteon_Lighting_Service:1">uuid:0</u:GetCurrentSystemStatus></s:Body></s:Envelope>

And that most likely was the app because I cleared log before I closed it.

Just opened the app and 6 more appeared.

[JavierRefuerzo]

These are not necessarily errors, they are subscription attempts, but needed to see if there was a loop. Let's check the subscriptions, in the past we have had clients which held too many subscriptions causing the same 817 error. This appears very similar, although in the past ISY would not recover and all clients would be blocked from new subscriptions which required a reboot to reset all subscriptions. Are you running both PG2 and PG3? Some of the PG2 node servers utilizing PyISY where found to cause the issue (i.e HueEmulator but there may be others) and I'm unsure if it was resolved.

With AC and app closed what is the output of
http://address:port/rest/subscriptions

Now reboot ISY wait a few minutes to startup without opening AC or App and run rest/subscriptions again so we can see if something else is requesting a socket.

[macjeff]

One pg2 left and a LOT of pg3. I think I have 25 pg3 so with the pg2 slot that’s 26 slots.

…

Sent from my iPhone On Jul 15, 2022, at 2:47 PM, Javi ***@***.***> wrote:  These are not necessarily errors, they are subscription attempts, but needed to see if there was a loop. Let's check the subscriptions, in the past we have had clients which held too many subscriptions causing the same 817 error. This appears very similar, although in the past ISY would not recover and all clients would be blocked from new subscriptions which required a reboot to reset all subscriptions. Are you running both PG2 and PG3? Some of the PG2 node servers utilizing PyISY where found to cause the issue (i.e HueEmulator but there may be others) and I'm unsure if it was resolved. With AC and app closed what is the output of http://address:port/rest/subscriptions Now reboot ISY wait a few minutes to startup without opening AC or App and run rest/subscriptions again so we can see if something else is requesting a socket. — Reply to this email directly, view it on GitHub<#65 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AE3OB7S3QSFKWVT4ZKPDZXDVUGW3TANCNFSM53IZQ6RQ>. You are receiving this because you authored the thread.Message ID: ***@***.***>

[macjeff]

This is BEFORE the ISY reboot. Doing Reboot now of ISY and will post in a bit

It disappears when I add comment so its a screen shot now

[macjeff]

this is after reboot

[JavierRefuerzo]

Thanks Jeff.

The first screenshot shows 3 expired subscriptions which were not closed gracefully. Do you get the error in the app now?

The same call (rest/subscriptions) should show 1 isExpired="no" when the app is open with a socket id (sid) not equal to -1,. When the app is closed it should remove the same sid and change back to -1.

I see on the forum that ST-inventory is causing issues for other users. Do you have this NS installed?

[macjeff]

I do use ST Inventory but on the forum all I see is that its crashing someones entire ISY. Thats not my issue

But as I said before on a regular basis I get already subscribed errors on port 8080 when connecting to IOP. so this could be it. I disabled it in Pg3 for now as its just an Info nodeserver. I dont really need it.

I will post in the forum about my issue but if you could point me to the topic so I dont start a second one and get yelled at (LOL) let me know.

Keep this open for now and I will let you know if I have the issue with ST Inventory off.

[macjeff]

So I turned off ST Inventory for the weekend and zero errors. I saw a post saying to increase the short poll to 1 hour and long poll to 1 day so I did. Now its back on.

Right away the errors are back.

But I still dont see a post about ST Inventory not disconnecting gracefully. Can you send me a link? meanwhile I am creating my own!!!

[macjeff]

started this topic

https://forum.universal-devices.com/topic/37429-non-graceful-disconnect-causing-issues-with-ud-mobile-connection-error-and-isy-admin-already-subscribed/

Please keep this one open for now

[JavierRefuerzo]

Hi Jeff,

Great. Thanks for isolating the issue.

I have not had time to look into ST-Inventory so it may be a different issue, although the issue appears similar to issues with PyISY. PyISY is a library used by some node servers to connect with ISY.

[macjeff]

maybe you can chime in on my forum post. Have a feeling the developer is going want more info

[JavierRefuerzo]

I've been following a few threads and tickets with similar issues. I think this may be related to a client request timeout for 994i while data transmission is in progress. While the 994i recovers most of the time within a minute, if there is a loop of large requests and timeouts this could cause abnormal behavior/crash, similar to a denial of service. The same issue may exist on Polisy but the system recovers in about 10 seconds and may drop request for graceful socket disconnect causing 817 (Already subscribed). I have asked simplex to check the timeout settings in ST-Inventory

[macjeff]

It happened today with ST turned off about an hour ago but you’re right. Tried again about 10 seconds later and it’s fine. With ISY Admin (JAVA) I get ALREADY SUBCRIBED. It can take a few min for that to recover but if I use 8443 instead of 8080 I am fine. Usually I do that because I am impatient!! Jeff On Jul 20, 2022, at 11:35 AM, Javi ***@***.***> wrote: I've been following a few threads and tickets with similar issues. I think this may be related to a client request timeout for 994i while data transmission is in progress. While the 994i recovers most of the time within a minute, if there is a loop of large requests and timeouts this could cause abnormal behavior/crash, similar to a denial of service. The same issue may exist on Polisy but the system recovers in about 10 seconds and may drop request for graceful socket disconnect causing 817 (Already subscribed). I have asked simplex to check the timeout settings in ST-Inventory — Reply to this email directly, view it on GitHub<#65 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AE3OB7QVGALJ7WREGRAYFF3VVAME7ANCNFSM53IZQ6RQ>. You are receiving this because you authored the thread.Message ID: ***@***.***>

[macjeff]

All of a sudden (And I was on vacation until yesterday and not touched the ISY) it started doing it today again. I did notice an update ran. Whats different this time is if I turn off wifi and run it as if its not local it works fine but locally it gives me same error. When I turn wifi back on after connecting locally it works until I quit the app and then I get the error again. And it does not recover anymore. Going to try rebooting the ISY. Tried rebooting phone with no luck.

** even though there is an error everything seems to work fine (except error at bottom- see image). I dont think before it would all work fine.

Also I turned off the ST Inventory and that did not fix this time

[macjeff]

rebooting the ISY seems to have solved the issue but this is annoying and I hope we can narrow down a fix (assuming its not the app)

[JavierRefuerzo]

If it happens again we can look at the logs. If an firmware update ran it's possible it did not start correctly after installation.

If everything was working, but the error was showing it may simply be the app failed to remove the error on reconnect (UI issue). The portal subscription does not use the normal subscription queue, this is the reason it works with portal event when the normal queue appears to be full. I still suspect there is another client subscribing or dropping connections.

[macjeff]

I did not change anything on ISY. Had not even logged in for the 10 days I was gone. And the entire 10 days I used the app just fine. It all started when I ran the test flight update yesterday. Then I started getting errors. Could this all be TEST Flight not gracefully disconnecting when it updates? Jeff On Aug 15, 2022, at 10:17 AM, Javi ***@***.***> wrote: If it happens again we can look at the logs. If an firmware update ran it's possible it did not start correctly after installation. If everything was working, but the error was showing it may simply be the app failed to remove the error on reconnect (UI issue). The portal subscription does not use the normal subscription queue, this is the reason it works with portal event when the normal queue appears to be full. I still suspect there is another client subscribing or dropping connections. — Reply to this email directly, view it on GitHub<#65 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AE3OB7VA44SRCJSIPCRQUU3VZJGORANCNFSM53IZQ6RQ>. You are receiving this because you authored the thread.Message ID: ***@***.***>

[JavierRefuerzo]

Hi Jeff, It is likely there is another client trying to connect to the ISY or dropping connections. It does not appear to be related to the app as all users would have the issue. The app is one client and will attempt to close gracefully, but will show an error if the subscription queue is already full or inoperable which appears to be the case. If a node server, PG3, PG2, or some other client causes the issue where the ISY could not recover then nothing will happen until ISY reboot. So disabling after the fact may have no effect. If disabled and the issue does not present itself until enabled again there is a good chance the disabled client is causing the issue.

Somethings can be fixed in firmware, however if there is a client behaving poorly the client will need to be fixed or access disallowed.

When this happens I will need logs and instructions followed to help isolate the issue. If it's firmware Michel or Chris can take a look, if it's PG3 Bob can take a look, if it's PG2 it may need to be stopped as it is now deprecated, if it's a node server or a client not created by UD then the author will need to fix.