DLNA / UPNP binding


(Mark Herwege) #101

This seems to be because the renderers are sending empty xml metadata in your case. The xml parser chokes on these and logs the error. While it does not do any harm (the exception is catched and the flow continuous as expected), I have added a check for empty xml strings before calling the xml parser.

I also updated the thing status logic to go offline at initialization. So far, it was waiting to receive a service message before turning online later, but that meant it never went offline if the message did not come and remained in intializing status.

Github is updated and new version is loaded on my dropbox.


(Scott Rushworth) #102

Here is another uncaught exception that periodically comes up in Karaf. I didn’t have debug turned on, so let me know if this isn’t enough to track it down. I was also getting these from the version before 2.4.0.201808071611.

openhab> [Fatal Error] :1:70: The prefix "upnp" for element "upnp:class" is not bound.
org.eclipse.jetty.io.EofException: Early EOF
        at org.eclipse.jetty.server.HttpInput$3.noContent(HttpInput.java:898)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:191)
        at java.io.InputStream.read(InputStream.java:101)
        at org.jupnp.util.io.IO.copyLarge(IO.java:980)
        at org.jupnp.util.io.IO.copy(IO.java:954)
        at org.jupnp.util.io.IO.toByteArray(IO.java:402)
        at org.jupnp.util.io.IO.readBytes(IO.java:121)
        at org.jupnp.transport.impl.ServletUpnpStream.readRequestMessage(ServletUpnpStream.java:137)
        at org.jupnp.transport.impl.ServletUpnpStream.run(ServletUpnpStream.java:61)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

(Mark Herwege) #103

A debug log would help. All of this seem to be messages I do not parse correctly because I don’t see them in my test setup. The debug log should show the message it fails on.


(Scott Rushworth) #104

I have a rule for playing audio notifications. I’ll need to do some more investigation to find out exactly how to reproduce it, but from my log entries, I suspect it occurs when the volume of all the speakers is changed through the Twonky API. The Twonky server is then making the UPnP calls to the speakers. This happens every time with version 2.4.0.201806281613, but only occasionally with the latest.

I believe this uncaught exception...
org.eclipse.jetty.io.EofException: Early EOF
        at org.eclipse.jetty.server.HttpInput$3.noContent(HttpInput.java:898)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:191)
        at java.io.InputStream.read(InputStream.java:101)
        at org.jupnp.util.io.IO.copyLarge(IO.java:980)
        at org.jupnp.util.io.IO.copy(IO.java:954)
        at org.jupnp.util.io.IO.toByteArray(IO.java:402)
        at org.jupnp.util.io.IO.readBytes(IO.java:121)
        at org.jupnp.transport.impl.ServletUpnpStream.readRequestMessage(ServletUpnpStream.java:137)
        at org.jupnp.transport.impl.ServletUpnpStream.run(ServletUpnpStream.java:61)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[Fatal Error] :1:70: The prefix "upnp" for element "upnp:class" is not bound.
org.eclipse.jetty.io.EofException: Early EOF
        at org.eclipse.jetty.server.HttpInput$3.noContent(HttpInput.java:898)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:191)
        at java.io.InputStream.read(InputStream.java:101)
        at org.jupnp.util.io.IO.copyLarge(IO.java:980)
        at org.jupnp.util.io.IO.copy(IO.java:954)
        at org.jupnp.util.io.IO.toByteArray(IO.java:402)
        at org.jupnp.util.io.IO.readBytes(IO.java:121)
        at org.jupnp.transport.impl.ServletUpnpStream.readRequestMessage(ServletUpnpStream.java:137)
        at org.jupnp.transport.impl.ServletUpnpStream.run(ServletUpnpStream.java:61)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
... possibly correlates to this warning...
2018-08-10 19:10:47.885 [WARN ] [org.eclipse.jetty.http.HttpParser] - bad HTTP parsed: 400 No URI for HttpChannelOverHttp@9b5399f{r=1,c=false,a=IDLE,uri=null}
... and here are the log entries during this time...
2018-08-10 19:10:45.483 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="NO_MEDIA_PRESENT"/>
    <CurrentTransportActions val="Stop"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:45.488 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTransportActions with value Stop from service AVTransport
2018-08-10 19:10:45.488 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:45.488 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-08-10 19:10:46.326 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="PLAYING"/>
    <CurrentTransportActions val="Pause,Stop,Next,Previous"/>
    <CurrentTrack val="1"/>
    <CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:pv=&quot;http://www.pv.com/pvns/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item restricted=&quot;1&quot; parentID=&quot;-1&quot; id=&quot;9085&quot;&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;res protocolInfo=&quot;http-get:*:audio/aac:*&quot;&gt;http://stream.europeanhitradio.com:8000/Stream_17.aac&lt;/res&gt;&lt;dc:title&gt;Stream_17&lt;/dc:title&gt;&lt;pv:supported&gt;true&lt;/pv:supported&gt;&lt;pv:pushSource&gt;10.5.5.10&lt;/pv:pushSource&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
    <CurrentTrackURI val="local://linein_party"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:46.328 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTransportActions with value Pause,Stop,Next,Previous from service AVTransport
2018-08-10 19:10:46.329 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value local://linein_party from service AVTransport
2018-08-10 19:10:46.330 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:46.330 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/aac:*">http://stream.europeanhitradio.com:8000/Stream_17.aac</res><dc:title>Stream_17</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 19:10:46.330 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrack with value 1 from service AVTransport
2018-08-10 19:10:46.330 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value PLAYING from service AVTransport
2018-08-10 19:10:47.035 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="PLAYING"/>
    <CurrentTransportActions val="Pause,Stop,Next,Previous"/>
    <CurrentPlayMode val="RANDOM"/>
    <CurrentTrackURI val="local://linein_party"/>
    <CurrentTrack val="1"/>
    <CurrentTrackMetaData val="&lt;DIDL-Lite &gt;
&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;1&quot;&gt;
&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;
&lt;dc:title&gt;Analog Input&lt;/dc:title&gt;
&lt;/item&gt; &lt;/DIDL-Lite&gt;"/>
    <AVTransportURI val="local://linein_party"/>
    <AVTransportURIMetaData val="&lt;DIDL-Lite &gt;
&lt;item id=&quot;-1&quot; parentID=&quot;-1&quot; restricted=&quot;1&quot;&gt;
&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;
&lt;dc:title&gt;Analog Input&lt;/dc:title&gt;
&lt;/item&gt; &lt;/DIDL-Lite&gt;"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:47.038 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURI with value local://linein_party from service AVTransport
2018-08-10 19:10:47.039 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURI with value local://linein_party from service AVTransport
2018-08-10 19:10:47.043 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTransportActions with value Pause,Stop,Next,Previous from service AVTransport
2018-08-10 19:10:47.043 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value local://linein_party from service AVTransport
2018-08-10 19:10:47.044 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:47.044 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value <DIDL-Lite > <item id="-1" parentID="-1" restricted="1"> <upnp:class>object.item.audioItem</upnp:class> <dc:title>Analog Input</dc:title> </item> </DIDL-Lite> from service AVTransport
2018-08-10 19:10:47.045 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURIMetaData with value <DIDL-Lite > <item id="-1" parentID="-1" restricted="1"> <upnp:class>object.item.audioItem</upnp:class> <dc:title>Analog Input</dc:title> </item> </DIDL-Lite> from service AVTransport
2018-08-10 19:10:47.045 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURIMetaData with value <DIDL-Lite > <item id="-1" parentID="-1" restricted="1"> <upnp:class>object.item.audioItem</upnp:class> <dc:title>Analog Input</dc:title> </item> </DIDL-Lite> from service AVTransport
2018-08-10 19:10:47.051 [DEBUG] [org.openhab.binding.upnpcontrol.internal.UpnpXMLParser] - Could not parse Entries from string '<DIDL-Lite > <item id="-1" parentID="-1" restricted="1"> <upnp:class>object.item.audioItem</upnp:class> <dc:title>Analog Input</dc:title> </item> </DIDL-Lite>'
2018-08-10 19:10:47.052 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentPlayMode with value RANDOM from service AVTransport
2018-08-10 19:10:47.052 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrack with value 1 from service AVTransport
2018-08-10 19:10:47.052 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value PLAYING from service AVTransport
2018-08-10 19:10:47.562 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="NO_MEDIA_PRESENT"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:47.563 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:47.563 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-08-10 19:10:47.669 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <CurrentTrackDuration val="0:00:00"/>
    <CurrentMediaDuration val="0:00:00"/>
    <AVTransportURI val="http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:47.672 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURI with value http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3 from service AVTransport
2018-08-10 19:10:47.673 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURI with value http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3 from service AVTransport
2018-08-10 19:10:47.673 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:47.673 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentMediaDuration with value 0:00:00 from service AVTransport
2018-08-10 19:10:47.673 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackDuration with value 0:00:00 from service AVTransport
2018-08-10 19:10:48.208 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="NO_MEDIA_PRESENT"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:48.209 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:48.209 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-08-10 19:10:48.478 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="NO_MEDIA_PRESENT"/>
    <PlaybackStorageMedium val="NONE"/>
    <NumberOfTracks val="0"/>
    <CurrentTrack val="0"/>
    <CurrentTrackMetaData val=""/>
    <CurrentTrackURI val=""/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:48.482 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable PlaybackStorageMedium with value NONE from service AVTransport
2018-08-10 19:10:48.482 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable NumberOfTracks with value 0 from service AVTransport
2018-08-10 19:10:48.482 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value  from service AVTransport
2018-08-10 19:10:48.482 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:48.483 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value  from service AVTransport
2018-08-10 19:10:48.483 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrack with value 0 from service AVTransport
2018-08-10 19:10:48.483 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-08-10 19:10:49.190 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="NO_MEDIA_PRESENT"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:49.192 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:49.192 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportState with value NO_MEDIA_PRESENT from service AVTransport
2018-08-10 19:10:49.652 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <PlaybackStorageMedium val="NONE"/>
    <NumberOfTracks val="0"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:49.653 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable PlaybackStorageMedium with value NONE from service AVTransport
2018-08-10 19:10:49.653 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable NumberOfTracks with value 0 from service AVTransport
2018-08-10 19:10:49.654 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:49.756 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:pv=&quot;http://www.pv.com/pvns/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item restricted=&quot;1&quot; parentID=&quot;-1&quot; id=&quot;9085&quot;&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:*&quot; size=&quot;206397&quot;&gt;http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3&lt;/res&gt;&lt;dc:title&gt;recycled.combined&lt;/dc:title&gt;&lt;pv:supported&gt;true&lt;/pv:supported&gt;&lt;pv:pushSource&gt;10.5.5.10&lt;/pv:pushSource&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
    <CurrentTrackURI val="http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3"/>
    <AVTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:pv=&quot;http://www.pv.com/pvns/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item restricted=&quot;1&quot; parentID=&quot;-1&quot; id=&quot;9085&quot;&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:*&quot; size=&quot;206397&quot;&gt;http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3&lt;/res&gt;&lt;dc:title&gt;recycled.combined&lt;/dc:title&gt;&lt;pv:supported&gt;true&lt;/pv:supported&gt;&lt;pv:pushSource&gt;10.5.5.10&lt;/pv:pushSource&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 19:10:49.758 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3 from service AVTransport
2018-08-10 19:10:49.758 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 19:10:49.758 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*" size="206397">http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3</res><dc:title>recycled.combined</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 19:10:49.758 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURIMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*" size="206397">http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3</res><dc:title>recycled.combined</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 19:10:49.758 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURIMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*" size="206397">http://fedora01.rushworth.us:8080/static/TTS/cmu_us_rms.flitevox/recycled.combined.mp3</res><dc:title>recycled.combined</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 19:10:49.759 [DEBUG] [org.openhab.binding.upnpcontrol.internal.UpnpXMLParser] - Did not recognise element named supported
2018-08-10 19:10:49.759 [DEBUG] [org.openhab.binding.upnpcontrol.internal.UpnpXMLParser] - Did not recognise element named pushSource
2018-08-10 19:10:49.761 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Failed to download the content of URL
... and the error may be occurring at this line...
2018-08-10 19:10:47.051 [DEBUG] [org.openhab.binding.upnpcontrol.internal.UpnpXMLParser] - Could not parse Entries from string '<DIDL-Lite > <item id="-1" parentID="-1" restricted="1"> <upnp:class>object.item.audioItem</upnp:class> <dc:title>Analog Input</dc:title> </item> </DIDL-Lite>'

Here's a new one. I believe this caught exception...
2018-08-10 18:53:25.120 [ERROR] [org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl] - Participant threw an exception onValueReceived
java.lang.NumberFormatException: null
        at java.lang.Long.parseLong(Long.java:552) [?:?]
        at java.lang.Long.parseLong(Long.java:631) [?:?]
        at org.openhab.binding.upnpcontrol.internal.UpnpXMLParser$EntryHandler.startElement(UpnpXMLParser.java:151) [512:org.openhab.binding.upnpcontrol:2.4.0.201808090837]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(AbstractSAXParser.java:509) [?:?]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:374) [?:?]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:2784) [?:?]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602) [?:?]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112) [?:?]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505) [?:?]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:842) [?:?]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:771) [?:?]
        at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141) [?:?]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213) [?:?]
        at org.openhab.binding.upnpcontrol.internal.UpnpXMLParser.getEntriesFromXML(UpnpXMLParser.java:81) [512:org.openhab.binding.upnpcontrol:2.4.0.201808090837]
        at org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:372) [512:org.openhab.binding.upnpcontrol:2.4.0.201808090837]
        at org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:353) [512:org.openhab.binding.upnpcontrol:2.4.0.201808090837]
        at org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl$UpnpSubscriptionCallback.eventReceived(UpnpIOServiceImpl.java:159) [224:org.eclipse.smarthome.io.transport.upnp:0.10.0.201808011124]
        at org.jupnp.controlpoint.SubscriptionCallback$2.eventReceived(SubscriptionCallback.java:222) [231:org.jupnp:2.4.0]
        at org.jupnp.model.gena.RemoteGENASubscription.receive(RemoteGENASubscription.java:114) [231:org.jupnp:2.4.0]
        at org.jupnp.protocol.sync.ReceivingEvent$2.run(ReceivingEvent.java:130) [231:org.jupnp:2.4.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
... correlates with this these log entries...
2018-08-10 18:47:29.596 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 18:53:25.116 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <NumberOfTracks val="1"/>
    <PlaybackStorageMedium val="NETWORK"/>
    <AVTransportURI val="http://emf.streamguys1.com/sa001_mp3_high_tunein"/>
    <TransportState val="STOPPED"/>
    <CurrentTrackMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:pv=&quot;http://www.pv.com/pvns/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item restricted=&quot;1&quot; parentID=&quot;-1&quot; id=&quot;9085&quot;&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:*&quot;&gt;http://emf.streamguys1.com/sa001_mp3_high_tunein&lt;/res&gt;&lt;dc:title&gt;sa001_mp3_high_tunein&lt;/dc:title&gt;&lt;pv:supported&gt;true&lt;/pv:supported&gt;&lt;pv:pushSource&gt;10.5.5.10&lt;/pv:pushSource&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
    <CurrentTrackURI val="http://emf.streamguys1.com/sa001_mp3_high_tunein"/>
    <AVTransportURIMetaData val="&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:pv=&quot;http://www.pv.com/pvns/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item restricted=&quot;1&quot; parentID=&quot;-1&quot; id=&quot;9085&quot;&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:*&quot;&gt;http://emf.streamguys1.com/sa001_mp3_high_tunein&lt;/res&gt;&lt;dc:title&gt;sa001_mp3_high_tunein&lt;/dc:title&gt;&lt;pv:supported&gt;true&lt;/pv:supported&gt;&lt;pv:pushSource&gt;10.5.5.10&lt;/pv:pushSource&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
  </InstanceID>
</Event> from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURI with value http://emf.streamguys1.com/sa001_mp3_high_tunein from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURI with value http://emf.streamguys1.com/sa001_mp3_high_tunein from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable PlaybackStorageMedium with value NETWORK from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable NumberOfTracks with value 1 from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value http://emf.streamguys1.com/sa001_mp3_high_tunein from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-10 18:53:25.118 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*">http://emf.streamguys1.com/sa001_mp3_high_tunein</res><dc:title>sa001_mp3_high_tunein</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 18:53:25.119 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURIMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*">http://emf.streamguys1.com/sa001_mp3_high_tunein</res><dc:title>sa001_mp3_high_tunein</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 18:53:25.119 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURIMetaData with value <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:pv="http://www.pv.com/pvns/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item restricted="1" parentID="-1" id="9085"><upnp:class>object.item.audioItem</upnp:class><res protocolInfo="http-get:*:audio/mpeg:*">http://emf.streamguys1.com/sa001_mp3_high_tunein</res><dc:title>sa001_mp3_high_tunein</dc:title><pv:supported>true</pv:supported><pv:pushSource>10.5.5.10</pv:pushSource></item></DIDL-Lite> from service AVTransport
2018-08-10 18:53:27.019 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <CurrentTransportActions val="Stop"/>
    <TransportState val="TRANSITIONING"/>
  </InstanceID>
</Event> from service AVTransport

There also looks to be a typo in the logging in this entry, where a close paren is used instead or a close curly brace...
2018-08-10 18:44:13.518 [DEBUG] [org.openhab.binding.upnpcontrol.handler.UpnpHandler] - Upnp device {) received subscription reply UPnP: Office from service true

(Mark Herwege) #105

@5iver
I found a little bit of time to improve this again. I have loaded a new version.
I now tested this with multiple servers and multiple renderers. I have ironed out most issues I found with this (renderers do not behave very consistently). I hope that also resolves your issues (I think it should).
Again, this is far from finished. To make this work consistently with various mixes of renderers and servers would need stress testing with a lot of combinations.
I have been using a TVersity media server running on a windows PC and a test media server from upnp.org. I could browse and search in both cases. I could then serve a queue of media to a Kodi renderer running on a PC and a upnp.org test renderer. Audio worked in all cases and the media nicely advanced to the next in the queue at the end of a track. For the Kodi renderer, also movie and images worked. Kodi also shows the meta data, as does the OH control point binding.
Next would be a possibility to define favorites from the content directory browse or search and store these on the control point for easy access.


OpenHAB and media repositories
(Scott Rushworth) #106

Sounds great! I’ll try it out right away. I’ve been busy migrating my rules to JSR223-Jython, and the last bit are the alert rules which rely heavily on UPnP. I plan to migrate all of it to use this binding instead of the scripts that I made. So, I should have some good feedback soon! I only have Sony SA-NS400 renderers for audio, but also have Kodi on a few FireTVs. I mainly use Twonky for the media server, but I plan to move the media over to my MythTV server, which is currently only used for PVR recordings.

Thank you for keeping this moving forward!


(Scott Rushworth) #107

Binding 2.4.0.201808280819 on OH snapshot 1341.

I'm getting these periodically...
2018-08-29 19:42:42.318 [ERROR] [org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl] - Participant threw an exception onValueReceived
java.lang.IllegalArgumentException: Invalid URI host: null (authority: null)
        at org.eclipse.jetty.client.HttpClient.checkHost(HttpClient.java:487) [77:org.eclipse.jetty.client:9.3.21.v20170918]
        at org.eclipse.jetty.client.HttpClient.newHttpRequest(HttpClient.java:472) [77:org.eclipse.jetty.client:9.3.21.v20170918]
        at org.eclipse.jetty.client.HttpClient.newRequest(HttpClient.java:430) [77:org.eclipse.jetty.client:9.3.21.v20170918]
        at org.eclipse.jetty.client.HttpClient.newRequest(HttpClient.java:419) [77:org.eclipse.jetty.client:9.3.21.v20170918]
        at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:213) [121:org.eclipse.smarthome.io.net:0.10.0.201808242044]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadData(HttpUtil.java:439) [121:org.eclipse.smarthome.io.net:0.10.0.201808242044]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:402) [121:org.eclipse.smarthome.io.net:0.10.0.201808242044]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:373) [121:org.eclipse.smarthome.io.net:0.10.0.201808242044]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:359) [121:org.eclipse.smarthome.io.net:0.10.0.201808242044]
        at org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler.updateMetaDataState(UpnpRendererHandler.java:583) [20:org.openhab.binding.upnpcontrol:2.4.0.201808280819]
        at org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:412) [20:org.openhab.binding.upnpcontrol:2.4.0.201808280819]
        at org.openhab.binding.upnpcontrol.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:356) [20:org.openhab.binding.upnpcontrol:2.4.0.201808280819]
        at org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl$UpnpSubscriptionCallback.eventReceived(UpnpIOServiceImpl.java:159) [230:org.eclipse.smarthome.io.transport.upnp:0.10.0.201808242044]
        at org.jupnp.controlpoint.SubscriptionCallback$2.eventReceived(SubscriptionCallback.java:222) [237:org.jupnp:2.4.0]
        at org.jupnp.model.gena.RemoteGENASubscription.receive(RemoteGENASubscription.java:114) [237:org.jupnp:2.4.0]
        at org.jupnp.protocol.sync.ReceivingEvent$2.run(ReceivingEvent.java:130) [237:org.jupnp:2.4.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-08-29 19:14:41.436 [ERROR] [org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl] - Participant threw an exception onValueReceived
2018-08-29 19:12:43.163 [ERROR] [org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl] - Participant threw an exception onValueReceived
2018-08-29 19:00:07.325 [ERROR] [org.eclipse.smarthome.io.transport.upnp.internal.UpnpIOServiceImpl] - Participant threw an exception onValueReceived

These occur every time an audio alert is being played. There’s a lot happening in the log at this time… too much to fit into a post. I’ve included the entire log, so that you can ge the bigger picture. When an audio alert is played, the speakers are put into Sony’s Party Mode, with one speaker as the host. Maybe this is causing the issue?

EDIT: this looks to be happening after… Received variable CurrentTrackMetaData. The files being played are TTS wav files generated though flite, then transcoded to mp3s with ffmpeg, so they shouldn’t have any metadata in them. They are also not in the Twonky library. I’m not including any metadata in the Twonky API call, but it looks like there’s something there. Maybe Twonky added it in.


(Mark Herwege) #108

@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.


(Stefan Kühnen) #109

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


(Scott Rushworth) #110

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?


(Stefan Kühnen) #111

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.


(Scott Rushworth) #112

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

(Stefan Kühnen) #113

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. :frowning:

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’


Webradio Template (?)
(Stefan Kühnen) #114

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>

(Michael) #115

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!


(Scott Rushworth) #117

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.


(Michael) #118

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!


(Scott Rushworth) #119

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?


(Michael) #120

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


(Scott Rushworth) #121

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