HTTP Status 500 Internal Server Errors followed by no zone players found

[dsuttles]

homebridge.zp.log

Issue

Large SONOS system. Was working fine until recently, but now I see a bunch of 500 errors followed by no zone players found. Hopefully debug log helps with troubleshooting.

Log Messages

[Sonos] error: RINCON_347E5C7F2F2501400 [192.168.1.38]: http status 500 Internal Server Error
[Sonos] warning: no zone players found

Debug Files

homebridge.log.gz

[dsuttles]

I setup an entirely new homebridge instance today on a Raspberry Pi instead of my Mac Pro... the resulting problem and errors are identical.

[dsuttles]

A bit more log info as time goes on. These requests continue successfully (errors are only at the start) - other than the warning that no zone players are found.

[6/12/2021, 10:43:58 PM] [Sonos] RINCON_48A6B8692F5501400 [192.168.1.216]: request 12: SUBSCRIBE /ZoneGroupTopology/Event
[6/12/2021, 10:43:58 PM] [Sonos] RINCON_48A6B8692F5501400 [192.168.1.216]: request 12: status 200 OK
[6/12/2021, 10:44:27 PM] [Sonos] warning: no zone players found

[ebaauw]

Thanks. I don't see the listening on http://0.0.0.0:port/notify (normal) log message that Homebridge ZP's web server (to receive zone player notifications) has been started. Also, the error messages don't show which request caused the error (damn), but it looks like the GetZoneGroupState is failing? I think there might be something wrong in the Homebridge ZP startup logic, causing it not to handle this (unexpected) error correctly.

Could you try zp -H 192.168.1.38 info? If that also shows an error, could you please capture and attach the output of zp -DDD -H 192.168.1.38 info?

Apologies for the dummy check: but the players do show correctly in the Sonos app?

EDIT: Managed to reproduce this behaviour. The GetZoneGroupState fails when the number of zone players in the household is too large. Homebridge ZP should try a ZoneGroupTopology event subscription as fallback, but this is failing.

[ebaauw]

Could you try beta v1.3.1-0?

[dsuttles]

Looks like we are back in business. The relevant log output looks like this (just showing for one of the SONOS IP addresses):

[6/13/2021, 8:43:07 AM] [Sonos] Initializing ZP platform...
[6/13/2021, 8:43:07 AM] [Sonos] homebridge-zp v1.3.1-0, node v14.17.0, homebridge v1.3.4, homebridge-lib v5.1.5
[6/13/2021, 8:43:07 AM] [Sonos] config.json: {"name":"Sonos","brightness":true,"excludeAirPlay":true,"leds":false,"service":"switch","speakers":false,"tv":true,"platform":"ZP"}
[6/13/2021, 8:43:07 AM] [Sonos] config: {"nameScheme":"% Sonos","maxFavourites":96,"port":0,"resetTimeout":500,"subscriptionTimeout":1800,"timeout":15,"tvIdPrefix":"TV","name":"Sonos","brightness":true,"excludeAirPlay":true,"leds":false,"service":"switch","speakers":false,"tv":true,"platform":"ZP"}
[6/13/2021, 8:43:07 AM] [Sonos] SpeakerService: "00000049-0000-1000-8000-0026BB765291"
[6/13/2021, 8:43:07 AM] [Sonos] VolumeCharacteristic: "00000008-0000-1000-8000-0026BB765291"
[6/13/2021, 8:43:07 AM] [Sonos] Office: cached Master v1.3.0 RINCON_347E5C7F2F2501400: {"name":"Office","id":"RINCON_347E5C7F2F2501400","address":"192.168.1.38"}
[6/13/2021, 8:43:07 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: probing (1 jobs)...
[6/13/2021, 8:43:07 AM] [Sonos] starting heartbeat for ["ZpPlatform"]
[6/13/2021, 8:43:07 AM] [Sonos] restored 1 accessories from cache
[6/13/2021, 8:43:08 AM] [Sonos] upnp: listening on 0.0.0.0:1900
[6/13/2021, 8:43:08 AM] [Sonos] upnp: searching on 0.0.0.0:52270
[6/13/2021, 8:43:08 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 1: GET /xml/device_description.xml
[6/13/2021, 8:43:08 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 1: status 200 OK
[6/13/2021, 8:43:08 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 2: POST /ZoneGroupTopology/Control GetZoneGroupState
[6/13/2021, 8:43:08 AM] [Sonos] warning: RINCON_347E5C7F2F2501400 [192.168.1.38]: request 2: http status 500 Internal Server Error
[6/13/2021, 8:43:08 AM] [Sonos] listening on http://0.0.0.0:51886/notify
[6/13/2021, 8:43:08 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 3: SUBSCRIBE /ZoneGroupTopology/Event
[6/13/2021, 8:43:08 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 3: status 200 OK
[6/13/2021, 8:43:11 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: notify ZoneGroupTopology/Event
[6/13/2021, 8:43:11 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 4: UNSUBSCRIBE /ZoneGroupTopology/Event
[6/13/2021, 8:43:11 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: request 4: status 200 OK
[6/13/2021, 8:43:11 AM] [Sonos] RINCON_347E5C7F2F2501400 [192.168.1.38]: Office: Sonos Playbar (S9) v13.1.1

[ebaauw]

In v1.3.1