Latest version is throwing InitTopology error (again)

[JeffGoldner]

Issue

As the log message shows. I think this is something that had been fixed before but it's back.

Log Messages

[12/6/2021, 10:26:50 AM] [Sonos] error: RINCON_B8E937BA3CC801400: [192.168.1.12]: SyntaxError: initTopology() not yet called
at ZpClient.checkInitTopology (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:528:13)
at ZpClient.get bootSeq [as bootSeq] (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:594:10)
at ZpPlatform.heartbeat (/homebridge/node_modules/homebridge-zp/lib/ZpPlatform.js:148:42)
at ZpPlatform.emit (node:events:390:28)
at ZpPlatform.emit (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Delegate.js:174:13)
at ZpPlatform._heartbeat (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:317:10)
at ZpPlatform._beat (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:305:42)
at Timeout._onTimeout (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:295:12)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)

Debug Files

homebridge.log.txt.zip

[ebaauw]

Looks like this concerns the LS speaker of the Family Room. It used to work normally, but then starts acting up:

[12/3/2021, 9:09:29 PM] [Sonos] RINCON_B8E937BA3CC801400 [Family Room (LS)]: lastSeen: Fri Dec 03 2021 20:55:20, 850s ago at 192.168.1.12, bootSeq: 180
[12/4/2021, 1:54:29 AM] [Sonos] RINCON_B8E937BA3CC801400 [Family Room (LS)]: lastSeen: Sat Dec 04 2021 01:40:19, 851s ago at 192.168.1.12, bootSeq: 180
[12/4/2021, 5:54:29 AM] [Sonos] RINCON_B8E937BA3CC801400 [Family Room (LS)]: lastSeen: Sat Dec 04 2021 05:40:20, 850s ago at 192.168.1.12, bootSeq: 180
[12/4/2021, 2:54:29 PM] [Sonos] RINCON_B8E937BA3CC801400 [Family Room (LS)]: lastSeen: Sat Dec 04 2021 14:40:23, 847s ago at 192.168.1.12, bootSeq: 180

After restarting Homebridge ZP, it's missing from the overview at 8:46:20 PM, but apparently comes online 10 minutes later. You're not running Homebridge in DEBUG mode, so I cannot tell whether it's discovered though UPnP or reported through another zone player. However, the first request (getting description.xml from the player) succeeds, but subscribing to the ZoneGoupTopology fails, causing the SyntaxError:

[12/5/2021, 8:55:46 PM] [Sonos] RINCON_B8E937BA3CC801400 [192.168.1.12]: request 2: SUBSCRIBE /ZoneGroupTopology/Event
[12/5/2021, 8:55:46 PM] [Sonos] warning: RINCON_B8E937BA3CC801400 [192.168.1.12]: request 2: timeout after 15 seconds
[12/5/2021, 8:56:01 PM] [Sonos] warning: RINCON_B8E937BA3CC801400 [192.168.1.12]: no ZoneGroupTopology event received in 15s
[12/5/2021, 8:56:01 PM] [Sonos] error: SyntaxError: initTopology() not yet called
    at ZpClient.checkInitTopology (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:528:13)
    at ZpClient.get zonePlayers [as zonePlayers] (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:912:10)
    at ZpPlatform.parseZones (/homebridge/node_modules/homebridge-zp/lib/ZpPlatform.js:332:31)
    at ZpPlatform.createZpClient (/homebridge/node_modules/homebridge-zp/lib/ZpPlatform.js:299:18)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at ZpPlatform.handleUpnpMessage (/homebridge/node_modules/homebridge-zp/lib/ZpPlatform.js:186:24)

This is a bug in Homebidge ZP alright, in that it doesn't handle this case correctly. It's going to be very hard to reproduce this issue and test for it, though. Homebridge ZP keeps the uninitialised client for the zone player, reporting every 5 minutes on it's reachability. Or rather trying to, as this fails due to the client not being initialised:

[12/5/2021, 9:31:50 PM] [Sonos] error: RINCON_B8E937BA3CC801400: [192.168.1.12]: SyntaxError: initTopology() not yet called
    at ZpClient.checkInitTopology (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:528:13)
    at ZpClient.get bootSeq [as bootSeq] (/homebridge/node_modules/homebridge-zp/lib/ZpClient.js:594:10)
    at ZpPlatform.heartbeat (/homebridge/node_modules/homebridge-zp/lib/ZpPlatform.js:148:42)
    at ZpPlatform.emit (node:events:390:28)
    at ZpPlatform.emit (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Delegate.js:174:13)
    at ZpPlatform._heartbeat (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:317:10)
    at ZpPlatform._beat (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:305:42)
    at Timeout._onTimeout (/homebridge/node_modules/homebridge-zp/node_modules/homebridge-lib/lib/Platform.js:295:12)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7)

(note the different call stack from the first error). Not sure if this is a bug in itself, there shouldn't be any unintialised client if the previous case would have been handled correctly.

I'm still not sure what's the matter with the surround speaker. Does the Sonos app show it missing as well? What happens if you power-cycle the speaker? I'm afraid Homebridge ZP might not recover from the un-initialised client, even when the player does come online fully, but restarting Homebridge ZP after that should get rid of the errors.

I'm also puzzled that there's 7 zones in your household, but only 5 were persisted by Homebridge ZP.

[12/5/2021, 8:46:20 PM] [Sonos] found 1 households
[12/5/2021, 8:46:20 PM] [Sonos] Sonos_aqsBYUjH6wqRs1NHlyNYcEle1j: RINCON_000E58B5315201400 [192.168.1.63]: associated S1 zoneplayer
[12/5/2021, 8:46:20 PM] [Sonos] Sonos_aqsBYUjH6wqRs1NHlyNYcEle1j: found 10 S1 zone players in 7 zones

[12/5/2021, 8:46:19 PM] [Sonos] restored 5 accessories from cache

Did you add new players or change the home theatre setup?

[JeffGoldner]

No changes to the equipment in the house. But the RS speaker was missing in the Sonos Controller. I have power cycled it and it seems to be back now and errors resolved. For good, measure I cycled the HB container as well:

[12/8/2021, 10:51:44 AM] [Sonos] warning: RINCON_7828CA73966C01400 [Boost]: no ZoneGroupTopology event received in 15s
[12/8/2021, 10:51:45 AM] [Sonos] warning: RINCON_5CAAFD0EBD8A01400 [Sonos Garage]: no ZoneGroupTopology event received in 15s
[12/8/2021, 10:51:45 AM] [Sonos] found 1 households
[12/8/2021, 10:51:45 AM] [Sonos] Sonos_aqsBYUjH6wqRs1NHlyNYcEle1j: RINCON_000E58B5315201400 [192.168.1.63]: associated S1 zoneplayer
[12/8/2021, 10:51:45 AM] [Sonos] Sonos_aqsBYUjH6wqRs1NHlyNYcEle1j: found 11 S1 zone players in 7 zones
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Boost (invisible)
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_7828CA73966C01400 [Boost]: Sonos Boost (BR200) (master)
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Deck (L+R)
[12/8/2021, 10:51:45 AM] [Sonos] │ ├─ RINCON_B8E93759102001400 [Deck (L)]: Sonos Play:1 (S1) (master)
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_B8E93758F74401400 [Deck (R)]: Sonos Play:1 (S1) (slave)
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Family Room (+LS+RS)
[12/8/2021, 10:51:45 AM] [Sonos] │ ├─ RINCON_5CAAFDAB504D01400 [Family Room]: Sonos Playbar (S9) (master, tvIn)
[12/8/2021, 10:51:45 AM] [Sonos] │ ├─ RINCON_B8E937BA3CC801400 [Family Room (LS)]: Sonos Play:1 (S1) (satellite)
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_B8E937BA343A01400 [Family Room (RS)]: Sonos Play:1 (S1) (satellite)
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Kitchen (L+R)
[12/8/2021, 10:51:45 AM] [Sonos] │ ├─ RINCON_000E5888AC6201400 [Kitchen (L)]: Sonos Play:5 (S5) (master, audioIn)
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_000E585C325C01400 [Kitchen (R)]: Sonos Play:5 (S5) (slave, audioIn)
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Living Room
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_000E58A0176C01400 [Living Room]: Sonos Connect (ZP90) (master, audioIn)
[12/8/2021, 10:51:45 AM] [Sonos] ├─ Master Bedroom
[12/8/2021, 10:51:45 AM] [Sonos] │ └─ RINCON_000E58B5315201400 [Master Bedroom]: Sonos Playbar (S9) (master, tvIn)
[12/8/2021, 10:51:45 AM] [Sonos] └─ Sonos Garage
[12/8/2021, 10:51:45 AM] [Sonos] └─ RINCON_5CAAFD0EBD8A01400 [Sonos Garage]: Sonos Play:5 (S6) (master, airPlay, audioIn)
[12/8/2021, 10:51:45 AM] [Sonos] Deck Sonos: set Status Fault from 0 to 1
[12/8/2021, 10:51:45 AM] [Sonos] Family Room Sonos: set Status Fault from 0 to 1
[12/8/2021, 10:51:45 AM] [Sonos] Kitchen Sonos: set Status Fault from 0 to 1
[12/8/2021, 10:51:45 AM] [Sonos] Living Room Sonos: set Status Fault from 0 to 1
[12/8/2021, 10:51:45 AM] [Sonos] Master Bedroom Sonos: set Status Fault from 0 to 1
[12/8/2021, 10:51:45 AM] [Sonos] Master Bedroom Sonos: set Status Fault from 1 to 0
[12/8/2021, 10:51:45 AM] [Sonos] Family Room Sonos: set Status Fault from 1 to 0
[12/8/2021, 10:51:45 AM] [Sonos] Deck Sonos: set Status Fault from 1 to 0
[12/8/2021, 10:51:45 AM] [Sonos] Living Room Sonos: set Status Fault from 1 to 0
[12/8/2021, 10:51:45 AM] [Sonos] Kitchen Sonos: set Status Fault from 1 to 0

Looks good, not urgent to fix the above.

[Tyraenor]

I tried to install the previous version to get rid of this bug and this somehow removed all plugins of my homebridge except of yours. Now all my stuff in Homekit is gone I am starting from scratch as HomeKit removed all accessories and added them as new ones...

So please get rid of this bug...

[ebaauw]

Yesterday, I received an update of the Sonos app, including an upgrade of the zone player firmware. It took the app several attempts to upgrade all players.

This caused all sorts of initTopology errors, and I don't think the subscriptions where restored properly. I suspect a zone player might reboot more than once during a firmware upgrade, or maybe announces itself before it's fully ready. On zones with multilple players (stereo pairs, home theatre setups), the master zone player might become available before the slaves or satellites (or maybe the upgrade of the slaves / satellites only starts after the master has been upgraded?).

Restarting Homebridge ZP (a couple of times) eventually got rid of all errors.

Anyways, it might be prudent to monitor for firmware upgrades, and suspend Homebridge ZP while they're happening. Also, I need to review the re-connect logic after reboot.