search

chrisjshull / homebridge-nest

Nest plugin for HomeBridge
699 stars 112 forks source link

Unable to reconnect to Nest API after network comes back online #597

Closed poindextrose closed 1 year ago

poindextrose commented 1 year ago

My network went down due to power outage while homebridge continued to run on a laptop. After the network/power returned (40 minutes later), homebridge-nest was still unable to connect to Nest 9 hours later when I realized it wasn't connected. After I restarted the child bridge it immediately connected to Nest API.

Here are the logs when the network went down. It was doing it's normal things with "illegal value" as it always does then we lose network at 8:58:37 AM when we see the ENOTFOUND.

[1/9/2023, 8:57:44 AM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 8:58:06 AM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 8:58:37 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 8:58:37 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 8:59:00 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 8:59:00 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 8:59:06 AM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 8:59:21 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 8:59:21 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 8:59:43 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 8:59:43 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:04 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 9:00:04 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:06 AM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 9:00:09 AM] [Nest] API observe: error { code: 'ETIMEDOUT' }
[1/9/2023, 9:00:09 AM] [Nest] ^^^^^ this message is for information only, it does not mean there is a problem, please do not file a ticket unless you actually have a problem with the function of the plug-in
[1/9/2023, 9:00:09 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:26 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 9:00:26 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:29 AM] [Nest] API observe: error Error: The pending stream has been canceled (caused by: getaddrinfo ENOTFOUND grpc-web.production.nest.com)
    at new NodeError (node:internal/errors:393:5)
    at closeSession (node:internal/http2/core:1143:20)
    at ClientHttp2Session.destroy (node:internal/http2/core:1537:5)
    at TLSSocket.socketOnError (node:internal/http2/core:2991:13)
    at TLSSocket.emit (node:events:513:28)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  cause: Error: getaddrinfo ENOTFOUND grpc-web.production.nest.com
      at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26) {
    errno: -3008,
    code: 'ENOTFOUND',
    syscall: 'getaddrinfo',
    hostname: 'grpc-web.production.nest.com'
  },
  code: 'ERR_HTTP2_STREAM_CANCEL'
}
[1/9/2023, 9:00:29 AM] [Nest] ^^^^^ this message is for information only, it does not mean there is a problem, please do not file a ticket unless you actually have a problem with the function of the plug-in
[1/9/2023, 9:00:29 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:47 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND
[1/9/2023, 9:00:47 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:00:50 AM] [Nest] API observe: error Error: The pending stream has been canceled (caused by: getaddrinfo ENOTFOUND grpc-web.production.nest.com)
    at new NodeError (node:internal/errors:393:5)
    at closeSession (node:internal/http2/core:1143:20)
    at ClientHttp2Session.destroy (node:internal/http2/core:1537:5)
    at TLSSocket.socketOnError (node:internal/http2/core:2991:13)
    at TLSSocket.emit (node:events:513:28)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  cause: Error: getaddrinfo ENOTFOUND grpc-web.production.nest.com
      at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26) {
    errno: -3008,
    code: 'ENOTFOUND',
    syscall: 'getaddrinfo',
    hostname: 'grpc-web.production.nest.com'
  },
  code: 'ERR_HTTP2_STREAM_CANCEL'
}
[1/9/2023, 9:00:50 AM] [Nest] ^^^^^ this message is for information only, it does not mean there is a problem, please do not file a ticket unless you actually have a problem with the function of the plug-in
[1/9/2023, 9:00:50 AM] [Nest] Retrying in 10 seconds.
[1/9/2023, 9:01:06 AM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 9:01:10 AM] [Nest] Nest API call to subscribe to device settings updates returned an error: ENOTFOUND

The log continues this repeat the same error message but then changes do reauthenticating at 6:30:49

[1/9/2023, 6:30:39 PM] [Nest] API observe: error Error: The pending stream has been canceled (caused by: getaddrinfo ENOTFOUND grpc-web.production.nest.com)
    at new NodeError (node:internal/errors:393:5)
    at closeSession (node:internal/http2/core:1143:20)
    at ClientHttp2Session.destroy (node:internal/http2/core:1537:5)
    at TLSSocket.socketOnError (node:internal/http2/core:2991:13)
    at TLSSocket.emit (node:events:513:28)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  cause: Error: getaddrinfo ENOTFOUND grpc-web.production.nest.com
      at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26) {
    errno: -3008,
    code: 'ENOTFOUND',
    syscall: 'getaddrinfo',
    hostname: 'grpc-web.production.nest.com'
  },
  code: 'ERR_HTTP2_STREAM_CANCEL'
}
[1/9/2023, 6:30:39 PM] [Nest] ^^^^^ this message is for information only, it does not mean there is a problem, please do not file a ticket unless you actually have a problem with the function of the plug-in
[1/9/2023, 6:30:39 PM] [Nest] Retrying in 10 seconds.
[1/9/2023, 6:30:44 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:30:45 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:30:49 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:30:49 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:30:52 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:30:54 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:30:57 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:30:59 PM] [Nest] Reauthenticating on Nest service ...

...repeats until I restart the child bridge at 6:54:04PM

[1/9/2023, 6:53:59 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:54:01 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:54:03 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:54:04 PM] [Nest] Restarting child bridge...
[1/9/2023, 6:54:04 PM] Got SIGTERM, shutting down child bridge process...
[1/9/2023, 6:54:06 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:54:09 PM] [Nest] Reauthenticating on Nest service ...
[1/9/2023, 6:54:09 PM] [Nest] Child bridge process ended
[1/9/2023, 6:54:09 PM] [Nest] Process Ended. Code: 143, Signal: null
[1/9/2023, 6:54:16 PM] [Nest] Restarting Process...
[1/9/2023, 6:54:17 PM] [Nest] Launched child bridge with PID 3045677
[1/9/2023, 6:54:17 PM] Registering platform 'homebridge-nest.Nest'
[1/9/2023, 6:54:17 PM] [Nest] Loaded homebridge-nest v4.6.9 child bridge successfully
[1/9/2023, 6:54:17 PM] Loaded 14 cached accessories from cachedAccessories.0E1FD4FAD217.
[1/9/2023, 6:54:17 PM] [Nest] Fetching Nest devices.
[1/9/2023, 6:54:17 PM] Homebridge v1.6.0 (HAP v0.11.0) (Nest) is running on port 35607.
[1/9/2023, 6:54:22 PM] [Nest] initing thermostat (P) "Rio's Bedroom Thermostat": deviceId: CCA7C100003615B7 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[Rio's Bedroom Thermostat@@Heating Threshold Temperature] characteristic was supplied illegal value: number 0 exceeded minimum of 10
[1/9/2023, 6:54:22 PM] [Nest] initing thermostat (P) "Basement Bathroom Thermostat": deviceId: CCA7C1000036FB3C structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[Basement Bathroom Thermostat@@Heating Threshold Temperature] characteristic was supplied illegal value: number 0 exceeded minimum of 10
[Basement Bathroom Thermostat@@Cooling Threshold Temperature] characteristic was supplied illegal value: number 5 exceeded minimum of 10
[1/9/2023, 6:54:22 PM] [Nest] initing thermostat (P) "Basement Thermostat": deviceId: CCA7C100002C353C structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[Basement Thermostat@@Heating Threshold Temperature] characteristic was supplied illegal value: number 0 exceeded minimum of 10
[1/9/2023, 6:54:22 PM] [Nest] initing thermostat (P) "Shawn's Bedroom Thermostat": deviceId: CCA7C1000036E1E2 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[Shawn's Bedroom Thermostat@@Heating Threshold Temperature] characteristic was supplied illegal value: number 0 exceeded minimum of 10
[1/9/2023, 6:54:22 PM] [Nest] initing thermostat (P) "Hallway Thermostat": deviceId: CCA7C10000223576 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[Hallway Thermostat@@Heating Threshold Temperature] characteristic was supplied illegal value: number 0 exceeded minimum of 10
[1/9/2023, 6:54:22 PM] [Nest] initing home_away_sensor "Home Occupied": deviceId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing temp_sensor (P) "Becki's Bedroom": deviceId: 18B430CE7616F97C structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing protect "Basement Nest Protect": deviceId: 18B430004198E5C1 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing protect "Shawn's Bedroom Nest Protect": deviceId: 18B430004198DF5D structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing protect "Rio's Bedroom Nest Protect": deviceId: 18B430004198DCF8 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing lock (P) "Entryway Lock": deviceId: 00177A00000ACD1F structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing lock (P) "Garage Lock": deviceId: 00177A00000ACCD5 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing lock (P) "Kitchen Lock": deviceId: 00177A00000ACCE4 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:22 PM] [Nest] initing lock (P) "Basement Lock": deviceId: 00177A00000D1F65 structureId: 0746e0c0-2e36-11ec-bc85-0e7a9cd89f03
[1/9/2023, 6:54:46 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:55:46 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:56:53 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:58:03 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.
[1/9/2023, 6:59:03 PM] [homebridge-nest] This plugin generated a warning from the characteristic 'Cooling Threshold Temperature': characteristic was supplied illegal value: number 5 exceeded minimum of 10. See https://homebridge.io/w/JtMGR for more info.

Config

{
    "bridge": {
        "name": "Homebridge E11C",
        "username": "0E:A4:AA:7D:E7:E1",
        "port": 51018,
        "pin": "248-34-055",
        "advertiser": "ciao"
    },
    "accessories": [],
    "platforms": [
        {
            "name": "Config",
            "port": 8581,
            "auth": "form",
            "theme": "auto",
            "tempUnits": "f",
            "lang": "auto",
            "platform": "config"
        },
        {
            "name": "Nest",
            "googleAuth": {
                "issueToken": "...",
                "cookies": "..."
            },
            "_bridge": {
                "username": "0E:1F:D4:FA:D2:17",
                "port": 35607
            },
            "platform": "Nest"
        },
        {
            "name": "Levoit Air Purifiers",
            "email": "...",
            "password": "...",
            "platform": "LevoitAirPurifiers",
            "_bridge": {
                "username": "0E:08:C4:EB:03:C5",
                "port": 46977
            }
        }
    ]
}

Recently install home bridge and this plugin a few weeks ago on a new machine node -- version v12.22.9 npm homebridge --version 8.5.1

adriancable commented 1 year ago

ENOTFOUND is a DNS lookup error. Your machine for whatever reason isn't able to make DNS lookups, probably as some consequence of the outage. It isn't a plug-in issue, or a Homebridge issue.

poindextrose commented 1 year ago

Thanks for looking into this. I wish it was that simple. While DNS was unavailable for a short period of time when DNS came back on the homebridge-nest plugin was unable to reconnect to the API. Everything else on the system was functional and the ONLY thing I did to restore the plugin to working status was to restart the plugin from the homebridge UI. After restart it worked as expected.

I'll see if I can reproduce with a minimal example.

adriancable commented 1 year ago

@poindextrose - the error you are getting is from the Linux network stack: getaddrinfo ENOTFOUND grpc-web.production.nest.com

It's likely that Linux's DNS cache remained stale for a little while after the network came back. It's possible that restarted the Homebridge process flushed it. Unfortunately, if you are getting ENOTFOUND errors from the network stack, it's completely beyond my influence.