Random Reconnect Notices in UD Mobile

[mbking]

Since moving to PG3x both in Polisy and eisy, I get random reconnect notices from all my node servers at the same time. I looked at one of the node server logs and there were no indications that anything happened at that time to cause the reconnect notice. Happens maybe once a day. Interval seems random. Since there is nothing in the log, maybe this is a bug in the logic that triggers the notices?

[DennisC]

2 hours ago, mbking said:

Since moving to PG3x both in Polisy and eisy, I get random reconnect notices from all my node servers at the same time. I looked at one of the node server logs and there were no indications that anything happened at that time to cause the reconnect notice. Happens maybe once a day. Interval seems random. Since there is nothing in the log, maybe this is a bug in the logic that triggers the notices?

Check the PG3x Polyglot log. Sounds like either PG3x is crashing or you are dropping the network connection.

Edited May 28, 2023 by DennisC
Spelling

[Geddy]

@mbking Which device is this happening on? Are you running both devices and having the issues at the same time? Or are you only running one device and this has been an ongoing issue that you're asking about?

Not sure if it would be an indication in your case, but see two replies from @bpwwer in another thread talking about this happening to others.

Reply 1 - https://forum.universal-devices.com/topic/41247-support-thread-for-pg3x-v3127-may-22-2023/?do=findComment&comment=366754

Reply 2 - https://forum.universal-devices.com/topic/41247-support-thread-for-pg3x-v3127-may-22-2023/?do=findComment&comment=366867

Probably the best thing to do is the next time this happens would be to pull a log package and open a support ticket and include the log package. 

It might be valuable to look at two different logs:

1 being just the standard log when you see this happen (you'll need to catch it on the same day that you get the notifications)

2 change the log type to "debug" then restart the node server(s) you are having issues with. Then restart Polyglot and allow things to settle in the log (maybe 2-5 minutes) then download that log package (maybe add the word DEBUG in the file name to indicate it as different and possibly more information).   I think Bob made a change that the log will revert back to info after a period of time, but to be safe make sure you change the log type back to "Info" so it doesn't keep flooding all the debug info into the log file.

 

[mbking]

16 hours ago, Geddy said:

@mbking Which device is this happening on? Are you running both devices and having the issues at the same time? Or are you only running one device and this has been an ongoing issue that you're asking about?

Not sure if it would be an indication in your case, but see two replies from @bpwwer in another thread talking about this happening to others.

Reply 1 - https://forum.universal-devices.com/topic/41247-support-thread-for-pg3x-v3127-may-22-2023/?do=findComment&comment=366754

Reply 2 - https://forum.universal-devices.com/topic/41247-support-thread-for-pg3x-v3127-may-22-2023/?do=findComment&comment=366867

Probably the best thing to do is the next time this happens would be to pull a log package and open a support ticket and include the log package. 

It might be valuable to look at two different logs:

1 being just the standard log when you see this happen (you'll need to catch it on the same day that you get the notifications)

2 change the log type to "debug" then restart the node server(s) you are having issues with. Then restart Polyglot and allow things to settle in the log (maybe 2-5 minutes) then download that log package (maybe add the word DEBUG in the file name to indicate it as different and possibly more information).   I think Bob made a change that the log will revert back to info after a period of time, but to be safe make sure you change the log type back to "Info" so it doesn't keep flooding all the debug info into the log file.

 

@Geddy, currently, I'm only running eisy.  This morning, I received connect notifications from all 5 node servers.  They came in all at once and all have the same time stamp.  I looked at the log for 2 of the node servers and found nothing abnormal around the time of the notifications.  This same thing happened yesterday at exactly the same time, 7:01 am.  This makes me think this is a bug in the notification logic and not an issue with the node servers.  But I'm no expert on the details, so I was going to send @bpwwer the log packages for 2 of the node servers to see if they shed any light on this issue.  Should I send these packages to Bob directly or submit a ticket with the packages attached?  Not sure of the best process here.

[DennisC]

2 hours ago, mbking said:

@Geddy, currently, I'm only running eisy.  This morning, I received connect notifications from all 5 node servers.  They came in all at once and all have the same time stamp.  I looked at the log for 2 of the node servers and found nothing abnormal around the time of the notifications.  This same thing happened yesterday at exactly the same time, 7:01 am.  This makes me think this is a bug in the notification logic and not an issue with the node servers.  But I'm no expert on the details, so I was going to send @bpwwer the log packages for 2 of the node servers to see if they shed any light on this issue.  Should I send these packages to Bob directly or submit a ticket with the packages attached?  Not sure of the best process here.

You can do both, but I would suggest also checking the PG3 log, not just the node server log.

[Geddy]

3 hours ago, mbking said:

But I'm no expert on the details, so I was going to send @bpwwer the log packages for 2 of the node servers to see if they shed any light on this issue.  Should I send these packages to Bob directly or submit a ticket with the packages attached?  Not sure of the best process here.

I prefer to suggest people start a ticket so all of UDI can be aware of any issues going on. Certainly @bpwwer has offered to review logs for others for specific issue. 

However, since this covers node servers, UD Mobile, and ISY Portal it's best to start a ticket so the issue can be reviewed by everybody and see how their part plays into this. Something like this impacts the entire process so best to have everything worked out eventually. 

 

 

1 hour ago, DennisC said:

I would suggest also checking the PG3 log

@mbking I agree with @DennisC and that's what I implied above. Sorry...looking back it wasn't clear. My meaning of "standard log" is the PG3x log package. If you have that in debug mode and then manually restart the node servers that had issues it might shed some insight as to what's happening. 

While the specific node server logs are also important because this is creating a notification through the Portal to UD Mobile it's more likely to be something PG3x related. 

 

[bpwwer]

If it is only one of many node servers then it is likely something happening with the node server.  Node server will attempt to re-connect to PG3 automatically if the connection drops so you may not notice anything wrong, but this will now trigger notifications to UDMobile.  In this case, you should see a "failed" notification followed by a 'connected" notification.

If you are seeing notifications for all node servers at the same time, it is likely PG3 that has crashed.  PG3 will automatically restart so again, you may not be seeing any other indication of a problem but when PG3 crashes, it will attempt to stop all node servers before restarting and both the stopping and restarting of the node servers will trigger the notifications. In this case you should see "disconnected" notifications followed by "connected" notifications.

In either case, this is an indication that something is wrong.  Node servers shouldn't randomly disconnect and PG3 shouldn't randomly crash.

If you just don't care because things seem to be working fine, you can disable the notifications by going to the System -> Notifications page and disable PG3 notifications.

 

[mbking]

5 hours ago, bpwwer said:

If it is only one of many node servers then it is likely something happening with the node server.  Node server will attempt to re-connect to PG3 automatically if the connection drops so you may not notice anything wrong, but this will now trigger notifications to UDMobile.  In this case, you should see a "failed" notification followed by a 'connected" notification.

If you are seeing notifications for all node servers at the same time, it is likely PG3 that has crashed.  PG3 will automatically restart so again, you may not be seeing any other indication of a problem but when PG3 crashes, it will attempt to stop all node servers before restarting and both the stopping and restarting of the node servers will trigger the notifications. In this case you should see "disconnected" notifications followed by "connected" notifications.

In either case, this is an indication that something is wrong.  Node servers shouldn't randomly disconnect and PG3 shouldn't randomly crash.

If you just don't care because things seem to be working fine, you can disable the notifications by going to the System -> Notifications page and disable PG3 notifications.

 

@bpwwer,

This is an excerpt from the PG3 log file at the time the notifications came through this morning:

5/29/2023, 07:00:59 [pg3] info: Verifying node servers are installed on IoX correctly
5/29/2023, 07:00:59 [pg3] info: IoX entry for ELK::2 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for AmbientWeather::3 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for HueEmulator::4 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for RainMachine::5 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for VenstarCT::6 OK
5/29/2023, 07:01:01 [pg3] info: MQTT attempting reconnection to broker...
5/29/2023, 07:01:01 [pg3] info: Pushing notification {"title":"AmbientWeather (3): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"VenstarCT (6): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"RainMachine (5): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"ELK (2): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"HueEmulator (4): Connected","body":"from PG3"} to UD Mobile
 

At 3:01pm this afternoon, exactly 8 hours later, I got all 5 notifications again.  I'll be watching tonight at 11:01pm to see if it happens at an 8 hour interval again .  I definitely want to keep the notifications on.  This one isn't a show stopper, but it would be nice to get it resolved.  I can PM you the whole log package if you like.  Let me know.

Update: At 11:01pm, I got the same 5 notifications and the log messages are the as above.  The difference was the location of the MQTT reconnection message which at 11:01pm, came before Verifying node servers message.  There does appear to be a pattern.

Mark

Edited May 30, 2023 by mbking

[bpwwer]

16 hours ago, mbking said:

@bpwwer,

This is an excerpt from the PG3 log file at the time the notifications came through this morning:

5/29/2023, 07:00:59 [pg3] info: Verifying node servers are installed on IoX correctly
5/29/2023, 07:00:59 [pg3] info: IoX entry for ELK::2 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for AmbientWeather::3 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for HueEmulator::4 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for RainMachine::5 OK
5/29/2023, 07:00:59 [pg3] info: IoX entry for VenstarCT::6 OK
5/29/2023, 07:01:01 [pg3] info: MQTT attempting reconnection to broker...
5/29/2023, 07:01:01 [pg3] info: Pushing notification {"title":"AmbientWeather (3): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"VenstarCT (6): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"RainMachine (5): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"ELK (2): Connected","body":"from PG3"} to UD Mobile
5/29/2023, 07:01:02 [pg3] info: Pushing notification {"title":"HueEmulator (4): Connected","body":"from PG3"} to UD Mobile
 

At 3:01pm this afternoon, exactly 8 hours later, I got all 5 notifications again.  I'll be watching tonight at 11:01pm to see if it happens at an 8 hour interval again .  I definitely want to keep the notifications on.  This one isn't a show stopper, but it would be nice to get it resolved.  I can PM you the whole log package if you like.  Let me know.

Update: At 11:01pm, I got the same 5 notifications and the log messages are the as above.  The difference was the location of the MQTT reconnection message which at 11:01pm, came before Verifying node servers message.  There does appear to be a pattern.

Mark

Thanks for the details.  That really does help.  

The node servers are verified every 5 minutes so that's probably not related, just that it is what you'll see in the log when PG3 is mostly idle.   

But the reconnecting to MQTT broker is related.  That's saying that the network connection between the MQTT broker and PG3 dropped for some reason and it had to reconnect.  Most likely , that also means that the network connection between each node server and the MQTT broker also dropped and it's each node server's connection dropping and reconnecting that is causing the notifications.

Since the MQTT broker is a separate system service communicating with node servers and PG3 over the network, can you think of anything on your network that would be causing network disruptions on a 8 hour frequency?

[mbking]

6 hours ago, bpwwer said:

Thanks for the details.  That really does help.  

The node servers are verified every 5 minutes so that's probably not related, just that it is what you'll see in the log when PG3 is mostly idle.   

But the reconnecting to MQTT broker is related.  That's saying that the network connection between the MQTT broker and PG3 dropped for some reason and it had to reconnect.  Most likely , that also means that the network connection between each node server and the MQTT broker also dropped and it's each node server's connection dropping and reconnecting that is causing the notifications.

Since the MQTT broker is a separate system service communicating with node servers and PG3 over the network, can you think of anything on your network that would be causing network disruptions on a 8 hour frequency?

I've gone through the systems I have online and can't find anything that might disrupt the network, but I do have a UDM-Pro connected to my existing network at the moment to prepare it to be my main router and it monitors its connection to the network.  I'm not showing any loss of network connection during the time of the MQTT issues.

@bpwwer, I'm updating this response.  I did find something that happens every 8 hours; PG3 looks for changes in the node servers.  The reconnect notices come right after that checking for updates.  Yesterday I had reconnect notices at 7:01, 15:01, and 23:01.  In two of those events, the following error occured in that checking for changes event:

5/29/2023, 23:00:56 [pg3] info: Query store database https://pg3betastore.isy.io/v1/list
5/29/2023, 23:00:56 [pg3] error: MQTTC: Error: write ECONNRESET
5/29/2023, 23:00:56 [pg3] error: MQTT received error: Error: write ECONNRESET
 

Interesting note: I received the connect notifications at 7:01, but not at 15:01 as I expected, so it doesn't happen every time.  I'm going to PM you the log package from yesterday so you see the full picture.

Edited May 30, 2023 by mbking