DLNA / UPNP binding

Mherwege · September 6, 2018, 3:57pm

@5iver The issue is indeed that I pass an empty URL to retrieve album art. As the meta data is empty this will obviously not work, but the framework does not act nicely and throws an error.
I have changed it to first check for an empty URL, so the error should not appear anymore.
Most of the logging you see is the direct UPnP communication. So the renderers do send updates with ‘empty’ metadata. I assume that’s what they send if they don’t have any. I have made the logging a little bit more meaningful by always logging the renderer or server the communication is with.
A new version can be downloaded from the usual link.

DonStefano · October 29, 2018, 7:59pm

I’m still suffering problems with playing radio streams over my pioneer web radio with upnp capabilities. If I configure the station over the app and set it to webradio it plays the stream fine. When I try to set it over UPNP control via openHAB binding it does not play. I have set the log to trace (seems to be not more verbose as debug) and have no idea why it won’t play.
When I issue the command:

playStream(UPNP_Device, "http://mp3-live.dasding.de/dasding_m.m3u")

The device produces this log:

2018-10-29 20:51:09.682 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2018-10-29 20:51:09.683 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3, CurrentURIMetaData=}
2018-10-29 20:51:09.684 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2018-10-29 20:51:09.701 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer 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"/>
    </InstanceID>
</Event> from service AVTransport
2018-10-29 20:51:09.704 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTransportActions with value Play,Next,Previous from service AVTransport
2018-10-29 20:51:09.705 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable InstanceID with value 0 from service AVTransport
2018-10-29 20:51:09.705 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportState with value STOPPED from service AVTransport
2018-10-29 20:51:09.904 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
    <InstanceID val="0">
        <TransportState val="TRANSITIONING"/>
        <CurrentTransportActions val="Stop"/>
        <NumberOfTracks val="1"/>
    </InstanceID>
</Event> from service AVTransport
2018-10-29 20:51:09.905 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTransportActions with value Stop from service AVTransport
2018-10-29 20:51:09.906 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable NumberOfTracks with value 1 from service AVTransport
2018-10-29 20:51:09.906 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable InstanceID with value 0 from service AVTransport
2018-10-29 20:51:09.906 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportState with value TRANSITIONING from service AVTransport

It seems to be stuck in the stopped state. After issuing the command “play” over the control chanel it tries to start:

==< /var/log/openhab2/events.log >==
2018-10-29 20:51:21.022 [ome.event.ItemCommandEvent] - Item 'XWSMA32337FB_Player' received command PLAY

==< /var/log/openhab2/openhab.log >==
2018-10-29 20:51:21.023 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Handle command PLAY for channel upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB:control on renderer XW-SMA3 2337FB UPnPRenderer
2018-10-29 20:51:21.028 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}

==< /var/log/openhab2/events.log >==
2018-10-29 20:51:21.030 [nt.ItemStatePredictedEvent] - XWSMA32337FB_Player predicted to become PLAY

That’s all, after producing the output nothig else happens.

I would be really happy to have someone analyse my problem.
TIA

Stefan

5iver · October 29, 2018, 8:39pm

What are you using for the UPNP_Device variable? From your log, it looks like it should be…

upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB

With my speakers, I was seeing the playStream command fail the first time it was sent, but sending a second time was working. I figured this may be due to my speakers being sleepy, but I could not find a timeout in the binding or within playStream, but I still haven’t dug through the org.eclipse.smarthome.io.transport.upnp or org.jupnp. Maybe this could be affecting you too?

DonStefano · October 30, 2018, 7:58am

Thank you Scott for replying. Your assumption is right, I declared a val for not having the string all over in my rule.

While trying your idea to issue the playstream command a second time I discovered that the log posted previously was already the second attempt to play the stream.

The most information on my device was sent with a spontanous event:

2018-10-30 08:42:10.015 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer add upnp subscription on AVTransport
2018-10-30 08:42:10.129 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received subscription reply true from service AVTransport
2018-10-30 08:42:10.146 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer 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="NETWORK"/>
    <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="1"/>
    <CurrentTrack val="1"/>
    <CurrentTrackDuration val="0:00:00"/>
    <CurrentMediaDuration val="0:00:00"/>
    <CurrentTrackMetaData val=""/>
    <CurrentTrackURI val="http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3"/>
    <AVTransportURI val="http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3"/>
    <AVTransportURIMetaData val=""/>
    <NextAVTransportURI val="NOT_IMPLEMENTED"/>
    <NextAVTransportURIMetaData val="NOT_IMPLEMENTED"/>
    <CurrentTransportActions val=""/>
  </InstanceID>
</Event> from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable AVTransportURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportPlaySpeed with value 1 from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackURI with value http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable InstanceID with value 0 from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackMetaData with value  from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportStatus with value OK from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable AVTransportURIMetaData with value  from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackMetaData with value  from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentPlayMode with value NORMAL from service AVTransport
2018-10-30 08:42:10.151 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackDuration with value 0:00:00 from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable PossiblePlaybackStorageMedia with value NONE,NETWORK from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrack with value 1 from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentRecordQualityMode with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable RecordMediumWriteStatus with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable PlaybackStorageMedium with value NETWORK from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable PossibleRecordQualityModes with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable NextAVTransportURIMetaData with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTransportActions with value  from service AVTransport
2018-10-30 08:42:10.152 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable NumberOfTracks with value 1 from service AVTransport
2018-10-30 08:42:10.153 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable PossibleRecordStorageMedia with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.155 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentMediaDuration with value 0:00:00 from service AVTransport
2018-10-30 08:42:10.155 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable NextAVTransportURI with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.155 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable RecordStorageMedium with value NOT_IMPLEMENTED from service AVTransport
2018-10-30 08:42:10.155 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport

My device is not in streaming mode, it is currently playing another stream via web radio.

When I issue anothe playstream command the result is just:

2018-10-30 08:54:10.256 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2018-10-30 08:54:10.258 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3, CurrentURIMetaData=}
2018-10-30 08:54:10.259 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2018-10-30 08:54:10.298 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <AVTransportURI val="http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3"/>
    <NumberOfTracks val="1"/>
    <CurrentTrackURI val="http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3"/>
    <TransportState val="STOPPED"/>
    <CurrentTransportActions val="Play,Next,Previous"/>
  </InstanceID>
</Event> from service AVTransport
2018-10-30 08:54:10.299 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable AVTransportURI with value http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:54:10.299 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackURI with value http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:54:10.300 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTransportActions with value Play,Next,Previous from service AVTransport
2018-10-30 08:54:10.300 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable NumberOfTracks with value 1 from service AVTransport
2018-10-30 08:54:10.300 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTrackURI with value http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3 from service AVTransport
2018-10-30 08:54:10.300 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable InstanceID with value 0 from service AVTransport
2018-10-30 08:54:10.300 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportState with value STOPPED from service AVTransport

2018-10-30 08:54:10.579 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer 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-10-30 08:54:10.580 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable CurrentTransportActions with value Stop from service AVTransport
2018-10-30 08:54:10.580 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable InstanceID with value 0 from service AVTransport
2018-10-30 08:54:10.581 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Upnp device XW-SMA3 2337FB UPnPRenderer received variable TransportState with value TRANSITIONING from service AVTransport

Next I will try to shut off (sleep mode) my device and restart the bundle. The result in my logs seems to be highly state dependant.

5iver · October 30, 2018, 10:58am

If you haven’t already, you may also want to try doing a playSound to see if that works. Rather than fiddling with a rule, you easily do this through the Karaf console with:

smarthome:audio play upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB doorbell.mp3

Another thought… do you get different results going directly to the stream, rather than the playlist…

smarthome:audio stream upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB http://swr-swr3-live.cast.addradio.de/swr/swr3/live/mp3/128/stream.mp3

DonStefano · October 30, 2018, 3:14pm

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’

DonStefano · November 19, 2018, 1:09pm

Now I have set the logging back and waiting for some answer:

openhab> log:set DEFAULT org.openhab.binding.upnpcontrol
openhab> log:set DEFAULT org.eclipse.smarthome.config.discovery.upnp
openhab> log:set DEFAULT org.eclipse.smarthome.io.transport.upnp
openhab>

thisisIO · January 6, 2019, 9:44pm

Mherwege:

I don’t think it is that difficult to create a generic binding that acts as a UPnP audio (video) control point. I have been experimenting a little bit with it. I created some code that can discover UPnP media renderers and servers and register the renderers as audio sinks. The idea was to have a control point thing defined manually that then has a server and a renderer channel with selection of the available renderers and servers.
I am far from finished on this, but I can use a renderer as an audio sink. I am limited in time, so not sure I will ever finish it. However, for those who want to check it out, here is a compiled jar . The code is on my github . I didn’t create a pull request as it is not in a workable state yet. And the code is far from clean.

The most challenging part I see is implementing a simple media libary search/query on the server thing. I want to be able to walk through the tree and set favourites. That would allow me to use rules in openHAB to play media I have stored somewhere on a media server.

Hello,

thanks for great work!
I have installed 2.4, auto discovered my Reсeiver, but i can not unsertand how can i play on it a stream?
I found here that i need to user command like this
playStream(UPNP_Device, “http://mp3-live.dasding.de/dasding_m.m3u”)

But it is not clear - it must be item or something else?

Thanks a lot!

5iver · January 7, 2019, 5:36am

Your renderers will be added as audiosinks. You can view them in Karaf with:

smarthome:audio sinks

This lists a friendly name and the sink in parenthesis, like this:

Family Room (upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f522dcaf)

Use the sink in your playStream command (as a string)…

playStream("upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f522dcaf", “http://mp3-live.dasding.de/dasding_m.m3u”)

… or set a sink as the default, don’t include a sink in the playStream command, and it will play to the default.

thisisIO · January 7, 2019, 9:24am

Thanks a lot i got it!
I configured Yamaha Receiver it as default sink http://prntscr.com/m3z23w
Und simple command - playSound (“doorbell.mp3”)
It plays on receiver! I get log http://prntscr.com/m3zea3

But when i try to play a stream like this
playStream(“http://swr-dasding-live.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3”)
or this
playStream(“http://mp3-live.dasding.de/dasding_m.m3u”)
it do not works. In Log i see http://prntscr.com/m3zesa
It looks like it start playing and then make pause.

By the way i tested UPNP Controls with another stream, that i started in reviever (with yamaha app) - i can contorl it, set volume, mute.

It there any soultion?
Thanks a lot!

5iver · January 7, 2019, 10:30pm

It sounds like you and @DonStefano are reporting the same behavior. I am able to use playStream with radio streams from the Internet and from a local media server. However, only about 75% of the calls actually succeed. Sending the command twice helped a little. I’ve been really frustrated with this, so I will either go back to using scripts for UPnP, or will dig in to the binding and UPNP library if I can find some time.

Maybe your receiver is compatible with the Yamaha receiver binding?

thisisIO · January 7, 2019, 11:12pm

Yes compatible, i use it, but there is not way to play a stream or?

5iver · January 8, 2019, 12:05am

Sorry… I assumed there was a Channel for playing a stream!

Tema · January 11, 2019, 7:54am

Continuing the discussion from DLNA / UPNP binding:

Hi, sorry, I not understand how I can install UPNP binding in my OpenHAB?

5iver · January 11, 2019, 8:06am

Not much to it… download the jar, and copy it to your /addons folder. It’s still very experimental, but I’m using it successfully with a Twonky media server and Sony SA-NS400 renderers. I’m frustrated with streams not always playing, wish there was a Channel on the renders for setting an AVTransportURI (you have to use the renderers as audio sinks), and I usually have to manually restart the binding after an OH restart to get the subscriptions going and then manually set the STOP and Player states, but having the subscriptions is wonderful (was previously using scripts without subscriptions).

MacFly · January 11, 2019, 10:16am

Hi Mark !

I’m sorry to bother you again, but I just upgraded to OpenHab 2.4.0-1 Release, and my simple Volume Control doesn’t work anymore.
When I power up my Sony device, the binding discover it but the discovery seem fail :

2019-01-11 11:03:43.239 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Sony Corporation, model BDV, SN# null

2019-01-11 11:03:43.240 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Sony Corporation, BDV

2019-01-11 11:03:43.240 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Device ‘00000000-0000-1010-8000-544249199c7c’ reachability status changed to ‘true’

2019-01-11 11:03:43.241 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Renderer status changed to true

2019-01-11 11:03:43.243 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY add upnp subscription on AVTransport

2019-01-11 11:03:43.248 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY invoke upnp action GetTransportInfo on service AVTransport with inputs {InstanceID=0}

2019-01-11 11:03:43.249 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY invoke upnp action GetProtocolInfo on service ConnectionManager with inputs {}

2019-01-11 11:03:43.249 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Could not find action ‘GetTransportInfo’ for participant ‘00000000-0000-1010-8000-544249199c7c’

2019-01-11 11:03:43.250 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Could not find action ‘GetProtocolInfo’ for participant ‘00000000-0000-1010-8000-544249199c7c’

2019-01-11 11:03:43.258 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - A GENA subscription ‘AVTransport’ for device ‘uuid:00000000-0000-1010-8000-544249199c7c’ failed

2019-01-11 11:03:43.259 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY received subscription reply false from service AVTransport

==> /var/log/openhab2/events.log <==

2019-01-11 11:03:43.252 [hingStatusInfoChangedEvent] - ‘upnpcontrol:upnprenderer:00000000-0000-1010-8000-544249199c7c’ changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with SALON BLU-RAY to ONLINE

==> /var/log/openhab2/openhab.log <==

2019-01-11 11:03:44.264 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Sony Corporation, model BDV, SN# null

2019-01-11 11:03:44.265 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Device ‘00000000-0000-1010-8000-544249199c7c’ reachability status changed to ‘false’

2019-01-11 11:03:44.266 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Sony Corporation, BDV

2019-01-11 11:03:44.267 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Renderer status changed to false

2019-01-11 11:03:44.682 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Sony Corporation, model BDV, SN# null

2019-01-11 11:03:44.682 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Device ‘00000000-0000-1010-8000-544249199c7c’ reachability status changed to ‘true’

2019-01-11 11:03:44.683 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Sony Corporation, BDV

2019-01-11 11:03:44.683 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Renderer status changed to true

2019-01-11 11:03:44.684 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY add upnp subscription on AVTransport

2019-01-11 11:03:44.686 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY invoke upnp action GetProtocolInfo on service ConnectionManager with inputs {}

2019-01-11 11:03:44.687 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Could not find action ‘GetProtocolInfo’ for participant ‘00000000-0000-1010-8000-544249199c7c’

2019-01-11 11:03:44.689 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY invoke upnp action GetTransportInfo on service AVTransport with inputs {InstanceID=0}

2019-01-11 11:03:44.695 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - A GENA subscription ‘AVTransport’ for device ‘uuid:00000000-0000-1010-8000-544249199c7c’ failed

2019-01-11 11:03:44.695 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Could not find action ‘GetTransportInfo’ for participant ‘00000000-0000-1010-8000-544249199c7c’

2019-01-11 11:03:44.696 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY received subscription reply false from service AVTransport

==> /var/log/openhab2/events.log <==

2019-01-11 11:03:44.271 [hingStatusInfoChangedEvent] - ‘upnpcontrol:upnprenderer:00000000-0000-1010-8000-544249199c7c’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication lost with SALON BLU-RAY

2019-01-11 11:03:44.697 [hingStatusInfoChangedEvent] - ‘upnpcontrol:upnprenderer:00000000-0000-1010-8000-544249199c7c’ changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with SALON BLU-RAY to ONLINE

But when I tried to send a setvolume command thru the Dimmer item :

2019-01-11 11:04:04.174 [DEBUG] [pcontrol.handler.UpnpRendererHandler] - Handle command 18 for channel upnpcontrol:upnprenderer:00000000-0000-1010-8000-544249199c7c:volume on renderer SALON BLU-RAY

2019-01-11 11:04:04.175 [DEBUG] [ding.upnpcontrol.handler.UpnpHandler] - Upnp device SALON BLU-RAY invoke upnp action SetVolume on service RenderingControl with inputs {InstanceID=0, Channel=Master, DesiredVolume=18}

2019-01-11 11:04:04.177 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Could not find action ‘SetVolume’ for participant ‘00000000-0000-1010-8000-544249199c7c’

…Error and nothing happend …

Any thought about it ? Tell me if I can provide you more information.

Thanks you.

Mherwege · January 11, 2019, 7:23pm

@MacFly I would need to dig into the code again and start debugging and improving. I know there are issues with the binding, not just for you. I pulled this together as a quick project but didn’t have the time to keep on working on this one. I am afraid I won’t have the time for this the next few weeks. Sorry for that.
@5iver My original intention for this binding was to be able to use it as a control point to control a media server and send the media for playback to a renderer. That works for me. I actually can play more than just audio (video, photos). Again, I know there are bugs and combinations that do not work. There is a lot of potential for improvement. Registering the renderers as audio sinks is just an easy side step. Adding a URL directly to the renderer kind of defeats the whole concept of the binding. But maybe there should be a separate server thing type, which is just has a url for a streaming service channel (with a similar renderer selection channel capability). What do you think?

5iver · January 13, 2019, 10:34am

Using audio sinks just is not all that user friendly, and I’ve basically simulated a playURI channel with String items, a rule, and Items to store the uuids. A Channel would have simplified this. I also generate local TTS audio alerts on the server running OH, and have the speakers access the files from the server… no media server involved, so I don’t think what your suggesting would help, at least in my implementation.

Before the binding, I used scripts for everything. Using the binding and playStream, audio often does not play after sending the command. In looking at the logs after a playStream that did not work, I found a Stop PLAY and SetAVTransportURI all being sent at the same time, in random order. And the order of the responses explains why the audio often does not play. I would have expected that the SetAVtransport wouldn’t have been sent until the response was received for the STOP. Same for the PLAY waiting for the SetAVTransport response.

private void playMedia(String url) {
    handler.stop();
    String newUrl = url;
    if (!url.startsWith("x-") && !url.startsWith("http")) {
        newUrl = "x-file-cifs:" + url;
    }
    handler.setCurrentURI(newUrl, "");
    handler.play();
}

MacFly · January 14, 2019, 12:01pm

Hi Mark,
First of all, thanks you for your answer … I know this is only a side tool for you but so useful for many

Here is more information about my differents tests, with the hope that will be help you when you have some spare time to dig in it.

First question is when it happend? With the help of Dockers, I have played with many milestone builds (openHAB 2.4 Milestone builds). Your binding works well until milestone 2.4.0-M7, 2.4.0-M8 and further doesn’t work anymore.

Second thing I noticed (on M8 and further) is that if my device is powered ON when I start Openhab, the binding works well but If my device is OFF at openhab start or if I power OFF and ON my device when openhab is started, the actions isn’t reconnized anymore.

Again, thanks you for this tool. At the moment, I kept a container with a light milestone 7 and only your binding, sync with my main openhab 2.4.0 release with mqtt.

Best regards,

Mac_Fly.

Mherwege · January 14, 2019, 10:32pm

@5iver The logic of waiting for a message acknowledgment before taking the next action is weak in the binding. I would have to recode much of it, probably using futures to be able to wait for required return values, if there is an expected answer. I started this by copying some code from bindings like the Sonos binding, and I noticed that in most of these, there wasn’t a consistent check of message acknowledgments.
Also, I tested with a few players, and they all behaved differently as to the expected sequence before the next media queued was served.
Again, a lot of work ahead to make this logic a lot stronger. I am sorry, but I can’t focus on that in the near future.