Frequent reflector connection errors

Posted on
Fri Mar 13, 2020 7:25 am
welchgregusa offline
Posts: 101
Joined: May 29, 2013
Location: Orlando, FL

Re: Frequent reflector connection errors

I dropped the log entries into Excel and there is clearly a pattern.

reflector_jpeg.jpg
reflector_jpeg.jpg (322.73 KiB) Viewed 4234 times


I could post the Excel sheet, etc. but it's basically the same pattern over 24 hours yesterday.

I looked in the machine's system log to see what else was happening, and here is an example:

Mar 13 08:10:39 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 08:10:39 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 08:11:23 home IndigoServer[59884]: Error "MUD, Keypad" off (scene 45 cleanup); send failed (no acknowledgment)
Mar 13 08:13:42 home com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.B8EE0159-AA6F-495C-BB87-DF90F896B38D[66937]): Service did not exit 5 seconds after SIGTERM. Sending SIGKILL.
Mar 13 08:21:04 home syslogd[55]: ASL Sender Statistics
Mar 13 08:21:05 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 08:21:05 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 08:28:49 home com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.7A283C03-DA9E-43E0-A7CE-B1732B7AD035[67691]): Service did not exit 5 seconds after SIGTERM. Sending SIGKILL.
Mar 13 08:31:30 home syslogd[55]: ASL Sender Statistics
Mar 13 08:31:30 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 08:31:30 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 08:41:38 home timed[102]: settimeofday({0x5e6b7f82,0x967fa}) == 0
Mar 13 08:41:38 home syslogd[55]: ASL Sender Statistics
Mar 13 08:41:57 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 08:41:57 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 08:43:51 home com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.C6ABF51E-07E9-44A7-ADBF-172435639FFB[68430]): Service did not exit 5 seconds after SIGTERM. Sending SIGKILL.
Mar 13 08:51:59 home syslogd[55]: ASL Sender Statistics
Mar 13 08:52:23 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 08:52:23 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 08:58:54 home com.apple.xpc.launchd[1] (com.apple.WebKit.WebContent.D6B9A830-C6E6-49DA-B212-4A2883655094[69144]): Service exited with abnormal code: 1
Mar 13 08:58:59 home com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.37FF0E5B-D2A4-40AF-93E1-B26C293C8921[69145]): Service did not exit 5 seconds after SIGTERM. Sending SIGKILL.
Mar 13 09:02:48 home syslogd[55]: ASL Sender Statistics
Mar 13 09:02:49 home IndigoServer[59884]: Error reflector connection test failed: Reflector connection is currently down.
Mar 13 09:02:49 home IndigoServer[59884]: Error reflector reconnection scheduled in 5 seconds
Mar 13 09:07:53 home kcm[69575]: DEPRECATED USE in libdispatch client: Setting timer interval to 0 requests a 1ns timer, did you mean FOREVER (a one-shot timer)?; set a breakpoint on _dispatch_bug_deprecated to debug


I don't know if the "Service did not exit 5 seconds after SIGTERM" events are relevant, but perhaps, as the reflector reconnections are being scheduled (somehow) for 5 seconds.

Posted on
Fri Mar 13, 2020 6:28 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

matt (support) wrote:
A couple of thoughts. First is it exactly 2 hours consistently? What is the variance? Also open a browser window on your Indigo Server Mac and point it to the main (home) page of your reflector (so use your reflector URL and not your Mac IP address) then select a device folder and leave that window open and running. The browser will make a request to your Indigo Server over the reflector (round tripping from your Mac -> reflector server -> back to Indigo no your Mac) every couple of seconds to check for device state updates. I'm curious if that helps to keep the connection alive or not.

It appears that leaving the browser window open with a device folder helped considerably. The error happened only once in an 11 hour period.

I also update the MBP from 10.14.4 to 10.14.6 and that didn't change anything.

--Dave

Posted on
Sat Mar 14, 2020 9:54 am
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

DVDDave wrote:
It appears that leaving the browser window open with a device folder helped considerably. The error happened only once in an 11 hour period.

I also update the MBP from 10.14.4 to 10.14.6 and that didn't change anything.

Much to my surprise, I'm no longer getting the reflector errors! No browser window open and I had verified updating the OS didn't help.

The only other thing that changed on my side was that I disabled the weather location part of the Cynical Weather plugin that wasn't working and switched to Fantastic Weather for location dependent current conditions and forecasts.. This error started 2 or 3 weeks ago and had been reported to Perry the Cynic. It looks like this when the plugin is reloaded:
Code: Select all
Cynical Weather Location unavailable: [Errno 54] Connection reset by peer
I didn't think it was related since the reflector errors started about a month earlier but now I'm not sure. Did you guys make any changes to the reflector yesterday on your end?

Thanks.

--Dave

Posted on
Sat Mar 14, 2020 3:34 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

DVDDave wrote:
Much to my surprise, I'm no longer getting the reflector errors! No browser window open and I had verified updating the OS didn't help....

Arghhh! Never mind. The errors started again just after midnight. I don't know why I missed the 4 errors that happened before I posted my earlier message.

Posted on
Sat Mar 14, 2020 3:53 pm
welchgregusa offline
Posts: 101
Joined: May 29, 2013
Location: Orlando, FL

Re: Frequent reflector connection errors

I've set up a Dejal Simon (https://www.dejal.com/simon/) test for the site so that I have some sort of record of its ups and downs, and it seems it's more down than up for me. I checked my log files. There were 0 events on 15 FEB. During 16-29 FEB there were several per day. In March it appears to have ramped way up to 10s of events per days, with something like 100 so far today.

This is SO bizarre.

Matt/Jay, two questions if/when you can:

1. Is it plausible that there is too much going on in Indigo (e.g., Python script processing) such that the updates are getting starved for CPU time, and thus the timeouts I'm seeing?

2. Can you say anything about the networking mechanism being used, ports, etc.? I'm wondering whether there is something in my router (a new Netgear Orbi) that might be inhibiting the updates, or whether some antivirus software could be interfering (Sophos on my server). I'm not aware of anything changing w.r.t. either of those, but....

Thanks guys.

Posted on
Sun Mar 15, 2020 1:02 am
jay (support) offline
Site Admin
User avatar
Posts: 18200
Joined: Mar 19, 2008
Location: Austin, Texas

Re: Frequent reflector connection errors

welchgregusa wrote:
1. Is it plausible that there is too much going on in Indigo (e.g., Python script processing) such that the updates are getting starved for CPU time, and thus the timeouts I'm seeing?


That seems quite unlikely, but of course I don't know what scripts you are running. Since scripts can make network calls, anything is possible. Nothing Indigo is doing would ever likely cause a problem like that.

welchgregusa wrote:
2. Can you say anything about the networking mechanism being used, ports, etc.? I'm wondering whether there is something in my router (a new Netgear Orbi) that might be inhibiting the updates, or whether some antivirus software could be interfering (Sophos on my server). I'm not aware of anything changing w.r.t. either of those, but.....


We use standard sockets to communicate between the server and the clients (including the plugin hosts) on port 1176. IWS opens http ports on 8176. We don't do anything unusual (or you'd be seeing a LOT more posts about network issues). Your router is most likely dropping the connections for some unknown reason. We've seen issues like this before and they've always been one of two things: the router has some wacky config or the ISP is doing something bad (satellite providers are the worst, but we've see a couple others that time out network connections really fast).

Jay (Indigo Support)
Twitter | Facebook | LinkedIn

Posted on
Sun Mar 15, 2020 7:27 am
welchgregusa offline
Posts: 101
Joined: May 29, 2013
Location: Orlando, FL

Re: Frequent reflector connection errors

Thanks Jay. After more tests, I'm beginning to think it might be some sort of NAT loopback issue w/ my router. I just discovered that if I connect to a remote machine (at my university) via a remote desktop app (Splashtop), and then back to my Indigo server at home, via any of the DDNS hostnames I maintain for the server, it connects fine. However it fails when using those same hostnames from any browser on the LAN. I replaced my router a while back, which could be when it started for me (or perhaps a router firmware update), but perhaps I simply never noticed. Indeed, the Netgear page on NAT loopback does not list my router (Netgear Orbi RBS850) as supporting NAT loopback. I've got an email in to them for tech support. It would be a pain, but I could revert to my previous router as a test. Perhaps w/ our university's response to Covid-19 I'll have some time to do that....

Thanks to all.

Posted on
Sun Mar 15, 2020 1:51 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

matt (support) wrote:
A couple of thoughts. First is it exactly 2 hours consistently? What is the variance? Also open a browser window on your Indigo Server Mac and point it to the main (home) page of your reflector (so use your reflector URL and not your Mac IP address) then select a device folder and leave that window open and running. The browser will make a request to your Indigo Server over the reflector (round tripping from your Mac -> reflector server -> back to Indigo no your Mac) every couple of seconds to check for device state updates. I'm curious if that helps to keep the connection alive or not.

Hi again Matt and Jay,

My original thread got kinda buried and I also posted some erroneous info so I thought I would summarize what I've learned about the reflector connection errors and see if you have any other thoughts.

1. The errors happen even more consistently than I thought. Almost exactly 2.5 hours from the last successful connection. The small variance I reported before was when the first reconnection attempt failed and Indigo waited 2 minutes to try again.
2. Running a device folder window on the server does indeed cause the errors to go away.
3. The errors started on 1/29/2020 at 10:13:18, 2.5 hours after I restarted the Indigo server after detecting the network going down. The logs don't show anything unusual at that time. I mention this in case you guys happened to make some tweak to the reflector on your end around that time.

The 2.5 hour periodic errors seem to be consistent with what I've read about how persistent connections are typically handled in the absence of a keep-alive message. Apparently, the browser window does indeed serve as a keep-alive, but for some reason the normal operation of the server does not. I understand that you are sending some kind of keep-alive messages between my server and your reflector but they don't appear to be working on my system.

Hopefully, this triggers some thoughts. If not, would you mind elaborating briefly on the keep-alive messages between the server and reflector. If I know what I'm looking for, perhaps I could investigate further why they aren't working for me.

Thanks!

--Dave

Posted on
Sun Mar 15, 2020 2:51 pm
matt (support) offline
Site Admin
User avatar
Posts: 21411
Joined: Jan 27, 2003
Location: Texas

Re: Frequent reflector connection errors

Hi Dave,

DVDDave wrote:
2. Running a device folder window on the server does indeed cause the errors to go away.

Does it reduce or totally eliminate the failures? I believe above you had said you still had the failure it just took much longer than 2 hours.
DVDDave wrote:
3. The errors started on 1/29/2020 at 10:13:18, 2.5 hours after I restarted the Indigo server after detecting the network going down. The logs don't show anything unusual at that time. I mention this in case you guys happened to make some tweak to the reflector on your end around that time.

We haven't had any (intentional) server side changes.
DVDDave wrote:
The 2.5 hour periodic errors seem to be consistent with what I've read about how persistent connections are typically handled in the absence of a keep-alive message. Apparently, the browser window does indeed serve as a keep-alive, but for some reason the normal operation of the server does not. I understand that you are sending some kind of keep-alive messages between my server and your reflector but they don't appear to be working on my system.

Indigo's keep-alive mechanism is when it does a self test of by making a round trip HTTP request using the reflector URL. That occurs once every 10 minutes (and more frequently if the reflector tunnel was just created). We know that test is occurring because that is what detects the down reflector and restarts it (which is shown in your Event Log).

Previously you had said:
DVDDave wrote:
About 1/3 of the time, it comes back in a few seconds on the first retry attempt with the rest coming back after 2 minutes.

Is that still true? If 2/3rds of the time the reflector tunnel's first attempt at reconnecting is failing (causing the 2nd attempt 2 minutes later) then I don't think the problem is related to keep-alives.

Open a Terminal window and start a ping to the reflector server:

Code: Select all
ping indigodomo.net

Leave that up and the next time there is a reflector failure see if there were ping failures around that time too.

Image

Posted on
Sun Mar 15, 2020 2:56 pm
matt (support) offline
Site Admin
User avatar
Posts: 21411
Joined: Jan 27, 2003
Location: Texas

Re: Frequent reflector connection errors

Also who is your ISP?

Image

Posted on
Sun Mar 15, 2020 3:08 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

ISP is Comcast (Xfinity)

I'll do the ping test and, at the same time, see how many times the connection comes right back by running it overnight.. (I assume the ping test won't affect that) After that, I'll determine whether the browser works 100% by running it overnight again.

Thanks, Matt!

--Dave

Posted on
Sun Mar 15, 2020 4:01 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

I started the ping test and I'm seeing round trip times of about 50ms with only a few seconds of variability.

However, I'm also seeing random timeouts about every 30 seconds or so. Note that I get similar timeouts when I ping google.com. I get similar timeouts on my other MacBook Pro.

When I change the ping interval to 3 seconds and set the wait time to 2 seconds, I still get timeouts. It appears that the packets are lost, not just delayed. I don't know if this is normal though.

While the ping timeouts are concerning, I'm not sure this is related to the overall problem since the connection errors are definitely not random. occurring with great regularity every 2.5 hours.

I'll continue the ping testing. The next connection error is due in about an hour.

Posted on
Sun Mar 15, 2020 4:06 pm
matt (support) offline
Site Admin
User avatar
Posts: 21411
Joined: Jan 27, 2003
Location: Texas

Re: Frequent reflector connection errors

That isn't normal. I think something is wrong with your router or your ISP.

Image

Posted on
Sun Mar 15, 2020 4:13 pm
DVDDave offline
Posts: 470
Joined: Feb 26, 2006
Location: San Jose, CA

Re: Frequent reflector connection errors

matt (support) wrote:
That isn't normal. I think something is wrong with your router or your ISP.

Hmmm. I've been reading about it and it seems that this level of packet loss is not uncommon and would normally not cause problems. I'll play with some settings like QoS and look at my network connections but I still think something else is going on since the connection error interval is so consistent. If the errors were due to random packet loss, I think they would be occurring at random intervals, especially since you run the connection test so frequently.

Also, when I can, I'll try the ping test elsewhere.

Posted on
Sun Mar 15, 2020 4:19 pm
matt (support) offline
Site Admin
User avatar
Posts: 21411
Joined: Jan 27, 2003
Location: Texas

Re: Frequent reflector connection errors

While protocols (like TCP) can handle packet loss, I still think having a ping failure every 30 seconds or so is not acceptable and a sign that there is an issue. I've run a ping test against indigodomo.net now for over an hour and have 0 failures. I suspect there is an issue somewhere and that issue is also causing the dropped reflector connections.

Code: Select all
--- indigodomo.net ping statistics ---
5040 packets transmitted, 5040 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 12.425/20.280/168.527/16.625 ms

Image

Who is online

Users browsing this forum: No registered users and 4 guests