I recently migrated from OH3.4.5 to OH4.0.4 and have issues with the sonos binding & my sonos move.
The thing is ONLINE, but all linked items only showing UNDEF
The same device is still working with OH3.4.5. With OH4.0.4 I do not have any errors in the log file.
Below the debug log, if I disable / enable the thing.
Appreciate any help to get this working again
2023-12-02 18:26:48.627 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Handler disposed for thing sonos:Move:RINCON_C438752586EC01400
2023-12-02 18:26:48.630 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service DeviceProperties...
2023-12-02 18:26:48.633 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service AVTransport...
2023-12-02 18:26:48.636 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service ZoneGroupTopology...
2023-12-02 18:26:48.640 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service GroupManagement...
2023-12-02 18:26:48.644 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service RenderingControl...
2023-12-02 18:26:48.649 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service AudioIn...
2023-12-02 18:26:48.654 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service HTControl...
2023-12-02 18:26:48.655 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Unsubscribing from service ContentDirectory...
==> /var/log/openhab/events.log <==
2023-12-02 18:26:48.611 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Move:RINCON_C438752586EC01400' changed from ONLINE to UNINITIALIZED
2023-12-02 18:26:48.672 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Move:RINCON_C438752586EC01400' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
==> /var/log/openhab/openhab.log <==
2023-12-02 18:26:50.904 [DEBUG] [g.sonos.internal.SonosHandlerFactory] - Creating a ZonePlayerHandler for thing 'sonos:Move:RINCON_C438752586EC01400' with UDN 'RINCON_C438752586EC01400'
2023-12-02 18:26:50.908 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Creating a ZonePlayerHandler for thing 'sonos:Move:RINCON_C438752586EC01400'
2023-12-02 18:26:50.947 [DEBUG] [s.internal.handler.ZonePlayerHandler] - initializing handler for thing sonos:Move:RINCON_C438752586EC01400
2023-12-02 18:26:50.949 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-12-02 18:26:50.960 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_C438752586EC01400 has been found in local network
2023-12-02 18:26:50.961 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service DeviceProperties...
2023-12-02 18:26:50.964 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service AVTransport...
2023-12-02 18:26:50.966 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service ZoneGroupTopology...
2023-12-02 18:26:50.970 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service GroupManagement...
2023-12-02 18:26:50.973 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service RenderingControl...
2023-12-02 18:26:50.975 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service AudioIn...
2023-12-02 18:26:50.977 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service HTControl...
2023-12-02 18:26:50.978 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscribing to service ContentDirectory...
2023-12-02 18:26:50.982 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service AVTransport succeeded
2023-12-02 18:26:50.985 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service DeviceProperties succeeded
2023-12-02 18:26:50.993 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service GroupManagement succeeded
2023-12-02 18:26:50.994 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service ZoneGroupTopology succeeded
2023-12-02 18:26:51.002 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service RenderingControl succeeded
2023-12-02 18:26:51.004 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_C438752586EC01400: Subscription to service ContentDirectory succeeded
==> /var/log/openhab/events.log <==
2023-12-02 18:26:50.938 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Move:RINCON_C438752586EC01400' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2023-12-02 18:26:50.963 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Move:RINCON_C438752586EC01400' changed from INITIALIZING to ONLINE
I found out that changing an item in OH will successfully send a command to the sonos device (e.g. changing volume in OH will change the actual volume at the device) but vice versa (changing the volume via sonos app or at the device) the status get not updated in OH
changing the logging to trace level gives me the following output:
Your OH server runs on what OS ? Are you using docker ?
Did you check the file events.log when you say items are not updated ?
Are you sure your channel links are correct?
No docker, no subnets.
Thing, items and channel links defined via gui. Also sending command from item to device is working, but not updating the item based on the device status, therefore I assume channel links are correct. If there is something specific I can check
If I start my backup from OH3.4.5 on my laptop it’s also working fine, therefore not expecting an issue on sonos itself.
First check events.log to confirm items are really not updated.
I would like to be sure you are not facing a UI problem.
Does it work well for other Sonos devices ?
Please check what is your thing type for the Move.
Nothing changed in OH 4 that should impact the Sonos binding and the binding is working very well for all of us (except few users running in docker with a wrong setup).
Yes, the items are not updating / only updating to UNDEF as per events.log
I use frontail to monitor both events.log and openhab.log and their can validate this.
I only have 1 Sonos device (Move 1st gen), therefore cannot test with a 2nd device.
The thing is sonos:Move:RINCON_C438752586EC01400
I’m a bit surprised that I don’t see any error message in the log, even I set the log level to trace.
If you have sonos devices, can you maybe post your log and I can check if I’m e.g. missing certain log messages?
When setting the log level to trace, I got the following message in events.log
==> /var/log/openhab/events.log <==
2023-12-04 18:48:29.228 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Move:RINCON_C438752586EC01400' changed from ONLINE to UNINITIALIZED
However within GUI → things the related thing is still listed as online, even the log does not contain any message, that the thing will go back to online.
When changing the volume via app afterwards I do not see any additional log message.
Only some time later I see messages regarding the regular polling:
I have installed a fresh OH 4.0.4 on my windows laptop and the Sonos binding is working fine.
Therefore the issue definitively must be related to the installation on my rpi3.
I am aware of the subnet/TTL issue, but don’t using subnets. Are there any other settings you would recommend to validate?
The installation is based on openhabian and just 1 or 2 weeks old. I have not applied any changes to the OS besides running updates and installing mqtt & zigbee2mqtt
