Failure to recover if network is not available on startup

[ryanleesmith]

Bug Report

Describe the Bug

It appears that if Homebridge boots on system start, and the network connection is not immediately available, the Ring plugin will get stuck in a loop where it claims the Ring API endpoints are not reachable. I never had any issues with this setup on a Raspberry Pi, but I recently migrated my setup to a Mac mini for more resources, and it consistently happens every time my Mac starts.

To Reproduce

Steps to reproduce the behavior:

• Start Homebridge on macOS boot
• Attempt to allow Ring plugin to load
• See error

Expected behavior

Ring plugin should automatically recover even if network connectivity was not initially available.

Screenshots/Logs

[Ring] Failed to reach Ring server at https://app.ring.com/rhq/v1/devices/v1/locations. cacheableLookup ENOTFOUND app.ring.com. Trying again in 5 seconds...

This log line is printed over and over until rebooting Homebridge.

Additional context

My Mac mini is setup with a wired connection, and automatically logs in without password on boot. All other plugins are able to start and recover from any initial errors. Restarting Homebridge after system boot resolves the issue.

Homebridge Ring Config

Post homebridge-ring platform config without sensitive information

{
  "refreshToken": "xxx",
  "platform": "Ring"
}

Environment

• OS: macOS Catalina
• Node.js: 12.18.3
• NPM: 6.14.6
• homebridge-ring: 9.9.0
• homebridge: 1.2.2
• hoobs: N/A

[ryanleesmith]

This is no surprise, but it's easily reproduced just by unplugging the ethernet cable and restarting Homebridge. If the "cacheableLookup ENOTFOUND app.ring.com" error is hit, the plugin never recovers even if you reconnect. This is just more noticeable on reboot because if it happens while you're away or otherwise don't have access, you will lose access to the Ring plugin.

[N-Hott]

Every time I do a hb-service restart I get these.

[9/16/2020, 3:44:03 PM] [Ring] Failed to reach Ring server at https://app.ring.com/rhq/v1/devices/v1/locations. Cannot read property 'request' of undefined. Trying again in 5 seconds...
2020-09-16T19:44:03.869Z ciao:Announcer [Homebridge E1A5._hap._tcp.local.] Sending announcement number 2
2020-09-16T19:44:05.875Z ciao:Announcer [Homebridge E1A5._hap._tcp.local.] Sending announcement number 3
[9/16/2020, 3:44:09 PM] [Ring] Failed to reach Ring server at https://api.ring.com/clients_api/ring_devices. Cannot read property 'request' of undefined. Trying again in 5 seconds...

Then shortly thereafter..

[9/16/2020, 3:44:39 PM] Error: Socket timeout
at TLSSocket.onTimeout (/usr/lib/node_modules/homebridge-ring/node_modules/agentkeepalive/lib/agent.js:345:23)
at TLSSocket.emit (events.js:326:22)
at TLSSocket.Socket._onTimeout (net.js:482:8)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)
[9/16/2020, 3:44:39 PM] Got SIGTERM, shutting down Homebridge...
2020-09-16T19:44:39.870Z ciao:Responder [Homebridge E1A5._hap._tcp.local.] Removing service from the network
2020-09-16T19:44:39.871Z ciao:Announcer [Homebridge E1A5._hap._tcp.local.] Sending goodbye for service
2020-09-16T19:44:39.873Z ciao:Announcer [Homebridge E1A5._hap._tcp.local.] Sending goodbye number 1
2020-09-16T19:44:39.882Z ciao:Responder Shutting down Responder...
[9/16/2020, 3:44:44 PM] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null
[9/16/2020, 3:44:49 PM] [HB Supervisor] Restarting Homebridge...
[9/16/2020, 3:44:49 PM] [HB Supervisor] Starting Homebridge with custom env: {"DEBUG":"ciao:*"}

It sometimes does this 2 or 3 times and is then stable.

[ryanleesmith]

I'm not sure what the cause of those errors is, but I don't see the "ENOTFOUND" error code in your logs. I assume there is some kind of domain/address lookup that is failing and caching...despite the network connection recovering.

[ryanleesmith]

One other thing, it seems the oauth requests are able to recover. It initially reports the following:

[Ring] Failed to reach Ring server at https://oauth.ring.com/oauth/token. getaddrinfo ENOTFOUND oauth.ring.com. Trying again in 5 seconds...

but after reconnecting, it switches to:

[Ring] Failed to reach Ring server at https://app.ring.com/rhq/v1/devices/v1/locations. cacheableLookup ENOTFOUND app.ring.com. Trying again in 5 seconds...

So it's not clear if this is a bug in cacheable-lookup or how the plugin is implemented.

[ryanleesmith]

Apparently it doesn't even require this to happen at Homebridge startup - if the Mac loses connectivity at any point, the plugin will get stuck in this loop :(

[dgreif]

@ryanleesmith This has been reported before, but I didn't realize I could recreate it just by turning WiFi off and back on, so thanks for the tip! I'm able to recreate this issue on my end now. It has to do with dns caching, which I added months ago. If there is no network connection on startup, it caches an error. I have code in place to clear the base value, but apparently it doesn't work. May be a bug in the library I'm using, but it will take some digging to figure it out. Unfortunately I don't have a ton of free time currently, but will push a fix as soon as I'm able.

[ryanleesmith]

No worries. I'd be more than happy to play around with it if I knew how to reliably install a local version - I've yet to figure out a good way to do this with npm. I cloned your repo locally, ran npx tsc from the main folder, and tried npm -g install from the homebridge folder, but homebridge errors out on startup.

[dgreif]

@ryanleesmith can you give it a try on v9.10.0?

[ryanleesmith]

That resolved it for me. Thanks!