DLNA / UPNP binding

[5iver (Scott Rushworth)]

@Mherwege

@5iver

Looks good, except for the Player, which looks to be UNDEF after changing the renderer.

I would need a log here. It is supposed to refresh the status, and will only put it to UNDEF if it does not receive anything. I have multiple servers, but only on renderer in my test setup, so difficult to test with this setup at the moment.

2020-08-22 00:08:10.278 [WARN ] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Cannot serve media from server TwonkyMedia [NAS01], no renderer selected
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395 for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:upnprenderer on server TwonkyMedia [NAS01]
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:volume on server TwonkyMedia [NAS01]
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395:volume on renderer Portable
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:mute on server TwonkyMedia [NAS01]
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395:mute on renderer Portable
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:control on server TwonkyMedia [NAS01]
2020-08-22 00:09:24.227 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395:control on renderer Portable
2020-08-22 00:09:24.228 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Set server handler TwonkyMedia [NAS01] on renderer Portable
2020-08-22 00:09:24.237 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Portable invoke upnp action GetVolume on service RenderingControl with inputs {InstanceID=0, Channel=Master}
2020-08-22 00:09:24.237 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Portable invoke upnp action GetVolume on service RenderingControl reply {CurrentVolume=30}
2020-08-22 00:09:24.238 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Portable received variable MasterVolume with value 30 from service RenderingControl
2020-08-22 00:09:24.238 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Update server TwonkyMedia [NAS01] channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395:volume state from renderer Portable
2020-08-22 00:09:24.242 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Portable invoke upnp action GetMute on service RenderingControl with inputs {InstanceID=0, Channel=Master}
2020-08-22 00:09:24.243 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Portable invoke upnp action GetMute on service RenderingControl reply {CurrentMute=false}
2020-08-22 00:09:24.243 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Portable received variable MasterMute with value false from service RenderingControl
2020-08-22 00:09:24.243 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Update server TwonkyMedia [NAS01] channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-30f9ed4f6395:mute state from renderer Portable
2020-08-22 00:13:14.806 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909 for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:upnprenderer on server TwonkyMedia [NAS01]
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:volume on server TwonkyMedia [NAS01]
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909:volume on renderer Living Room
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:mute on server TwonkyMedia [NAS01]
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909:mute on renderer Living Room
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpServerHandler] - Handle command REFRESH for channel upnpcontrol:upnpserver:55076f6e-6b79-1d65-a4eb-00089bd0e8f2:control on server TwonkyMedia [NAS01]
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command REFRESH for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909:control on renderer Living Room
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Unset server handler on renderer Portable
2020-08-22 00:13:14.807 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Set server handler TwonkyMedia [NAS01] on renderer Living Room
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Living Room invoke upnp action GetMute on service RenderingControl with inputs {InstanceID=0, Channel=Master}
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Living Room invoke upnp action GetVolume on service RenderingControl with inputs {InstanceID=0, Channel=Master}
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Living Room invoke upnp action GetMute on service RenderingControl reply {CurrentMute=false}
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Living Room invoke upnp action GetVolume on service RenderingControl reply {CurrentVolume=25}
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Living Room received variable MasterMute with value false from service RenderingControl
2020-08-22 00:13:14.824 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Living Room received variable MasterVolume with value 25 from service RenderingControl
2020-08-22 00:13:14.825 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Update server TwonkyMedia [NAS01] channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909:mute state from renderer Living Room
2020-08-22 00:13:14.825 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Update server TwonkyMedia [NAS01] channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f5210909:volume state from renderer Living Room

[Mherwege (Mark Herwege)]

@5iver I did a lot of changes in the binding to cope with the timeouts, search etc. I also implemented repeat and shuffle channels on the renderer for continuous play and random sequence.
It may not be perfect yet, but I don’t see issues anymore.
So I believe it is time for another test.

[5iver (Scott Rushworth)]

I have a few FireTV devices. They use UPnP for screen mirroring. I have OH System> Network Settings configured to use only one IP per interface and our subnet (not 192.168.49.1), but I still get these from the FireTV devices…

2020-08-25 11:13:12.981 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:13.029 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:13.155 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:13.198 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:13.329 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:13.380 [DEBUG] [org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] - Device type dial, manufacturer Amazon, model AFTT, SN# null
2020-08-25 11:13:22.985 [INFO ] [org.jupnp.transport.spi.StreamClient] - Timeout of 10 seconds while waiting for HTTP request to complete, aborting: (StreamRequestMessage) GET http://192.168.49.1:60000/upnp/dev/532e6fa6-9336-330d-86af-eea96e4ee3ea/desc
2020-08-25 11:13:22.985 [WARN ] [org.jupnp.protocol.RetrieveRemoteDescriptors] - Device descriptor retrieval failed, no response: http://192.168.49.1:60000/upnp/dev/532e6fa6-9336-330d-86af-eea96e4ee3ea/desc

[Mherwege (Mark Herwege)]

That looks normal to me. The upnpcontrol discovery is a upnp discovery participant. It will see the discovery messages pass by for all devices that can be discovered as upnp devices, but only react to mediaserver or mediarenderer devices. It is only the debug log that will be written (that is there to make sure I can verify I didn’t miss any device).

[5iver (Scott Rushworth)]

@Mherwege

but only react to mediaserver or mediarenderer devices

It was the 10s timeoiut that caught my eye, but I missed the part that it was jupnp!

[5iver (Scott Rushworth)]

Using the latest and doing a simple playStream…

from core.actions import Audio
Audio.playStream("upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f522dcaf", "http://stream.europeanhitradio.com:8000/Stream_17.aac")

… I am seeing a timeout more often than not…

2020-08-25 15:10:14.357 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-25 15:10:14.357 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-25 15:10:14.377 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://stream.europeanhitradio.com:8000/Stream_17.aac, CurrentURIMetaData=}
2020-08-25 15:10:14.377 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-08-25 15:10:16.847 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Timeout exception, cannot play, media URI not yet set in the renderer

[Mherwege (Mark Herwege)]

What was playing just before the stream? I see a stop command being given just before. It is the full sequence that may matter.

[5iver (Scott Rushworth)]

Here is a stream that played and was then stopped. When starting the same stream, it timed out.

2020-08-25 15:51:41.622 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-25 15:51:41.623 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-25 15:51:41.662 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://stream.europeanhitradio.com:8000/Stream_17.aac, CurrentURIMetaData=}
2020-08-25 15:51:41.662 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-08-25 15:51:41.690 [INFO ] [org.jupnp.transport.impl.async.AsyncServlet] - HttpServlet.service(): id: 865, request URI: /upnpcallback/dev/5f9ec1b3-ed59-1900-4530-0007f522dcaf/svc/upnp-org/AVTransport/event/cb
2020-08-25 15:51:41.692 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room 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://stream.europeanhitradio.com:8000/Stream_17.aac"/>
  </InstanceID>
</Event> from service AVTransport
2020-08-25 15:51:41.694 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable AVTransportURI with value http://stream.europeanhitradio.com:8000/Stream_17.aac from service AVTransport
2020-08-25 15:51:41.694 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTrackURI with value http://stream.europeanhitradio.com:8000/Stream_17.aac from service AVTransport
2020-08-25 15:51:41.694 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-25 15:51:41.694 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentMediaDuration with value 0:00:00 from service AVTransport
2020-08-25 15:51:41.694 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTrackDuration with value 0:00:00 from service AVTransport
2020-08-25 15:51:41.743 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2020-08-25 15:51:41.743 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Play on service AVTransport reply {}
2020-08-25 15:51:41.970 [INFO ] [org.jupnp.transport.impl.async.AsyncServlet] - HttpServlet.service(): id: 866, request URI: /upnpcallback/dev/5f9ec1b3-ed59-1900-4530-0007f522dcaf/svc/upnp-org/AVTransport/event/cb
2020-08-25 15:51:41.971 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <CurrentTrackURI val="http://stream.europeanhitradio.com:8000/Stream_17.aac"/>
    <TransportState val="TRANSITIONING"/>
    <CurrentTransportActions val="Stop"/>
  </InstanceID>
</Event> from service AVTransport
2020-08-25 15:51:41.972 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTransportActions with value Stop from service AVTransport
2020-08-25 15:51:41.972 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTrackURI with value http://stream.europeanhitradio.com:8000/Stream_17.aac from service AVTransport
2020-08-25 15:51:41.972 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-25 15:51:41.973 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TransportState with value TRANSITIONING from service AVTransport
2020-08-25 15:51:48.570 [INFO ] [org.jupnp.transport.impl.async.AsyncServlet] - HttpServlet.service(): id: 867, request URI: /upnpcallback/dev/5f9ec1b3-ed59-1900-4530-0007f522dcaf/svc/upnp-org/AVTransport/event/cb
2020-08-25 15:51:48.571 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room 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"/>
  </InstanceID>
</Event> from service AVTransport
2020-08-25 15:51:48.572 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTransportActions with value Pause,Stop,Next,Previous from service AVTransport
2020-08-25 15:51:48.572 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-25 15:51:48.572 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TransportState with value PLAYING from service AVTransport
2020-08-25 15:51:48.606 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TrackURI with value http://stream.europeanhitradio.com:8000/Stream_17.aac from service AVTransport



2020-08-25 15:52:07.163 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Handle command ON for channel upnpcontrol:upnprenderer:5f9ec1b3-ed59-1900-4530-0007f522dcaf:stop on renderer Family Room
2020-08-25 15:52:07.239 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-25 15:52:07.239 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-25 15:52:07.265 [INFO ] [org.jupnp.transport.impl.async.AsyncServlet] - HttpServlet.service(): id: 868, request URI: /upnpcallback/dev/5f9ec1b3-ed59-1900-4530-0007f522dcaf/svc/upnp-org/AVTransport/event/cb
2020-08-25 15:52:07.267 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room 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
2020-08-25 15:52:07.268 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTransportActions with value Play,Next,Previous from service AVTransport
2020-08-25 15:52:07.268 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-25 15:52:07.269 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TransportState with value STOPPED from service AVTransport



2020-08-25 15:52:16.021 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-25 15:52:16.022 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-25 15:52:16.043 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://stream.europeanhitradio.com:8000/Stream_17.aac, CurrentURIMetaData=}
2020-08-25 15:52:16.043 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-08-25 15:52:18.512 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Timeout exception, cannot play, media URI not yet set in the renderer

[Mherwege (Mark Herwege)]

And the URI is received immediately after the exception? It looks like it is still the same blocking issue of the GENA events thread causing it. I was sure I had solved it (I could reproduce and didn’t have it anymore), but I must have missed something.

[5iver (Scott Rushworth)]

@Mherwege

And the URI is received immediately after the exception?

I’m not sure what you are asking. The speaker played the first time but not the second time. I’ve looked through the code, but have not spotted anything in what was recently changed.

[Mherwege (Mark Herwege)]

The last message in your log is the timeout message.
In my testing, the message immediately following is always the receiving of the AVTransportURI. The timeout happens because we were waiting for it. But apparently, the whole thing is blocked until the timeout releases it.
So I was looking for confirmation it is still that same behavior I observed before.

[Mherwege (Mark Herwege)]

@5iver For testing, I use PaperUI with simple mode. That has the advantage I don’t need to create items for my channels to quickly test, and I can easily debug from Eclipse.
The challenge is running rules with actions. I can use the NGRE in PaperUI to simply play a sound to test the playSound action, but I cannot test the playStream action the same way. It is not available.
Could I do that with a few lines of javascript in a script action? I tried, but couldn’t get it to work. That would simplify testing this a lot. It would avoid setting up jython in the development environment.
I know you are the expert on this, so maybe you have some quick advice.
This is what I tried as a script action, but I get a ClassNotFoundException:

var Audio = Java.type("org.openhab.core.model.script.actions.Audio")
Audio.playStream("http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3")

[5iver (Scott Rushworth)]

Using the JS helper libraries is a little easier, since you do not need to know the class…

'use strict';

var OPENHAB_CONF = Java.type("java.lang.System").getenv("OPENHAB_CONF");
load(OPENHAB_CONF + '/automation/lib/javascript/core/actions.js');
Audio.playStream("http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3")

Without the helper libraries and using OHC 2.5.0, you would do…

'use strict';

var Audio = Java.type("org.eclipse.smarthome.model.script.actions.Audio")
Audio.playStream("http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3")

I have not tried this with OH 3.0, but what you had should work.

@Mherwege

It would avoid setting up jython in the development environment.

I’ll work on posting a tutorial for it, but it is very simple. You just need to add one line to the bottom of the org.openhab.demo.app/app.bndrun file…

-runvm: -Xbootclasspath/a:${.}/runtime/conf/automation/jython/jython-standalone-2.7.2.jar,-Dpython.home=${.}/runtime/conf/automation/jython,-Dpython.path=${.}/runtime/conf/automation/lib/python

You then need to copy in the Jython jar to the correct location. You will then have the option to use Jython in Actions and Conditions within the UI rule editor inside the IDE.

[Mherwege (Mark Herwege)]

@5iver

'use strict';

var Audio = Java.type("org.eclipse.smarthome.model.script.actions.Audio")
Audio.playStream("http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3")

I am still developing for 2.5.0, so going with this version. I did try this classpath before, but with the same result. I get the following in the Eclipse console:

16:30:14.524 [p330434288-2195] WARN  o.o.c.a.internal.RuleEngineImpl:1200 - Fail to execute action: 1
java.lang.RuntimeException: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.Audio cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
	at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:397)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:449)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:406)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:402)
	at jdk.nashorn.api.scripting.NashornScriptEngine.eval(NashornScriptEngine.java:155)
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:62)
	at java.util.Optional.ifPresent(Optional.java:159)
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:59)
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1189)
	at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1037)
	at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1053)
	at org.openhab.core.automation.rest.internal.RuleResource.runNow(RuleResource.java:288)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544)
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307)
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:494)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.Audio cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:511)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:422)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:414)
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:153)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
	at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:612)
	at org.ops4j.pax.swissbox.core.BundleClassLoader.findClass(BundleClassLoader.java:176)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
	at org.ops4j.pax.swissbox.core.BundleClassLoader.loadClass(BundleClassLoader.java:192)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:348)
	at jdk.nashorn.internal.runtime.Context.findClass(Context.java:1051)
	at jdk.nashorn.internal.objects.NativeJava.simpleType(NativeJava.java:498)
	at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:322)
	at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:314)
	at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:310)
	at jdk.nashorn.internal.scripts.Script$25$\^eval\_.:program(<eval>:3)
	at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637)
	at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494)
	at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393)
	... 72 common frames omitted

But smarthome:audio stream http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3 from the console does work. And I haven’t been able to reproduce any timeouts using that yet. I am at a loss for now I am afraid.

[5iver (Scott Rushworth)]

I’m getting a NPE when running app.bndrun in my IDE . Have you tried adding org.eclipse.smarthome.model.script to the Run Requirements? I would think that would resolve it, but you may need to add some audio packages too.

[Mherwege (Mark Herwege)]

The org.openhab.core.model.script [2.5.0, 2.5.1) bundle is already part of the run bundles after resolving. So, I believe the package is there (I believe the bundles have been renamed for core 2.5, but not the package names).

[5iver (Scott Rushworth)]

Mark, I got this working in another IDE, but the script is not erroring and started the stream. I then stopped OH to get some logging configuration chnages to take effect, and I got the timeout. Now, what is a little different here is that the stream was already playing from the last time I had run the script, but I’m thinking that should not matter. I will play some more to see if I can continue to reproduce the problem.

2020-08-27 00:53:22.003 [INFO ] [org.eclipse.smarthome.core.service.AbstractWatchService] - Loading script 'demo.js'
2020-08-27 00:53:22.103 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TrackURI with value http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3 from service AVTransport
2020-08-27 00:53:22.607 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-27 00:53:22.607 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-27 00:53:22.700 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3, CurrentURIMetaData=}
2020-08-27 00:53:22.700 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-08-27 00:53:23.074 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportState val="STOPPED"/>
  </InstanceID>
</Event> from service AVTransport
2020-08-27 00:53:23.077 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-27 00:53:23.077 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable TransportState with value STOPPED from service AVTransport
2020-08-27 00:53:23.079 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Cannot serve next, end of queue on renderer Family Room
2020-08-27 00:53:23.091 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-27 00:53:23.091 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-27 00:53:23.390 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <CurrentTransportActions val="Play,Next,Previous"/>
  </InstanceID>
</Event> from service AVTransport
2020-08-27 00:53:23.393 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable CurrentTransportActions with value Play,Next,Previous from service AVTransport
2020-08-27 00:53:23.393 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Upnp device Family Room received variable InstanceID with value 0 from service AVTransport
2020-08-27 00:53:25.080 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Timeout exception, cannot play, media URI not yet set in the renderer

Here is another from when nothing was playing…

g! 2020-08-27 01:00:24.610 [INFO ] [org.eclipse.smarthome.core.service.AbstractWatchService] - Loading script 'demo.js'
2020-08-27 01:00:24.926 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport with inputs {InstanceID=0}
2020-08-27 01:00:24.926 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action Stop on service AVTransport reply {}
2020-08-27 01:00:24.949 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://icecast.vrtcdn.be/stubru_tijdloze-high.mp3, CurrentURIMetaData=}
2020-08-27 01:00:24.949 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler] - Upnp device Family Room invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-08-27 01:00:27.411 [DEBUG] [org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler] - Timeout exception, cannot play, media URI not yet set in the renderer

[5iver (Scott Rushworth)]

Steps that I took inside Eclipse to setup the binding in the IDE. Hopefully there is something here that will fix your error.

1. Checkout 2.5 branch for openhab-distro
2. Clone your fork
3. Build the demo app
4. Build the binding
5. Search for the binding under Browse Repos
6. Drag and drop the binding into Run Requirements
7. Resolve app
8. Debug OSGi

I seem to be able to reproduce the timeout consistently:

1. Play a stream using the script
2. Stop the renderer using in Paper UI> Control
3. Run the script a second time

When I play the same stream, the timeout occurs. When I play a new stream each time, the timeout has not been occuring!

[Mherwege (Mark Herwege)]

Thanks for trying.
I followed the same procedure when installing Eclipse a while ago. What version of Eclipse are you currently running? I am running Version: 2020-03 (4.15.0),
Build id: 20200313-1211. I held off updating Eclipse for a while already as I know some changes in the libary versions can play havoc with the install. And except the script execution, it works for now. I can only assume there is a version difference in one of the libraries with the OSGI resolve between your and my installation.

I have been trying exactly the same thing yesterday as you do:

1. Play a stream using the console command (smarthome:audio stream …)
2. Stop the rendererer using Paper UI> Control
3. Play the stream again using the same console command

I was never able to get a timeout. My renderer is a test renderer running on the same computer I develop on. So that should improve reactivity, but I don’t think that can explain why mine would not time out, while yours does. After all, the timeout is 2.5s and the whole thing seems to be blocked until the timeout is reached. After that, it continues immediately.

I am investigating further.

[5iver (Scott Rushworth)]

@Mherwege

What version of Eclipse are you currently running?

I have a few installations of Eclipse. The one I used for this is pretty old: