Hi Scott,
I rebooted my device and got the following output, which shows the device capabilities:
2018-10-30 16:00:57.617 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Renderer status changed to true
2018-10-30 16:00:57.618 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 add upnp subscription on AVTransport
2018-10-30 16:00:57.618 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer PIONEER CORPORATION, model XW-SMA3, SN# null
2018-10-30 16:00:57.618 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: PIONEER CORPORATION, XW-SMA3
2018-10-30 16:00:57.619 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action GetProtocolInfo on service ConnectionManager with inputs {}
2018-10-30 16:00:57.619 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action GetTransportInfo on service AVTransport with inputs {InstanceID=0}
2018-10-30 16:00:57.624 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable Sink with value http-get:*:audio/L16;rate=44100;channels=1:DLNA.ORG_PN=LPCM,http-get:*:audio/L16;rate=44100;channels=2:DLNA.ORG_PN=LPCM,http-get:*:audio/L16;rate=48000;channels=1:DLNA.ORG_PN=LPCM,http-get:*:audio/L16;rate=48000;channels=2:DLNA.ORG_PN=LPCM,http-get:*:audio/mpeg:DLNA.ORG_PN=MP3,http-get:*:audio/x-ms-wma:DLNA.ORG_PN=WMABASE,http-get:*:audio/x-ms-wma:DLNA.ORG_PN=WMAFULL,http-get:*:audio/mp4:DLNA.ORG_PN=AAC_ISO,http-get:*:audio/3gpp:DLNA.ORG_PN=AAC_ISO,http-wavetunes:*:audio/x-ms-wma:*,http-get:*:audio/wav:*,http-get:*:audio/x-wav:*,http-get:*:audio/flac:*,http-get:*:audio/x-flac:*,http-get:*:audio/mp4:DLNA.ORG_PN=AAC_ISO_320,http-get:*:audio/3gpp:DLNA.ORG_PN=AAC_ISO_320,http-get:*:audio/vnd.dlna.adts:DLNA.ORG_PN=AAC_ADTS_320 from service ConnectionManager
2018-10-30 16:00:57.624 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Device UPnPRenderer XW-SMA3 supports audio
2018-10-30 16:00:57.624 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Audio Sink already registered for renderer UPnPRenderer XW-SMA3
2018-10-30 16:00:57.626 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentSpeed with value 1 from service AVTransport
2018-10-30 16:00:57.626 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-10-30 16:00:57.626 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportStatus with value OK from service AVTransport
2018-10-30 16:00:57.629 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 received subscription reply true from service AVTransport
2018-10-30 16:00:57.634 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="NO_MEDIA_PRESENT"/>
<TransportStatus val="OK"/>
<PlaybackStorageMedium val="NONE"/>
<RecordStorageMedium val="NOT_IMPLEMENTED"/>
<PossiblePlaybackStorageMedia val="NONE,NETWORK"/>
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/>
<CurrentPlayMode val="NORMAL"/>
<TransportPlaySpeed val="1"/>
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/>
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/>
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/>
<NumberOfTracks val="0"/>
<CurrentTrack val="0"/>
<CurrentTrackDuration val="0:00:00"/>
<CurrentMediaDuration val="0:00:00"/>
<CurrentTrackMetaData val=""/>
<CurrentTrackURI val=""/>
<AVTransportURI val=""/>
<AVTransportURIMetaData val=""/>
<NextAVTransportURI val="NOT_IMPLEMENTED"/>
<NextAVTransportURIMetaData val="NOT_IMPLEMENTED"/>
<CurrentTransportActions val=""/>
</InstanceID>
</Event> from service AVTransport
2018-10-30 16:00:57.635 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable AVTransportURI with value from service AVTransport
2018-10-30 16:00:57.635 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackURI with value from service AVTransport
2018-10-30 16:00:57.636 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportPlaySpeed with value 1 from service AVTransport
2018-10-30 16:00:57.636 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackURI with value from service AVTransport
2018-10-30 16:00:57.636 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable InstanceID with value 0 from service AVTransport
2018-10-30 16:00:57.636 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackMetaData with value from service AVTransport
2018-10-30 16:00:57.636 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportStatus with value OK from service AVTransport
2018-10-30 16:00:57.637 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable AVTransportURIMetaData with value from service AVTransport
2018-10-30 16:00:57.637 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackMetaData with value from service AVTransport
2018-10-30 16:00:57.637 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentPlayMode with value NORMAL from service AVTransport
2018-10-30 16:00:57.637 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackDuration with value 0:00:00 from service AVTransport
2018-10-30 16:00:57.637 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable PossiblePlaybackStorageMedia with value NONE,NETWORK from service AVTransport
2018-10-30 16:00:57.638 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrack with value 0 from service AVTransport
2018-10-30 16:00:57.638 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentRecordQualityMode with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.638 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable RecordMediumWriteStatus with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.638 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable PlaybackStorageMedium with value NONE from service AVTransport
2018-10-30 16:00:57.638 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable PossibleRecordQualityModes with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable NextAVTransportURIMetaData with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportActions with value from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable NumberOfTracks with value 0 from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable PossibleRecordStorageMedia with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentMediaDuration with value 0:00:00 from service AVTransport
2018-10-30 16:00:57.639 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable NextAVTransportURI with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.640 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable RecordStorageMedium with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 16:00:57.640 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
I also tried issuing the playsound command. It showed no error and did not play anything on my device. As the device is registered as my default audio sink it is the same as issuing
smarthome:audio play doorbell.mp3
The resulting log looks like:
2018-10-30 16:04:30.152 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2018-10-30 16:04:30.153 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://192.168.6.5:8080/audio/b7e90676-637d-4ae8-9cb2-a9eed4821e4a, CurrentURIMetaData=}
2018-10-30 16:04:30.154 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
So I would like to trace it further in the layers of source code to see if any audio is sent to / received by the device. I did not search the source code to find out, which call is made after the logged message.
Edit: It once worked perfectly with the same rule and stopped after upgrading from OH 2.2 to 2.3. Now I’m on 2.4M4 and use the upnpcontrol binding 2.4.0.201809061550.
It does also work when I use anothe UPNP controller, actually tested with BubbleUPNP.
Update 2018-11-19:
After updating to openHAB 2. M5 I did some more testing. After I enabled tracing on all UPNP bindings, it seems the stream always stays stopped.
2018-11-19 13:42:57.236 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2018-11-19 13:42:57.237 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'Stop' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:42:57.246 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3, CurrentURIMetaData=}
2018-11-19 13:42:57.247 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'SetAVTransportURI' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:42:57.248 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2018-11-19 13:42:57.248 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'Play' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:42:57.258 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Transition not available
2018-11-19 13:42:57.285 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Receiving a GENA subscription 'AVTransport' response for device 'uuid:5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:42:57.286 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="STOPPED"/>
<CurrentTransportActions val="Play,Next,Previous"/>
<AVTransportURI val="http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3"/>
<NumberOfTracks val="1"/>
<CurrentTrackURI val="http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3"/>
</InstanceID>
</Event> from service AVTransport
2018-11-19 13:42:57.287 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable AVTransportURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-11-19 13:42:57.287 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-11-19 13:42:57.287 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportActions with value Play,Next,Previous from service AVTransport
2018-11-19 13:42:57.287 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable NumberOfTracks with value 1 from service AVTransport
2018-11-19 13:42:57.288 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTrackURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-11-19 13:42:57.288 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable InstanceID with value 0 from service AVTransport
2018-11-19 13:42:57.288 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportState with value STOPPED from service AVTransport
So I added a Player Item to my sitemap and pressed ‘PLAY’ (>) on it.
2018-11-19 13:43:43.329 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Handle command PLAY for channel upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB:control on renderer UPnPRenderer XW-SMA3
2018-11-19 13:43:43.333 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2018-11-19 13:43:43.333 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'Play' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:43:43.410 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Receiving a GENA subscription 'AVTransport' response for device 'uuid:5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:43:43.411 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="TRANSITIONING"/>
<CurrentTransportActions val="Stop"/>
</InstanceID>
</Event> from service AVTransport
2018-11-19 13:43:43.412 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportActions with value Stop from service AVTransport
2018-11-19 13:43:43.413 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable InstanceID with value 0 from service AVTransport
2018-11-19 13:43:43.413 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportState with value TRANSITIONING from service AVTransport
Seems it doesn’t like the STOP and PLAY actions. I had success with the first version of the binding and am trying hard to get back to this state. But I’m not aware of the changes which have been incorporated in the code which made my stream silent.
I just tried the doorbell sound again:
2018-11-19 13:58:23.862 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2018-11-19 13:58:23.862 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'Stop' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:58:23.867 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://192.168.6.5:8080/audio/9d66ba8f-378d-49b0-bb3f-e26ae8a4d57b, CurrentURIMetaData=}
2018-11-19 13:58:23.867 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'SetAVTransportURI' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:58:23.867 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device UPnPRenderer XW-SMA3 invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2018-11-19 13:58:23.868 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'Play' of service 'AVTransport' for participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:58:23.889 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Illegal MIME-type
2018-11-19 13:58:23.899 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Receiving a GENA subscription 'AVTransport' response for device 'uuid:5F9EC1B3-ED59-79C2-4530-745E1C2337FB'
2018-11-19 13:58:23.901 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="TRANSITIONING"/>
<CurrentTransportActions val="Stop"/>
</InstanceID>
</Event> from service AVTransport
2018-11-19 13:58:23.902 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable CurrentTransportActions with value Stop from service AVTransport
2018-11-19 13:58:23.902 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable InstanceID with value 0 from service AVTransport
2018-11-19 13:58:23.902 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device UPnPRenderer XW-SMA3 received variable TransportState with value TRANSITIONING from service AVTransport
2018-11-19 13:58:23.908 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Illegal MIME-type
I can’t do very much with those logs. I can only see the status of stream is always ‘STOP’