Different errors and warnings when using Sonos speakers for notifications

  • Platform information:
    • Hardware: VMWare VM
    • OS: Ubuntu 16.04
    • Java Runtime Environment: Java™ SE Runtime Environment (build 1.8.0_121-b13)
      Java HotSpot™ 64-Bit Server VM (build 25.121-b13, mixed mode)
    • openHAB version:“0.9.0.b4”
  • Issue: I have about 5 Sonos speakers. 2 of them are Play 3’s and are a stereo pair in the kitchen. I want to be able to play a notification sound when my door is opened or when somebody pushes the doorbell. Based on reading I already determined that using the notification command is the fastest way to get a sound playing and I shouldn’t use the audio sink. When I implement my rules I get a lot of different errors in the openhab.log.

Furthermore: the file plays but the volume is too low (changing the notificationvolume in the things-file doesn’t change anything.

  • Please post configurations (if applicable):
    • things
Thing sonos:PLAY1:SonosBadkamer [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]

Thing sonos:PLAY1:Slaapkamer [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]

Thing sonos:PLAY1:Zithoek [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]
Thing sonos:PLAY5:SonosWoonkamer [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]

Thing sonos:PLAY3:SonosKeukenL [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]
Thing sonos:PLAY3:SonosKeukenR [udn="RINCON_xxxxxxxxxxx", refresh=60, notificationVolume=75]
  • Items configuration related to the issue
String Sonos_Keuken_Notification	"Sonos Keuken - Notificatiegeluid"
  • Rules code related to the issue

rule “DoorOpenPlaysSound”
when
Item input_AchterdeurStatus received update OPEN
then
logInfo(“RULE”, “Achterdeur is open!”)
sendCommand(Sonos_Keuken_Notification,“http://192.168.4.211:8080/static/doorbell.mp3”)
end

  • Services configuration related to the issue
  • If logs where generated please post these here using code fences:
2019-03-12 19:19:00.568 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'http://192.168.4.211:8080/static/doorbell.mp3' for item 'Sonos_Keuken_Notification' to handler for channel 'sonos:PLAY3:SonosKeuken:notificationsound', because no thing with the UID 'sonos:PLAY3:SonosKeuken' could be found.
2019-03-12 19:19:00.569 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'http://192.168.4.211:8080/static/doorbell.mp3' for item 'Sonos_Keuken_Notification' to handler for channel 'sonos:PLAY3:SonosKeuken:notificationsound', because no thing with the UID 'sonos:PLAY3:SonosKeuken' could be found.
2019-03-12 19:19:00.706 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling thing updated at ThingHandler 'org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler@64568036': null
java.util.concurrent.TimeoutException
        at java.util.concurrent.FutureTask.get(FutureTask.java:205)[:1.8.0_121]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.core.thing.internal.ThingManager.thingUpdated(ThingManager.java:518)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:227)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:150)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:1)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:167)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:57)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutUpdatedElement(AbstractProvider.java:82)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.access$4(GenericThingProvider.java:1)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$21.accept(GenericThingProvider.java:1044)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$21.accept(GenericThingProvider.java:1)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at java.util.ArrayList.forEach(ArrayList.java:1249)[:1.8.0_121]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.createThingsFromModelForThingHandlerFactory(GenericThingProvider.java:1054)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.access$1(GenericThingProvider.java:1008)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$1$1.accept(GenericThingProvider.java:236)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$1$1.accept(GenericThingProvider.java:1)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at java.util.concurrent.ConcurrentHashMap$KeySetView.forEach(ConcurrentHashMap.java:4649)[:1.8.0_121]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$1.apply(GenericThingProvider.java:239)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$1.apply(GenericThingProvider.java:1)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.config.core.BundleProcessorVetoManager.applyActionFor(BundleProcessorVetoManager.java:121)[94:org.eclipse.smarthome.config.core:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$6.accept(GenericThingProvider.java:320)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider$6.accept(GenericThingProvider.java:1)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at java.lang.Iterable.forEach(Iterable.java:75)[:1.8.0_121]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.createThingsFromModel(GenericThingProvider.java:323)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.thing.internal.GenericThingProvider.modelChanged(GenericThingProvider.java:901)[133:org.eclipse.smarthome.model.thing:0.9.0.b4]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.notifyListeners(ModelRepositoryImpl.java:207)[122:org.eclipse.smarthome.model.core:0.9.0.b4]
        at org.eclipse.smarthome.model.core.internal.ModelRepositoryImpl.addOrRefreshModel(ModelRepositoryImpl.java:120)[122:org.eclipse.smarthome.model.core:0.9.0.b4]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.checkFile(FolderObserver.java:272)[122:org.eclipse.smarthome.model.core:0.9.0.b4]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver.access$1(FolderObserver.java:265)[122:org.eclipse.smarthome.model.core:0.9.0.b4]
        at org.eclipse.smarthome.model.core.internal.folder.FolderObserver$WatchQueueReader.processWatchEvent(FolderObserver.java:146)[122:org.eclipse.smarthome.model.core:0.9.0.b4]
        at org.eclipse.smarthome.core.service.AbstractWatchQueueReader.run(AbstractWatchQueueReader.java:122)[98:org.eclipse.smarthome.core:0.9.0.b4]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2019-03-12 19:19:15.739 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfKeukenLxxxxx/svc/upnp-org/DeviceProperties/event/cb SEQUENCE: 14
2019-03-12 19:19:15.740 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfKeukenRxxxxx/svc/upnp-org/ZoneGroupTopology/event/cb SEQUENCE: 11
2019-03-12 19:19:15.740 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfLivingRoomxxx/svc/upnp-org/ZoneGroupTopology/event/cb SEQUENCE: 11
2019-03-12 19:19:15.740 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfKeukenRxxxxx/svc/upnp-org/DeviceProperties/event/cb SEQUENCE: 6
2019-03-12 19:19:16.050 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'PLAY' for item 'Sonos_Woonkamer_Controller' to handler for channel 'sonos:zoneplayer:RINCON_macOfLivingRoomxxx:control', because no thing with the UID 'sonos:zoneplayer:RINCON_macOfLivingRoomxxx' could be found.
2019-03-12 19:19:16.051 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'PLAY' for item 'Sonos_Woonkamer_Controller' to handler for channel 'sonos:PLAY5:RINCON_macOfWoonkamer5xx:control', because no thing with the UID 'sonos:PLAY5:RINCON_macOfWoonkamer5xx' could be found.
2019-03-12 19:19:16.095 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfKeukenLxxxxx/svc/upnp-org/AVTransport/event/cb SEQUENCE: 16
2019-03-12 19:19:16.096 [ERROR] [g.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_macOfKeukenRxxxxx_MR/svc/upnp-org/RenderingControl/event/cb SEQUENCE: 17
2019-03-12 19:19:16.833 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'PAUSE' for item 'Sonos_Woonkamer_Controller' to handler for channel 'sonos:zoneplayer:RINCON_macOfLivingRoomxxx:control', because no thing with the UID 'sonos:zoneplayer:RINCON_macOfLivingRoomxxx' could be found.
2019-03-12 19:19:16.833 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'PAUSE' for item 'Sonos_Woonkamer_Controller' to handler for channel 'sonos:PLAY5:RINCON_macOfWoonkamer5xx:control', because no thing with the UID 'sonos:PLAY5:RINCON_macOfWoonkamer5xx' could be found.
2019-03-12 19:19:18.247 [WARN ] [jetty.server.handler.ResourceHandler] - org.eclipse.jetty.io.EofException

It seemed to work for a while, and now these start popping up too:

2019-03-12 22:14:31.525 [INFO ] [.eclipse.smarthome.model.script.RULE] - Achterdeur is open!
2019-03-12 22:14:31.529 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'http://192.168.4.211:8080/static/BackDoorHasBeenOpened.mp3' for item 'Sonos_Keuken_Notification' to handler for channel 'sonos:PLAY3:SonosKeuken:notificationsound', because no thing with the UID 'sonos:PLAY3:SonosKeuken' could be found.
2019-03-12 22:14:31.531 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'http://192.168.4.211:8080/static/BackDoorHasBeenOpened.mp3' for item 'Sonos_Keuken_Notification' to handler for channel 'sonos:PLAY3:SonosKeuken:notificationsound', because no thing with the UID 'sonos:PLAY3:SonosKeuken' could be found.
2019-03-12 22:14:43.739 [WARN ] [ding.sonos.handler.ZonePlayerHandler] - Could not fetch TotalMatches result for type: Q:0 and filter: dc:title. Using default value '0': null
java.lang.NumberFormatException: null
        at java.lang.Long.parseLong(Long.java:552)[:1.8.0_121]
        at java.lang.Long.valueOf(Long.java:803)[:1.8.0_121]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.getResultEntry(ZonePlayerHandler.java:1158)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.getNbEntries(ZonePlayerHandler.java:1140)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.getQueueSize(ZonePlayerHandler.java:1061)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.handleNotificationSound(ZonePlayerHandler.java:2254)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.handleSharedQueue(ZonePlayerHandler.java:2236)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler.playNotificationSoundURI(ZonePlayerHandler.java:2141)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at org.eclipse.smarthome.binding.sonos.handler.ZonePlayerHandler$2.run(ZonePlayerHandler.java:2117)[184:org.eclipse.smarthome.binding.sonos:0.9.0.b4]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]