I have a pair of play:1 devices I’d like to play notification sounds on using my openhab2 (raspbian) system. Reading up on the basics, I found that the first step is to try and play some audio using the console interface, so running “openhab-cli console” I try to play the default doorbell.mp3. If the play:1 is inactive, I don’t notice any response when I try to play the doorbell.mp3. With the play:1 playing some music (tuneIn radio) I notice that something is happening as the master volume quickly goes up and then is muted (and stays muted) when I play the sample. But I don’t hear the doorbell sound.
openhab> log:set TRACE org.openab.binding.sonos
openhab> smarthome:audio play sonos:PLAY1:RINCON_94xxD922xx doorbell.mp3 50
The logs are not helping me much though, all it shows is (next to some occasional status updates)
Tried it on my system in order to check your problem and I am as well get no sound out of the sonos boxes!
I am on openHAB 2.5.1
Obviously I haven’t used that part of my installation for a long time!
If you really see that the volume goes to zero you should check your setting of the volume for announcements ( config section of each sonos thing). My volume changes to setting I have set there.
Hi Jürgen,
Thanks for verifying that it is not just my system setup. The default notification volume setting is at 50%. That might be the short initial volume increase I noticed when tune-in radio was playing. I tried both with and without specifying the notification volume in the console command. I didn’t notice any difference in behaviour. Do you also see the null URL popping up in the logs?
Hmmm, could well be unrelated of course. I am running openhab for some time now but I’m not sure I ever really tried to play a notification over the Sonos speakers before though. So I am not sure if it is also related to the 2.5 update I did a few months back or if there was already an issue before. I guess I will have to look at the code to see why it puts that line in the logs.
I just tested the feature and I can tell you that it still works.
But the first time I tried it did not work until I first played something on my Sonos device. It seems that the Sonos device was in a “strange” state.
Still trying to get a sound or voice played, I do see the player switching from the normal volume to the one set for announcements, the played music stops and after the 20 seconds all is set back to normal/playing.
I have limited the volume via the sonos app, would that cause an issue?
Tried it with “web audio”, working that way, so my problem seems to be somewhere with the usage of the sonos binding.
@Eric1974: If you select the audio sink “web audio” as default the sound should be played on the device you are actually using. I wonder if the URL null is reported that way as well.
I just tested with webaudio (@opus thanks for the tip) and that plays an audio doorbell sound on my computer.
No logging is generated but give that is a log from the ZonePlayerHandler I didn’t really expect one either. I just realized I did not create notification-sound items for the sonos device, so I did that now. Doesn’t appear to change the beahviour though. I have the duration of a notification sound set to 10 seconds, but the volume does not get restored (not after 10 seconds nor after the default 20 seconds) either.
@Lolodomo: thanks for verifying. This hints again to a local configuration issue.
@Eric1974
Your posted DEBUG log entry seems to be coming from the routine “playNotificationSoundURI” and should be showing the currentURI and metadata. Both are null in your case.
In my case this DEBUG message doesn’t even show ( although org.openab.binding.sonos is set to DEBUG). I do see the messages for setting the volume and starting and pushing the player. I have no idea why!
Edit: Stupid .me, when setting the logl:level for “org.openab.binding.sonos” (without the “h” !!) nothing will be logged for Sonos!
My log-messages when trying to play the doorbell.mp3:
2020-04-12 19:50:28.369 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E7D2EF401400: Subscription to service AVTransport succeeded
2020-04-12 19:50:30.378 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C14201400: Subscription to service RenderingControl succeeded
2020-04-12 19:50:30.380 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E7D2EF401400: Subscription to service RenderingControl succeeded
2020-04-12 19:50:31.121 [DEBUG] [s.internal.handler.ZonePlayerHandler] - playNotificationSoundURI: currentURI x-sonosapi-stream:s56851?sid=254&flags=8224&sn=0 metadata <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><dc:title>NDR 2 Niedersachsen</dc:title><upnp:class>object.item.audioItem.audioBroadcast</upnp:class><desc id="cdudn" nameSpace="urn:schemas-rinconnetworks-com:metadata-1-0/">SA_RINCON65031_</desc></item></DIDL-Lite>
2020-04-12 19:50:31.371 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E7D2EF401400: Subscription to service ContentDirectory succeeded
2020-04-12 19:50:31.378 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C14201400: Subscription to service AVTransport succeeded
2020-04-12 19:50:31.388 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C14201400: Subscription to service ContentDirectory succeeded
==> /var/log/openhab2/events.log <==
2020-04-12 19:50:31.454 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PLAY to PAUSE
==> /var/log/openhab2/openhab.log <==
2020-04-12 19:50:31.514 [DEBUG] [s.internal.handler.ZonePlayerHandler] - setCurrentURI URI x-rincon-queue:RINCON_949F3E7D2EF401400#0 URIMetaData
==> /var/log/openhab2/events.log <==
2020-04-12 19:50:31.762 [vent.ItemStateChangedEvent] - PlayBuero_Volume changed from 5 to 60
==> /var/log/openhab2/openhab.log <==
2020-04-12 19:50:33.396 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937BDEF0E01400: Subscription to service AVTransport succeeded
2020-04-12 19:50:33.417 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C16201400: Subscription to service RenderingControl succeeded
2020-04-12 19:50:33.439 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C16201400: Subscription to service AVTransport succeeded
2020-04-12 19:50:33.441 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937BDEF0E01400: Subscription to service ContentDirectory succeeded
2020-04-12 19:50:33.450 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E0C16201400: Subscription to service ContentDirectory succeeded
2020-04-12 19:50:33.451 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937BDEF0E01400: Subscription to service RenderingControl succeeded
2020-04-12 19:50:33.458 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Cannot update media data for group member (Could not find handler for RINCON_B8E937BDEFE601400)
2020-04-12 19:50:33.507 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Cannot update media data for group member (Could not find handler for RINCON_B8E937BDEFE601400)
==> /var/log/openhab2/events.log <==
2020-04-12 19:50:34.616 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PAUSE to UNDEF
2020-04-12 19:50:34.641 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from UNDEF to PAUSE
==> /var/log/openhab2/openhab.log <==
2020-04-12 19:50:43.622 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 19:50:53.889 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 19:50:54.685 [DEBUG] [s.internal.handler.ZonePlayerHandler] - setCurrentURI URI x-sonosapi-stream:s56851?sid=254&flags=8224&sn=0 URIMetaData <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="" parentID="" restricted="true"><dc:title>NDR 2 Niedersachsen</dc:title><upnp:class>object.item.audioItem.audioBroadcast</upnp:class><desc id="cdudn" nameSpace="urn:schemas-rinconnetworks-com:metadata-1-0/">RINCON_AssociatedZPUDN</desc></item></DIDL-Lite>
==> /var/log/openhab2/events.log <==
2020-04-12 19:50:54.728 [vent.ItemStateChangedEvent] - PlayBuero_Volume changed from 60 to 5
==> /var/log/openhab2/openhab.log <==
2020-04-12 19:50:54.966 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
==> /var/log/openhab2/events.log <==
2020-04-12 19:50:56.104 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PAUSE to UNDEF
2020-04-12 19:50:58.390 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from UNDEF to PLAY
==> /var/log/openhab2/openhab.log <==
2020-04-12 19:51:02.117 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 19:51:05.593 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Cannot update media data for group member (Could not find handler for RINCON_B8E937BDEFE601400)
2020-04-12 19:51:20.528 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Cannot update media data for group member (Could not find handler for RINCON_B8E937BDEFE601400)
Got it working again by doing a complete restart!
Before I tried deleting and reinstalling the Sonos things and restrarting the sonos bundle, both did not help!
The working log looks like:
2020-04-12 20:24:56.797 [DEBUG] [s.internal.handler.ZonePlayerHandler] - playNotificationSoundURI: currentURI x-sonosapi-stream:s56851?sid=254&flags=8224&sn=0 metadata <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><dc:title>NDR 2 Niedersachsen</dc:title><upnp:class>object.item.audioItem.audioBroadcast</upnp:class><desc id="cdudn" nameSpace="urn:schemas-rinconnetworks-com:metadata-1-0/">RINCON_AssociatedZPUDN</desc></item></DIDL-Lite>
==> /var/log/openhab2/events.log <==
2020-04-12 20:24:57.059 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PLAY to PAUSE
==> /var/log/openhab2/openhab.log <==
2020-04-12 20:24:57.130 [DEBUG] [s.internal.handler.ZonePlayerHandler] - setCurrentURI URI x-rincon-queue:RINCON_949F3E7D2EF401400#0 URIMetaData
==> /var/log/openhab2/events.log <==
2020-04-12 20:24:57.229 [vent.ItemStateChangedEvent] - PlayBuero_Volume changed from 12 to 60
2020-04-12 20:24:57.298 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PAUSE to PLAY
2020-04-12 20:25:03.706 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PLAY to PAUSE
==> /var/log/openhab2/openhab.log <==
2020-04-12 20:25:03.782 [DEBUG] [s.internal.handler.ZonePlayerHandler] - setCurrentURI URI x-sonosapi-stream:s56851?sid=254&flags=8224&sn=0 URIMetaData <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="" parentID="" restricted="true"><dc:title>NDR 2 Niedersachsen</dc:title><upnp:class>object.item.audioItem.audioBroadcast</upnp:class><desc id="cdudn" nameSpace="urn:schemas-rinconnetworks-com:metadata-1-0/">RINCON_AssociatedZPUDN</desc></item></DIDL-Lite>
==> /var/log/openhab2/events.log <==
2020-04-12 20:25:04.140 [vent.ItemStateChangedEvent] - PlayBuero_Volume changed from 60 to 12
2020-04-12 20:25:05.198 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from PAUSE to UNDEF
2020-04-12 20:25:07.684 [vent.ItemStateChangedEvent] - PlayBuero_Controller changed from UNDEF to PLAY
==> /var/log/openhab2/openhab.log <==
2020-04-12 20:25:12.880 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 20:25:12.965 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 20:25:13.016 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2020-04-12 20:25:13.143 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
@Eric1974: All I could suggest to your problem is a restart as well (although not knowing what actually caused my or your problem). Keeping fingers crossed!
Thanks @opus I’ll try rebooting later. First I’ll try to understand what should happen. I’ve pulled in the openhab-addon git, and will try to add some logging first to see if I can find out why this is happening while my system is in this state. At least both your and @Lolodomo results show that the error is in my local system setup and sofar it appears I’ve not done anything terribly wrong in trying to setup the binding either.
One thing I do wonder about in the documentation on the sonos binding is the “callbackUrl” that can be set on the Binding itself (in PaperUI). I don’t understand what this is for and if it is to be set (and if so what it should be set to)
I had the impression that my system had somehow mixed up the sonos ids ( hence the different ids showing in the faulty log).
Regarding the CallbackURL, that is unclear to me as well. All I can say it used to work without and does work without now again.
Good luck.
Edit:
If I understand the code correctly the faulty log shows that each player was checked positive in the Polling job with
if ((subscriptionState.get(subscription) == null) || !subscriptionState.get(subscription).booleanValue())
So there was a problem with the “known” state of the sonos things, which couldn’t be resolved by deleting/reinserting the things nor by restarting the sonos bundle.
Weird!
