Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Status does not go from Arming... to Armed. SSAPI timeout errors. #189

Closed
lmcquade opened this issue Feb 21, 2021 · 17 comments
Closed

Status does not go from Arming... to Armed. SSAPI timeout errors. #189

lmcquade opened this issue Feb 21, 2021 · 17 comments
Labels
bug Something isn't working unconfirmed Issue has not been verified

Comments

@lmcquade
Copy link
Contributor

lmcquade commented Feb 21, 2021

Describe The Bug:

After arming the system (using scene from home app) the status gets stuck as "Arming...". In the debug logs, I see repeated SSAPI reconnect attempts and timeouts from when homebridge starts.

To Reproduce:

Restart homebridge and homebridge-simplisafe3 in debug mode, watch log for SSAPI timeouts.

Expected behavior:

Status updates correctly. No SSAPI timeouts in log.

Environment:

  • Plugin version: homebridge-simplisafe3@1.6.17
  • Node.js Version: v15.9.0
  • NPM Version: 7.5.4
  • Homebridge Version: 1.3.0
  • Operating System: macOS

Homebridge Config:

{
    "name": "Home Alarm",
    "auth": {
        "username": "****",
        "password": "****"
    },
    "cameras": false,
    "debug": true,
    "sensorRefresh": 15,
    "persistAccessories": true,
    "resetSimpliSafeId": false,
    "cameraOptions": {
        "enableHwaccelRpi": false
    },
    "platform": "homebridge-simplisafe3.SimpliSafe 3"
},

Screenshots:

not applicable

Logs:

[2/21/2021, 11:46:31 AM] [Home Alarm] SSAPI socket reconnect_attempt #95
[2/21/2021, 11:46:51 AM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 11:46:51 AM] [Home Alarm] SSAPI socket connect_timeout
[2/21/2021, 11:46:56 AM] [Home Alarm] SSAPI socket reconnect_attempt #96
[2/21/2021, 11:47:16 AM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 11:47:16 AM] [Home Alarm] SSAPI socket connect_timeout
[2/21/2021, 11:47:21 AM] [Home Alarm] SSAPI socket reconnect_attempt #97
[2/21/2021, 11:47:41 AM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 11:47:41 AM] [Home Alarm] SSAPI socket connect_timeout
@lmcquade lmcquade added bug Something isn't working unconfirmed Issue has not been verified labels Feb 21, 2021
@shamoon
Copy link
Collaborator

shamoon commented Feb 21, 2021

Hi @lmcquade , as you said the logs suggest you’re not able to connect to SS servers. Yes, if you can’t connect successfully then changing the alarm state etc won’t work. The log output after first startup of homebridge might be helpful too. Have you verified if you can use the SS app/website when the plug-in is unable to connect?

@lmcquade
Copy link
Contributor Author

Hi @shamoon, thank you for looking at this!

I am able to connect to the SS website from my computer, the SS app on my phone, and from homebridge. Setting the alarm state works, it just doesn't update the status correctly. Here relevant log output from the startup of homebridge:

[2/21/2021, 12:53:25 PM] [HB Supervisor] Starting Homebridge with extra flags: -I -D
[2/21/2021, 12:53:25 PM] [HB Supervisor] Started Homebridge v1.3.0 with PID: 42605
Initializing HAP-NodeJS v0.9.1...
[2/21/2021, 12:53:27 PM] ---
[2/21/2021, 12:53:28 PM] Loaded plugin: homebridge-simplisafe3@1.6.17
[2/21/2021, 12:53:28 PM] Registering platform 'homebridge-simplisafe3.SimpliSafe 3'
[2/21/2021, 12:53:28 PM] ---
[2/21/2021, 12:53:28 PM] [Home Alarm] Initializing homebridge-simplisafe3.SimpliSafe 3 platform...
[2/21/2021, 12:53:28 PM] [Home Alarm] Configure existing accessory 'Front Door' (uuid <redacted>)
[2/21/2021, 12:53:28 PM] [Home Alarm] Found 27 cached accessories being configured
Preparing Advertiser for 'Homebridge CAD8' using ciao backend!
Starting to advertise 'Homebridge CAD8' using ciao backend!
[2/21/2021, 12:53:28 PM] Homebridge v1.3.0 (Homebridge) is running on port 51826.
Initializing HAP-NodeJS v0.9.1...
[2/21/2021, 12:53:29 PM] [Home Alarm] Logged in!
[2/21/2021, 12:53:29 PM] [Home Alarm] Refreshing accessories (add and remove: false)
[2/21/2021, 12:53:30 PM] [Home Alarm] Alarm not found, adding...
[2/21/2021, 12:53:30 PM] [Home Alarm] Discovered sensor 'Front Door' from SimpliSafe.
[2/21/2021, 12:53:30 PM] [Home Alarm] {
  serial: '<redacted>',
  type: 1,
  status: {},
  name: 'Front Door',
  deviceGroupID: 0,
  setting: { lowPowerMode: false, alarm: 1 },
  flags: { swingerShutdown: false, lowBattery: false, offline: false }
}
[2/21/2021, 12:53:31 PM] [Home Alarm] Found device 'SimpliSafe 3'
[2/21/2021, 12:53:31 PM] [Home Alarm] Refreshing alarm state
[2/21/2021, 12:53:31 PM] [Home Alarm] Found device 'Front Door'
[2/21/2021, 12:53:31 PM] [Home Alarm] Refreshing sensor state
[2/21/2021, 12:53:31 PM] [Home Alarm] Updated current state for SimpliSafe 3: OFF
[2/21/2021, 12:53:31 PM] [Home Alarm] Updated current state for Front Door: false, false
[2/21/2021, 12:53:31 PM] [Home Alarm] Refreshing accessories (add and remove: true)
[2/21/2021, 12:53:31 PM] [Home Alarm] Discovered sensor 'Front Door' from SimpliSafe.
[2/21/2021, 12:53:31 PM] [Home Alarm] {
  serial: '<redacted>',
  type: 1,
  status: {},
  name: 'Front Door',
  deviceGroupID: 0,
  setting: { lowPowerMode: false, alarm: 1 },
  flags: { swingerShutdown: false, lowBattery: false, offline: false }
}
[2/21/2021, 12:53:50 PM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 12:53:50 PM] [Home Alarm] SSAPI socket connect_timeout
[2/21/2021, 12:53:51 PM] [Home Alarm] SSAPI socket reconnect_attempt #1
[2/21/2021, 12:54:12 PM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 12:54:12 PM] [Home Alarm] SSAPI socket connect_timeout
[2/21/2021, 12:54:13 PM] [Home Alarm] SSAPI socket reconnect_attempt #2
[2/21/2021, 12:54:33 PM] [Home Alarm] SSAPI socket connect_error: timeout
[2/21/2021, 12:54:33 PM] [Home Alarm] SSAPI socket connect_timeout
[2/21/2021, 12:54:35 PM] [Home Alarm] SSAPI socket reconnect_attempt #3

@shamoon
Copy link
Collaborator

shamoon commented Feb 21, 2021

Yes I meant that the socket connection is what listens for events to actually update HomeKit that an event happened (e.g. arming alarm etc).

Its definitely weird, and not something I can reproduce ATM and haven't quite seen this before. Was it previously working and then stopped or have you never gotten past this point? Also since the SS API has been known to temporarily block IPs (though the plugin has logic to try and detect this) have you tried turning it off for a few hours or even a full day?

@lmcquade
Copy link
Contributor Author

It feels like it has been this way for a couple months, but since it arms and disarms correctly I didn't dig into it until now. I'll try disabling the plugin for a while to see if it helps.

@lmcquade
Copy link
Contributor Author

Still get SSAPI timeouts after leaving it disabled for several hours. It looks like only the socket.io calls are failing. Other queries seem to be working fine.

@shamoon
Copy link
Collaborator

shamoon commented Feb 22, 2021

Yea was a bit of a shot in the dark. It’s definitely odd that you can authenticate and reach the API in other ways. Anything about your network that could explain? Looks like it’s just timing out after 20s. Have you tried on a different machine? Checked your firewall? Again just kinda troubleshooting as I don’t see an obvious explanation.

@lmcquade
Copy link
Contributor Author

lmcquade commented Feb 22, 2021

The connections I see going to api.simplisafe.com through my firewall occur every 15 seconds (which seems to line up with sensorRefresh interval). I don't see any evidence of the socket.io attempts, which happen every 20-30sec.

PR        DIR SRC                           DEST                                   STATE                AGE       EXP     PKTS    BYTES
tcp       In  192.168.10.4:49603            34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:01:33  00:00:01       40    16980
tcp       Out <redacted>:18903              34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:01:33  00:00:01       40    16980
tcp       In  192.168.10.4:49617            3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:01:18  00:00:20       39    16928
tcp       Out <redacted>:25039              3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:01:18  00:00:20       39    16928
tcp       In  192.168.10.4:49626            34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:01:03  00:00:31       40    16980
tcp       Out <redacted>:63686              34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:01:03  00:00:31       40    16980
tcp       In  192.168.10.4:49653            3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:00:48  00:00:48       37    16860
tcp       Out <redacted>:36364              3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:00:48  00:00:48       37    16860
tcp       In  192.168.10.4:49667            34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:00:33  00:01:05       36    16820
tcp       Out <redacted>:33259              34.239.5.154:443                TIME_WAIT:TIME_WAIT    00:00:33  00:01:05       36    16820
tcp       In  192.168.10.4:49681            3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:00:17  00:01:16       36    16820
tcp       Out <redacted>:12371              3.220.241.248:443               TIME_WAIT:TIME_WAIT    00:00:17  00:01:16       36    16820
tcp       In  192.168.10.4:49688            3.232.188.126:443             ESTABLISHED:ESTABLISHED  00:00:02  23:59:58       18     7437
tcp       Out <redacted>:45200              3.232.188.126:443             ESTABLISHED:ESTABLISHED  00:00:02  23:59:58       18     7437

I don't think it is a firewall issue. Both kinds of messages are sent to api.simplisafe.com:443, right? They should look identical from the firewall's perspective. Next task is to look on the server machine for any evidence of the messages getting dropped.

@lmcquade
Copy link
Contributor Author

lmcquade commented Feb 22, 2021

socket.io-client and engine.io-client debug messages unfortunately don't shed much more light on this:

2021-02-22T09:23:41.953Z socket.io-client:url parse https://api.simplisafe.com/v1/user/<redacted>
2021-02-22T09:23:41.954Z socket.io-client new io instance for https://api.simplisafe.com/v1/user/<redacted>
2021-02-22T09:23:41.955Z socket.io-client:manager readyState closed
2021-02-22T09:23:41.955Z socket.io-client:manager opening https://api.simplisafe.com/v1/user/<redacted>
2021-02-22T09:23:41.955Z engine.io-client:socket creating transport "websocket"
2021-02-22T09:23:41.959Z engine.io-client:socket setting transport websocket
2021-02-22T09:23:41.959Z socket.io-client:manager connect attempt will timeout after 20000
2021-02-22T09:23:41.960Z socket.io-client:manager readyState opening
2021-02-22T09:24:02.030Z socket.io-client:manager connect attempt timed out after 20000
2021-02-22T09:24:02.031Z engine.io-client:socket socket close with reason: "forced close"
2021-02-22T09:24:02.031Z engine.io-client:socket socket closing - telling transport to close
2021-02-22T09:24:02.032Z socket.io-client:manager connect_error
2021-02-22T09:24:02.032Z socket.io-client:manager cleanup
2021-02-22T09:24:02.033Z socket.io-client:manager will wait 986ms before reconnect attempt
2021-02-22T09:24:03.090Z socket.io-client:manager attempting reconnect
...

@shamoon
Copy link
Collaborator

shamoon commented Feb 22, 2021

Just going on the fact that this works fine for every other user of the plugin makes me think its an issue with your machine / network which is why I was asking about whether you've tried another host and / or outside your network? Only other thing that might make sense would be an issue with the socket-io client but I haven't found anything obvious looking around. So Im left with recommending process-of-elimination... 🤷🏽‍♂️

@lmcquade
Copy link
Contributor Author

I agree, it is strange. I tend to think it is something strange with socket.io on my machine. I'll keep looking in my spare time.

I don't know that I am the only one with this issue. Sounds identical to #166.

@shamoon
Copy link
Collaborator

shamoon commented Feb 22, 2021

That issue could be the same but really no idea.

Agreed I’d poke around with socket.io, maybe try different version(s) but again, my first thing would be to try a different machine and then a machine outside my network.

Please do report back if you figure anything out, sorry I can’t really help more without being able to reproduce/an obvious way to investigate more

@lmcquade
Copy link
Contributor Author

lmcquade commented Feb 23, 2021

It starts working if I roll back to socket.io-client@2.1.1:

[2/22/2021, 6:02:06 PM] [Home Alarm] Initializing homebridge-simplisafe3.SimpliSafe 3 platform...
[2/22/2021, 6:02:06 PM] [Home Alarm] Configure existing accessory 'SimpliSafe 3' (uuid <redacted>)
...
[2/22/2021, 6:02:07 PM] [Home Alarm] Logged in!
[2/22/2021, 6:02:07 PM] [Home Alarm] Refreshing accessories (add and remove: false)
[2/22/2021, 6:02:09 PM] [Home Alarm] Alarm not found, adding...
2021-02-23T02:02:09.370Z socket.io-client:url parse https://api.simplisafe.com/v1/user/<redacted>
2021-02-23T02:02:09.371Z socket.io-client ignoring socket cache for https://api.simplisafe.com/v1/user/<redacted>
2021-02-23T02:02:09.371Z socket.io-client:manager readyState closed
2021-02-23T02:02:09.371Z socket.io-client:manager opening https://api.simplisafe.com/v1/user/<redacted>
2021-02-23T02:02:09.375Z socket.io-client:manager connect attempt will timeout after 20000
2021-02-23T02:02:09.376Z socket.io-client:manager readyState opening
2021-02-23T02:02:09.726Z socket.io-client:manager open
2021-02-23T02:02:09.726Z socket.io-client:manager cleanup
2021-02-23T02:02:09.726Z socket.io-client:socket transport is open - connecting
2021-02-23T02:02:09.726Z socket.io-client:socket sending connect packet with query ns=%2Fv1%2Fuser%2F<redacted>&accessToken=<redacted>%2FE%3D
2021-02-23T02:02:09.727Z socket.io-client:manager writing packet {"type":0,"query":"ns=%2Fv1%2Fuser%2F<redacted>&accessToken=<redacted>%2FE%3D","nsp":"/v1/user/<redacted>"}
2021-02-23T02:02:09.812Z socket.io-client:socket emitting event ["confirm-registered",["<redacted>"]]
[2/22/2021, 6:02:09 PM] [Home Alarm] SSAPI socket connected
[2/22/2021, 6:02:09 PM] [Home Alarm] Alarm now listening for real time events.

@lmcquade
Copy link
Contributor Author

lmcquade commented Feb 23, 2021

Going from socket.io-client@2.1.1 to socket.io-client@2.2.0, we jump from ws@3.3.1 all the way ws@6.1.2. Bisecting ws, I found that it stops working going from ws@5.0.0 to ws@5.1.0.

websockets/ws@5.0.0...5.1.0

@shamoon
Copy link
Collaborator

shamoon commented Feb 23, 2021

Very interesting, appreciate all the work. Thing is, Im not sure what to do with this. Its still quite odd to me others aren't seeing this (at least not in huge numbers). Im a little hesitant to downgrade the package. The other odd thing is this works fine on my Mac (my main testing machine in fact).

@lmcquade
Copy link
Contributor Author

I agree it is odd, and downgrading doesn't seem like a great option. I am on MacOS Catalina 10.15.7, if that makes a difference. Also, other modules on my system, like homebridge-config-ui-x are successfully using newer versions of ws. Here is the current script I use to get it to work:

npm install -g homebridge-simplisafe3
cd /usr/local/lib/node_modules/homebridge-simplisafe3
npm install socket.io-client@v2-latest
cd /usr/local/lib/node_modules/homebridge-simplisafe3/node_modules/engine.io-client
npm install ws@5.0.0

@shamoon
Copy link
Collaborator

shamoon commented Feb 24, 2021

Yea Im on Big Sur. Still very odd. Wish I could reproduce on my end so I could dig in further, thanks for sharing and all the investigating.

@lmcquade
Copy link
Contributor Author

Finally got VSCode setup to debug into node.js stuff, and was able to track down the issue. PR #191

The issue appears to be that socket.io sets pfx to null if it is undefined. Unfortunately, as of node v15.3.0, the https code explicitly checks against pfx === undefined. It fails because null is not a valid pfx. Until socket.io is fixed, the workaround is to set pass in pfx as [].

More info about this issue here: nodejs/node#36292

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working unconfirmed Issue has not been verified
Projects
None yet
Development

No branches or pull requests

2 participants