EvoHome crashes homebridge — ENETUNREACH

PuzzledUser commented 2 years ago

My Homebridge was dead this morning. No HomeKit, http, ssh, ping. It seems Evohome took it down. Perhaps provoked by transient inaccessibility of tccna.honeywell.com. Be nice to handle the error more elegantly.

(Note it had its time wrong https://github.com/luc-ass/homebridge-evohome/issues/100 — hence wrong next change)

[09/11/2021, 02:37:08] [Evohome] Updating: XX currentTempChange from: 17 to: 16.5
[09/11/2021, 03:03:31] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 03:33:00] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 04:02:29] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 04:17:41] [Evohome] Current temperature of XX Thermostat is 16.5°
[09/11/2021, 04:17:41] [Evohome] Target temperature for XX Thermostat is 13°
[09/11/2021, 04:31:58] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 05:01:27] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 05:30:56] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 05:50:00] [Evohome] Target temperature for XX Thermostat is 13°
[09/11/2021, 05:50:00] [Evohome] Request to set target temperature to 17
[09/11/2021, 05:50:00] [Evohome] HEAT or COOL selected, previous state AUTO, HEAT or COOL. Doing nothing.
[09/11/2021, 05:50:02] [Evohome] The current time is 06:50:02
[09/11/2021, 05:50:02] [Evohome] Schedule points for today (Tuesday)
[09/11/2021, 05:50:02] [Evohome] - 06:50:00
[09/11/2021, 05:50:02] [Evohome] - 07:10:00 -> next change
[09/11/2021, 05:50:02] [Evohome] - 08:10:00
[09/11/2021, 05:50:02] [Evohome] - 18:00:00
[09/11/2021, 05:50:02] [Evohome] - 22:00:00
[09/11/2021, 05:50:02] [Evohome] Setting target temperature for XX Thermostat to 17° until 07:10:00
[09/11/2021, 05:50:03] [Evohome] Successfully changed temperature!
[09/11/2021, 05:50:03] [Evohome] { id: 'XX' }
[09/11/2021, 05:52:08] [Evohome] Updating: XX currentTempChange from: 16.5 to: 17
[09/11/2021, 06:00:25] [Evohome] Renewed Honeywell API authentication token!
[09/11/2021, 06:11:38] [Evohome] Current temperature of XX Thermostat is 17°
[09/11/2021, 06:11:38] [Evohome] Target temperature for XX Thermostat is 17°
[09/11/2021, 06:18:51] [Evohome] Current temperature of XX Thermostat is 17°
[09/11/2021, 06:18:51] [Evohome] Target temperature for XX Thermostat is 17°
[09/11/2021, 06:20:18] [Evohome] Current temperature of XX Thermostat is 17°
[09/11/2021, 06:20:18] [Evohome] Target temperature for XX Thermostat is 17°
[09/11/2021, 06:20:27] [Evohome] Current temperature of XX Thermostat is 17°
[09/11/2021, 06:20:27] [Evohome] Target temperature for XX Thermostat is 17°
[09/11/2021, 06:22:17] [Evohome] Current temperature of XX Thermostat is 17°
[09/11/2021, 06:22:17] [Evohome] Target temperature for XX Thermostat is 17°
[09/11/2021, 06:23:58] Error: send ENETUNREACH 224.0.0.251:5353
    at doSend (dgram.js:692:16)
    at defaultTriggerAsyncIdScope (internal/async_hooks.js:429:12)
    at afterDns (dgram.js:638:5)
    at processTicksAndRejections (internal/process/task_queues.js:81:21)
[09/11/2021, 06:23:58] Got SIGTERM, shutting down Homebridge...
[09/11/2021, 06:24:03] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null
[09/11/2021, 06:24:08] [HB Supervisor] Restarting Homebridge...
[09/11/2021, 06:24:08] [HB Supervisor] Starting Homebridge with extra flags: -I
[09/11/2021, 06:24:08] [HB Supervisor] Started Homebridge v1.3.5 with PID: 8470
Initializing HAP-NodeJS v0.9.6...
<snip>
[09/11/2021, 06:24:24] Loaded plugin: homebridge-config-ui-x@4.41.2
[09/11/2021, 06:24:24] Registering platform 'homebridge-config-ui-x.config'
[09/11/2021, 06:24:24] ---
[09/11/2021, 06:24:28] Loaded plugin: homebridge-evohome@0.8.4
[09/11/2021, 06:24:47] Registering platform 'homebridge-evohome.Evohome'
[09/11/2021, 06:24:47] ---
<snip>
[09/11/2021, 06:24:50] [Evohome] Error during Login: Error: getaddrinfo ENOTFOUND tccna.honeywell.com
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'tccna.honeywell.com'
}

PuzzledUser commented 2 years ago

Perhaps related, my home automation script lost its parameters:

I had to re-select the accessory and its options.

I've seen this once before recently (after updating to the latest 0.8.4) after previously running my own fork of the code to support the Round stat for months.

PuzzledUser commented 2 years ago

Cold this morning as my heating didn't turn on early... Homebridge unresponsive again, needed power cycling. Last logs below:

[24/11/2021, 20:24:29] [Evohome] Current temperature of XX Thermostat is 17°
[24/11/2021, 20:24:29] [Evohome] Target temperature for XX Thermostat is 17°
[24/11/2021, 20:29:07] [Evohome] Current temperature of XX Thermostat is 17°
[24/11/2021, 20:29:07] [Evohome] Target temperature for XX Thermostat is 17°
[24/11/2021, 20:30:01] [Evohome] Target temperature for XX Thermostat is 17°
[24/11/2021, 20:30:03] [Evohome] Request to set target temperature to 17.5
[24/11/2021, 20:30:03] [Evohome] HEAT or COOL selected, previous state AUTO, HEAT or COOL. Doing nothing.
[24/11/2021, 20:30:04] [Evohome] Target temperature for XX Thermostat is 17°
[24/11/2021, 20:30:05] [Evohome] Request to set target temperature to 17.5
[24/11/2021, 20:30:05] [Evohome] HEAT or COOL selected, previous state AUTO, HEAT or COOL. Doing nothing.
[24/11/2021, 20:30:23] [Evohome] Evohome failed: Error: getaddrinfo ENOTFOUND tccna.honeywell.com
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'tccna.honeywell.com'
}
[24/11/2021, 20:30:25] [Evohome] The current time is 21:30:25
[24/11/2021, 20:30:25] [Evohome] Setting target temperature for XX Thermostat to 17.5° until null
[24/11/2021, 20:30:25] [Evohome] The current time is 21:30:25
[24/11/2021, 20:30:25] [Evohome] Setting target temperature for XX Thermostat to 17.5° until null
[24/11/2021, 20:30:25] [Evohome] Successfully changed temperature!
[24/11/2021, 20:30:25] [Evohome] [ { code: 'Unauthorized', message: 'Unauthorized.' } ]
[24/11/2021, 20:30:25] [Evohome] Successfully changed temperature!
[24/11/2021, 20:30:25] [Evohome] [ { code: 'Unauthorized', message: 'Unauthorized.' } ]
[24/11/2021, 20:30:28] [Evohome] Evohome failed: Error: getaddrinfo ENOTFOUND tccna.honeywell.com
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'tccna.honeywell.com'
}

All ok after the reboot. Authorisation was correct.

Homebridge v1.3.8 homebridge-config-ui-x v4.41.2 homebridge-evohome v0.8.4 Homebridge Raspbian v1.0.17 - Raspberry Pi Zero W Rev 1.1

luc-ass commented 2 years ago

Really strange. Did you have a fix in your branch?

PuzzledUser commented 2 years ago

Nope. I've been back on your pure release version for a few months.

PuzzledUser commented 2 years ago

homebridge-evohome v0.8.5

I suspect a Honeywell outage bombed my homebridge again. Just had to power cycle it and found pages of repeating debug in the logs ending with:

...
      agent: [Agent],
      socketPath: undefined,
      method: 'GET',
      maxHeaderSize: undefined,
      insecureHTTPParser: undefined,
      path: '/WebAPI/emea/api/v1/location/installationInfo?userId=594798&includeTemperatureControlSystems=True',
      _ended: true,
      res: [Circular *2],
      aborted: false,
      timeoutCb: null,
      upgradeOrConnect: false,
      parser: null,
      maxHeadersCount: null,
      reusedSocket: false,
      host: 'tccna.honeywell.com',
      protocol: 'https:',
      [Symbol(kCapture)]: false,
      [Symbol(kNeedDrain)]: false,
      [Symbol(corked)]: 0,
      [Symbol(kOutHeaders)]: [Object: null prototype]
    },
    ntick: true,
    response: [Circular *2],
    originalHost: 'tccna.honeywell.com',
    originalHostHeaderName: 'host',
    responseContent: [Circular *2],
    _destdata: true,
    _ended: true,
    _callbackCalled: true,
    [Symbol(kCapture)]: false
  },
  toJSON: [Function: responseToJSON],
  caseless: Caseless {
    dict: {
      'content-length': '62',
      connection: 'close',
      'cache-control': 'no-cache,no-store',
      pragma: 'no-cache'
    }
  },
  body: '<html><body><b>Http/1.1 Service Unavailable</b></body> </html>',
  [Symbol(kCapture)]: false,
  [Symbol(RequestTimeout)]: undefined
}
[22/12/2021, 16:17:56] [Evohome] Renewed Honeywell API authentication token!
[22/12/2021, 16:21:39] [Evohome] Updating: XX currentTempChange from: 14 to: 13.5
[22/12/2021, 16:39:11] [Garage] getState: Closed
[22/12/2021, 16:39:11] [Evohome] Current temperature of XX Thermostat is 13.5°
[22/12/2021, 16:39:11] [Evohome] Target temperature for XX Thermostat is 11°
[22/12/2021, 16:47:25] [Evohome] Renewed Honeywell API authentication token!
[22/12/2021, 22:02:16] [HB Supervisor] OS: Linux 5.10.63+ arm
[22/12/2021, 22:02:16] [HB Supervisor] Node.js v14.15.1 /usr/local/bin/node
[22/12/2021, 22:02:16] [HB Supervisor] Homebridge Path: /usr/local/lib/node_modules/homebridge/bin/homebridge
[22/12/2021, 22:02:16] [HB Supervisor] UI Path: /usr/local/lib/node_modules/homebridge-config-ui-x/dist/bin/standalone.js

Circumstantial, but suspicious

luc-ass commented 2 years ago

Thanks for following up. I don't have a lot of free time at the moment, but I'll try to find some way to do better error handling. I was planing to switch to axios anyway.

PuzzledUser commented 2 years ago

No problem @luc-ass, one for a rainy day. Speaking of which, the grot weather is weakening the wifi to my RPi (which lives in the garage 🙄). So I think I'm provoking your comms with Honeywell more than is typical. Still, no reason not to trap the errors 😉

Season's greetings!

[23/12/2021, 17:28:32] [Evohome] Current temperature of XX Thermostat is 15.5°
[23/12/2021, 17:28:32] [Evohome] Target temperature for XX Thermostat is 11°
[23/12/2021, 17:28:33] Error: send ENETUNREACH 224.0.0.251:5353
    at doSend (dgram.js:692:16)
    at defaultTriggerAsyncIdScope (internal/async_hooks.js:429:12)
    at afterDns (dgram.js:638:5)
    at processTicksAndRejections (internal/process/task_queues.js:81:21)
[23/12/2021, 17:28:33] Got SIGTERM, shutting down Homebridge...
[23/12/2021, 17:28:38] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null
[23/12/2021, 17:28:43] [HB Supervisor] Restarting Homebridge...
[23/12/2021, 17:28:43] [HB Supervisor] Starting Homebridge with extra flags: -I
[23/12/2021, 17:28:43] [HB Supervisor] Started Homebridge v1.3.8 with PID: 6685

PuzzledUser commented 2 years ago

Just a note that the recent Honeywell outage triggered this issue again. Very annoying that I have to reselect the accessory in my automations. If the plugin didn't crash, I guess I wouldn't have to re-add after a Honeywell outage?

[31/03/2022, 06:30:08] [Evohome] Evohome failed: SyntaxError: Unexpected token < in JSON at position 0
    at JSON.parse (<anonymous>)
    at Request._callback (/usr/local/lib/node_modules/homebridge-evohome/lib/evohome.js:313:23)
    at Request.self.callback (/usr/local/lib/node_modules/homebridge-evohome/node_modules/request/request.js:185:22)
    at Request.emit (events.js:315:20)
    at Request.<anonymous> (/usr/local/lib/node_modules/homebridge-evohome/node_modules/request/request.js:1154:10)
    at Request.emit (events.js:315:20)
    at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/homebridge-evohome/node_modules/request/request.js:1076:12)
    at Object.onceWrapper (events.js:421:28)
    at IncomingMessage.emit (events.js:327:22)
    at endReadableNT (_stream_readable.js:1327:12)

luc-ass commented 1 year ago

This should be fixed as of v0.10.1

Don't hesitate to reopen this issue, if you encounter problems!

luc-ass / homebridge-evohome

EvoHome crashes homebridge — ENETUNREACH #101