Bug Report: XfinityHome plugin 401 -timestamp errors

[rdeutsch3]

Describe The Bug:

I've been trying to run the XfinityHome homebridge plug in off and on for a couple of versions and have been having issues with it having 401 errors and then seemingly taking down other plugins that communicate with the outside world (e.g. ring & CarrierInfinity), and causing the homebridge to become generally unresponsive, see system A below. I've tried running it on a separate child bridge and that doesn't help, once I see a 401 error in the logs, it tends to clobber my other plugins as well. Each of the other plugins are running on their own separate bridges. Once I reboot the XfinityHome child bridge (and the other subsequent failed bridges), or homebridge, or the server, everything is fine for a while. If I disable the XfinityHome plugin child bridge (not running XfinityHome at all), my homebridge system stays up and remains responsive.

Subsequently I've configured a second system to run Homebridge, a Synology DSM (system b below), and only the XfinityHome plugin as a child bridge. This system also gets a 401 error after a short period of time, and the plugin does not recover. Restarting the child bridge and its fine for a short time. Meanwhile my original Homebridge continues to run the other child bridges fine.

My external and internal networks are stable. Both homebridge systems are using ethernet connections and I'm not experiencing any internal or external network connectivity issues.

Homebridge system configurations: a) Raspberry Pi Linux Bullseye 11 Node.js v18.12.1 (had the same problems using older Node.js versions) 8GB RAM, 7.12GB available Typically running around 5% CPU load Homebridge v1.5.1 - I've had the same problems with older home bridge versions 4 child bridges (when running XFinityHome, 3 now consisting of Ring, CarrierInfinity & Dummy) 1GB wired Ethernet connection directly to router

b) Synology DSM - running 7.1 Node.js v16.16.0 8 GB RAM / 7.1GB available 2% CPU load Homebridge v1.6.0 - I've had the same problems running 1.5.1 XfinityHome child bridge only. LAG Ethernet connection to switch then to router.

To Reproduce:

Configure XFinityHome using the instructions provided with the plugin. The instructions yield a working refresh token, a pin is provided and Log Level is set to 3. Then let it run a while.

Expected behavior:

Plugin works and provides AppleHomekit support.

Logs:

[11/28/2022, 6:36:59 PM] [Xfinity Home] Panel: Failed To Fetch Target State With Error:  {
  "name": "Error",
  "message": "Request failed with status code 401",
  "request": {
    "method": "GET",
    "protocol": "https:",
    "host": "xhomeapi-lb-prod.codebig2.net",
    "path": "/client/icontrol/device/109c9726ad8acc",
    "headers": [
      "GET /client/icontrol/device/109c9726ad8acc HTTP/1.1",
      "Accept: application/json",
      "Host: xhomeapi-lb-prod.codebig2.net",
      "Content-Type: application/x-www-form-urlencoded",
      "Connection: keep-alive",
      "X-Client-Features: auth4all,carousel,carousel-devicedeeplink,no-cookie,deeplinkV1",
      "Xh-Auth: <redacted>",
      "Authorization: Bearer <redacted>",
      "Accept-Language: en-us",
      "Accept-Encoding: gzip, deflate, br",
      "User-Agent: axios/0.26.1"
    ]
  },
  "response": {
    "statusCode": 401,
    "statusMessage": "Unauthorized",
    "headers": {
      "server": "CodeBig",
      "date": "Tue, 29 Nov 2022 00:36:59 GMT",
      "content-type": "text/plain",
      "transfer-encoding": "chunked",
      "connection": "keep-alive",
      "keep-alive": "timeout=60",
      "www-authenticate": "Bearer realm=\"CIMA\", error=\"invalid_token\", error_description=\"expired timestamp\"",
      "codebig-error-message": "expired timestamp",
      "via": "1.1 CodeBig"
    },
    "data": "expired timestamp\n"
  }
}
[11/28/2022, 6:37:46 PM] [Xfinity Home] Panel: Failed To Fetch Target State With Error:  {
  "name": "Error",
  "message": "Request failed with status code 401",
  "request": {
    "method": "GET",
    "protocol": "https:",
    "host": "xhomeapi-lb-prod.codebig2.net",
    "path": "/client/icontrol/device/109c9726ad8acc",
    "headers": [
      "GET /client/icontrol/device/109c9726ad8acc HTTP/1.1",
      "Accept: application/json",
      "Host: xhomeapi-lb-prod.codebig2.net",
      "Content-Type: application/x-www-form-urlencoded",
      "Connection: keep-alive",
      "X-Client-Features: auth4all,carousel,carousel-devicedeeplink,no-cookie,deeplinkV1",
      "Xh-Auth: <redacted>",
      "Authorization: Bearer <redacted>",
      "Accept-Language: en-us",
      "Accept-Encoding: gzip, deflate, br",
      "User-Agent: axios/0.26.1"
    ]
  },
  "response": {
    "statusCode": 401,
    "statusMessage": "Unauthorized",
    "headers": {
      "server": "CodeBig",
      "date": "Tue, 29 Nov 2022 00:37:46 GMT",
      "content-type": "text/plain",
      "transfer-encoding": "chunked",
      "connection": "keep-alive",
      "keep-alive": "timeout=60",
      "www-authenticate": "Bearer realm=\"CIMA\", error=\"invalid_token\", error_description=\"expired timestamp\"",
      "codebig-error-message": "expired timestamp",
      "via": "1.1 CodeBig"
    },
    "data": "expired timestamp\n"
  }
}
[11/28/2022, 6:45:16 PM] [Homebridge UI] [homebridge-xfinityhome] Terminating child process...
[11/28/2022, 6:45:16 PM] [Homebridge UI] [homebridge-xfinityhome] Child process ended

Note: Both homebridge system times appear to be the in sync with the rest my computers, iOS devices, etc.

Config:

{
    "bridge": {
        "name": "Homebridge",
        "username": "0E:EE:84:98:C2:5B",
        "port": 51810,
        "pin": "255-19-737",
        "advertiser": "bonjour-hap",
        "bind": [
            "bond0"
        ]
    },
    "accessories": [],
    "platforms": [
        {
            "name": "Config",
            "port": 8581,
            "platform": "config"
        },
        {
            "name": "Xfinity Home",
            "refreshToken": "******",
            "pin": "1597",
            "temperatureSensors": true,
            "logLevel": 3,
            "platform": "XfinityHomePlatform",
            "_bridge": {
                "username": "0E:CA:A4:35:02:C7",
                "port": 52433
            }
        }
    ]
}

Operating System:

Other

Node Version:

18.12.1 & 16.16.0

NPM Version:

8.19.2 & 8.11.0

Homebridge Version:

1.6.0 & 1.5.1

Plugin Version:

2.4.0

[rdeutsch3]

Please LMK if there is other information you need to debug the issue.

[bloomkd46]

I've experience this issue on my end as well but only about once a month so I didn't bother to patch it. Now that I know it is a bigger problem I will work on getting a patch out in the near future. I will let you know when it is out.

[rdeutsch3]

Cool. It happens pretty randomly as far as time between restart and when it occurs. Generally less than 6h. When I upgraded to the updated version of node.js I was hopeful as it seemed stable for a couple hours. I don't think I've made it over the 12h mark with it running reliably. I know I have not made the 24h mark once in the last week on the system that is only running the XfinityHome plug in (sorry - I'm not trying to 'add insult to injury', just letting you know the frequency of failure on my end)

[bloomkd46]

Could you try setting your DEBUG variable in homebridge settings to XHome:Error* and send me a copy of any new logs that show up right before/when it is unresponsive

[rdeutsch3]

Variable set. Will send log information when I get it.

[rdeutsch3]

OK dumb question: It failed sometime since 730 this morning and now 3:56pm. I've downloaded the log, but don't know when it failed. Perhaps in the last 4h, but I really don't know, and the log doesn't seem to go back that far. What message should I look for? What message would you find interesting to diagnose the issue?

Here is the oldest message I was able to get from the log file via the Homebridge UI: 2022-11-29T20:47:32.038Z XHome:Error Request failed with status code 401 2022-11-29T20:47:32.038Z XHome:Error:Info { name: 'Error', message: 'Request failed with status code 401', request: { method: 'GET', protocol: 'https:', host: 'xhomeapi-lb-prod.apps.cloud.comcast.net', path: '/client/icontrol/delta', headers: [ 'GET /client/icontrol/delta HTTP/1.1', 'Accept: application/json', 'Host: xhomeapi-lb-prod.apps.cloud.comcast.net', 'Content-Type: application/json', 'Connection: keep-alive', 'X-Client-Features: auth4all,carousel,carousel-devicedeeplink,no-cookie,deeplinkV1', 'Xh-Auth: ', 'Authorization: Bearer ', 'Accept-Language: en-us', 'Accept-Encoding: gzip, deflate, br', 'User-Agent: axios/0.26.1' ] }, response: { statusCode: 401, statusMessage: 'Unauthorized', headers: { 'cache-control': 'no-cache, no-store, max-age=0, must-revalidate', 'content-length': '300', 'content-type': 'application/json', date: 'Tue, 29 Nov 2022 20:47:31 GMT', expires: '0', pragma: 'no-cache', 'strict-transport-security': 'max-age=31536000 ; includeSubDomains', 'www-authenticate': 'Bearer realm="example", error="invalid_token", error_description="The access token expired"', 'x-content-type-options': 'nosniff', 'x-frame-options': 'DENY', 'x-vcap-request-id': '9bc1cb85-97d5-45c9-6ae1-f94fb4a51b11', 'x-xss-protection': '1; mode=block', xh_fingerprint: '379fe1a5-27e6-466c-9401-1a947c91ba20' }, data: { timestamp: '2022-11-29T20:47:32.007Z', path: '/client/icontrol/delta', method: 'GET', fingerprint: '379fe1a5-27e6-466c-9401-1a947c91ba20', errorCode: 'CIMA_TOKEN_INVALID', exception: [Object] } } }

[rdeutsch3]

Update: It died again today and I caught it earlier than yesterday, somewhere less than 2h from when it died, but unfortunately the transition between working and not had already been lost. I'll see if I can catch the transition point in the logs, but am not super hopeful as I don't stare at the Apple Home app all the time.

[bloomkd46]

I have re-wrote the whole backend and testing it out. It is currently published as 3.0.0-beta.16. You are welcome to try it out to see if it fixes this error. I will likely be publishing it as the latest release later tomorrow assuming nothing goes wrong.

[rdeutsch3]

I've updated to the v3.0.0 release and so far so good. I suggest we close this and we can re-open or log a new one if it reoccurs.

What I will add I've turned on the Log Watch Dog Errors, and I'm seeing pretty regular: "Watchdog Error: Error: socket hang up" messages. I can provide those messages here, or in a separate issue, your call.

I've also got a several of "Unknown accessory! messages.... Please open an issue about this". They relate to all the sensors and a couple of other components. The alarm does arm and disarm. Shall I log them in one issue or separately for each component? Again, your call.

Thank you for all your efforts. I hope you have a Merry Christmas.

[bloomkd46]

What I will add I've turned on the Log Watch Dog Errors, and I'm seeing pretty regular: "Watchdog Error: Error: socket hang up" messages. I can provide those messages here, or in a separate issue, your call.

I've already seen them from my instance, the socket hang up error is basically it timing out, they are harmless and expected

I've also got a several of "Unknown accessory! messages.... Please open an issue about this". They relate to all the sensors and a couple of other components. The alarm does arm and disarm. Shall I log them in one issue or separately for each component? Again, your call.

Please open a separate issue for each type of accessory. (for example, the current plugin has motion sensors, doors, and windows)

Merry Christmas to you too.