DLNA / UPNP binding

Mherwege · July 1, 2018, 4:05pm

@mjptec
I don’t do anything special here. I rely on the upnp discovery functionality in the framework to discover all upnp device for me an pick the ones that are servers and renderers. I don’t have code to remove them. So at first it looks like a framework problem.
You couldctry to switch on debug logging for the binding, as it will list a bit more info on what is being detected.
Also, I saw the underlying upnp library just got upgraded. That may solve some issues. It is not in 2.3 stable yet though.

mjptec · July 2, 2018, 12:47pm

Thanks @Mherwege, I’m on a 2.4 snapshot anyway so will update tonight and post some debug logs if it is still doing it.

mjptec · July 2, 2018, 10:24pm

Not sure why at the moment, but on reinstalling I got build 1307 again, so no change from before. I’ll try again tomorrow.

Unfortunately the debug output only adds the following:

02-Jul-2018 23:09:40.385 [DEBUG] [internal.discovery.UpnpControlDiscoveryParticipant] - Device type MediaServer, manufacturer Emby, model Emby Server, SN# 263de70f43c34416927ed0dd159a399a
02-Jul-2018 23:09:40.385 [DEBUG] [internal.discovery.UpnpControlDiscoveryParticipant] - Media server found: Emby, Emby Server
02-Jul-2018 23:09:40.418 [DEBUG] [internal.discovery.UpnpControlDiscoveryParticipant] - Device type MediaServer, manufacturer Emby, model Emby Server, SN# 263de70f43c34416927ed0dd159a399a
02-Jul-2018 23:09:40.419 [DEBUG] [internal.discovery.UpnpControlDiscoveryParticipant] - Media server found: Emby, Emby Server
etc

I am now for some reason able to add the thing, but it doesn’t change the above log and the event log now spits out the following every 30 seconds:

2018-07-02 23:17:16.548 [hingStatusInfoChangedEvent] - 'upnpcontrol:upnpserver:263de70f43c34416927ed0dd159a399a' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication lost with Emby - eek2
2018-07-02 23:17:16.548 [hingStatusInfoChangedEvent] - 'upnpcontrol:upnpserver:263de70f43c34416927ed0dd159a399a' changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with Emby - eek2 to ONLINE
2018-07-02 23:17:16.607 [hingStatusInfoChangedEvent] - 'upnpcontrol:upnpserver:263de70f43c34416927ed0dd159a399a' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication lost with Emby - eek2
2018-07-02 23:17:16.641 [hingStatusInfoChangedEvent] - 'upnpcontrol:upnpserver:263de70f43c34416927ed0dd159a399a' changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with Emby - eek2 to ONLINE
etc

Mherwege · July 3, 2018, 6:11am

I don’t know why your media server’s visibility changes like that.
I receive this status from the underlying upnp transport bundle and switch the device online/offline accordingly. The transport is doing polling for this.
You could try setting debug level logging for org.eclipse.smarthome.io.transport.upnp. That should provide much more info.

mjptec · July 3, 2018, 8:48pm

Thanks for the pointer. I can at least confirm it is a problem at the framework level:

03-Jul-2018 21:43:16.501 [DEBUG] [thome.io.transport.upnp.internal.UpnpIOServiceImpl] - Device '263de70f43c34416927ed0dd159a399a' reachability status changed to 'false'
03-Jul-2018 21:43:16.526 [DEBUG] [thome.io.transport.upnp.internal.UpnpIOServiceImpl] - Device '263de70f43c34416927ed0dd159a399a' reachability status changed to 'true'
03-Jul-2018 21:43:16.528 [DEBUG] [thome.io.transport.upnp.internal.UpnpIOServiceImpl] - Device '263de70f43c34416927ed0dd159a399a' reachability status changed to 'false'
03-Jul-2018 21:43:16.528 [DEBUG] [thome.io.transport.upnp.internal.UpnpIOServiceImpl] - Device '263de70f43c34416927ed0dd159a399a' reachability status changed to 'true'

I’ll keep prodding and report back if I find anything.

Mherwege · August 7, 2018, 4:21pm

For all interested.
I have updated my UPnP binding with UPnP server directory search capabilities. Fee free to try. You can find the .jar here. The search works by entering search criteria in UPnP search string format. Examples:

dc:title contains “song”
dc:creator contains “Springsteen”
upnp:class = “object.item.audioItem”
upnp:album contains “Born in”

The code is on my personal GitHub page here. It is far from production ready code and I don’t have plans to make it perfect. But you can use it if it is of benefit to you.

5iver · August 7, 2018, 4:51pm

Thank you! When the binding starts, I get these uncaught exceptions in Karaf, but the Things appear to be online. I’ll focus some testing of this binding in the next few days. I’m using OH snapshot 1325.

493 │ Active   │  80 │ 2.4.0.201808071611     │ UPnPControlPoint Binding
openhab> bundle:restart 493
openhab> [Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.
[Fatal Error] :1:1: Premature end of file.

EDIT: after some time, there was more to the error…

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)

Mherwege · August 8, 2018, 3:16pm

I don’t know what this error means. I don’t see it linking back to my code in the error message. It would be useful to get some debug messages from the binding just before these errors included here. I did do an update today, so you may want to try again.
Changes:

Made sort order configurable through a server thing parameter.
Implemented previous, to go back to previous entry playing on the renderer.
Added track duration channel on renderer.
Improvements in search, browse and media serving.

5iver · August 8, 2018, 5:19pm

When I restart the binding, I get seven of these…

[Fatal Error] :1:1: Premature end of file.

And in the log, I have seven vaiations of this (note empty string used in log and last entry)…

nding.upnpcontrol.handler.UpnpRendererHandler] - Device UPnP: Master Downstairs supports audio
2018-08-08 12:26:40.481 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURI with value  from service AVTransport
2018-08-08 12:26:40.484 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURI with value  from service AVTransport
2018-08-08 12:26:40.485 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportPlaySpeed with value 1 from service AVTransport
2018-08-08 12:26:40.484 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Registering Audio Sink for renderer UPnP: Master Downstairs
2018-08-08 12:26:40.485 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackURI with value  from service AVTransport
2018-08-08 12:26:40.485 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable InstanceID with value 0 from service AVTransport
2018-08-08 12:26:40.485 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentTrackMetaData with value  from service AVTransport
2018-08-08 12:26:40.485 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable TransportStatus with value OK from service AVTransport
2018-08-08 12:26:40.486 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable AVTransportURIMetaData with value  from service AVTransport
2018-08-08 12:26:40.486 [DEBUG] [ab.binding.upnpcontrol.handler.UpnpRendererHandler] - Received variable CurrentURIMetaData with value  from service AVTransport
2018-08-08 12:26:40.486 [DEBUG] [openhab.binding.upnpcontrol.internal.UpnpXMLParser] - Could not parse Entries from string ''

Unrelated, but filtering UPnP Things in Habmin, shows that the Thing statuses don’t look to be displaying properly for devices that are offline (Guest Bathroom).

)

The results with the latest version are the same.

Mherwege · August 9, 2018, 8:44am

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.

5iver · August 10, 2018, 12:53am

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)

Mherwege · August 10, 2018, 6:29am

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.

5iver · August 10, 2018, 11:57pm

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

Mherwege · August 28, 2018, 8:34am

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

5iver · August 28, 2018, 10:07am

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!

5iver · August 30, 2018, 12:49am

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.

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.