DLNA / UPNP binding

Add-ons Bindings
262

Since there has been put a lot of effort into this binding since I tried it about 1 year ago, I am willing to try it again with my DLNA capable Wifi Speaker. Only updating the binding on my 2.4 OH install gave

020-10-08 02:48:21.890 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB': null
java.lang.NullPointerException: null
    at java.util.Objects.requireNonNull(Objects.java:203) ~[?:1.8.0_252]
    at java.util.Arrays$ArrayList.<init>(Arrays.java:3813) ~[?:1.8.0_252]
	at java.util.Arrays.asList(Arrays.java:3800) ~[?:1.8.0_252]
	at org.openhab.binding.upnpcontrol.internal.util.UpnpControlUtil.list(UpnpControlUtil.java:105) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.util.UpnpControlUtil.updatePlaylistsList(UpnpControlUtil.java:42) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler.initialize(UpnpHandler.java:149) ~[?:?]
    at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.initialize(UpnpRendererHandler.java:175) ~[?:?]
    at sun.reflect.GeneratedMethodAccessor94.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

So next try will be to update my OH install to latest (2.5.9)

263

The Thing definitions have changed, so be sure to also delete and rediscover your upnpcontrol Things.

264

Not much change here. Thing is showing

UNINITIALIZED - HANDLER_INITIALIZING_ERROR
265

Since the old binding would have been installed manually, you may also need to clear the cache too. If you update OH, you’ll be doing this anyhow. Looking at your error, it looks like the latest binding would not be compatible with OH 2.4.

266

@DonStefano Thank you for testing.
You did find an actual bug I hadn’t catched yet. The binding reads saved playlists from a directory on disk, but fails when no playlists exist yet with the above exception. In all my personal testing, I already had saved playlists before hitting this.
Thank you for discovering. I fixed it and the latest version should not get stuck on this.
However, I do test on 2.5.9, so I cannot guarantee there is nothing that will block on 2.4. My intention is to only get this massive extension to the binding reviewed for 3.0 once I submit for review.

267

Yes, did both of them. I’m now on 2.5.9 and have cleared the cache after updating.

268

Thank you Mark, for solving that bug. :slight_smile:
I have downloaded and installed from source above (renamed file to be sure to have new version) and it gives different result, so I assume it’s already new version. Do I have to install any dependency first?It now gives:

2020-10-08 10:28:51.649 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.upnpcontrol-2.5.9-SNAPSHOT-2020-10-08.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.upnpcontrol [206]
  Unresolved requirement: Import-Package: org.eclipse.smarthome.config.discovery.upnp
            at org.eclipse.osgi.container.Module.start(Module.java:444) ~[org.eclipse.osgi-3.12.100.jar:?]
            at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[org.eclipse.osgi-3.12.100.jar:?]
            at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [bundleFile:3.6.4]
            at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [bundleFile:3.6.4]
            at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [bundleFile:3.6.4]
            at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [bundleFile:3.6.4]
            at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [bundleFile:3.6.4]

I tried what was suggested before, but

feature:install esh-io-transport-upnp

gave

Error executing command: No matching features for esh-io-transport-upnp/0

But later thing came online. Maybe after cleaning cache something was executed in wrong order. I will check during next restart if it gets solved.

Now tried to set URI to play my web radio stream. From the status on the pioneer binding I saw that the speaker switches to UPNP mode correctly, but no sound is audible. I have set the log to DEBUG to see more messages of the binding.

2020-10-08 11:30:54.967 [ome.event.ItemCommandEvent] - Item 'XWSMA32337FB_URI' received command http://mp3-live.dasding.de/dasding_m.m3u

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

2020-10-08 11:30:54.971 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command http://mp3-live.dasding.de/dasding_m.m3u for channel upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB:uri on renderer XW-SMA3 2337FB
2020-10-08 11:30:54.972 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://mp3-live.dasding.de/dasding_m.m3u, CurrentURIMetaData=}

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

2020-10-08 11:30:54.980 [nt.ItemStatePredictedEvent] - XWSMA32337FB_URI predicted to become http://mp3-live.dasding.de/dasding_m.m3u

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

2020-10-08 11:30:54.987 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-10-08 11:30:57.481 [DEBUG] [internal.handler.UpnpRendererHandler] - Timeout exception, media URI not yet set in renderer XW-SMA3 2337FB, trying to play anyway
2020-10-08 11:30:57.481 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2020-10-08 11:30:57.486 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action Play on service AVTransport reply {}

Is there a timeout value I can increase?

269

Try feature:install openhab-transport-upnp. You need to explicitly load the transport if no other binding you use relies on the UPnP transport.
There is a configuration option on the thing to increase the timeout, but I doubt that’s the issue. It may be GENA. events are not started because of the missing feature, so no event messages are received.

270

Yes, that solved the error messages. I did:

feature:install openhab-transport-upnp
bundle:restart  org.openhab.binding.upnpcontrol

Now even with debug messages on, I can’t spot an error. But the speaker stays silent. :frowning:

Would it be usefull to create a complete debug log from start to completion (playing)?

271

I just tried setting different stream URI with mp3 as extension. It seems, it was not able to extract the stream from the m3u. I downloaded the m3u to disk and have extracted the URI ending with stream.mp and it works! Still there’s no error message when it does not accept the URI and the timeout message is also still there (must have missed it before).

2020-10-08 16:35:04.995 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://swr-edge-2022-dus-lg-cdn.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3, CurrentURIMetaData=}
2020-10-08 16:35:05.046 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-10-08 16:35:07.496 [DEBUG] [internal.handler.UpnpRendererHandler] - Timeout exception, media URI not yet set in renderer XW-SMA3 2337FB, trying to play anyway
2020-10-08 16:35:07.497 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}
2020-10-08 16:35:07.507 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action Play on service AVTransport reply {}

I’m also able to use playStream as I was able to do before upgrade to 2.3.

Thanks a lot for this great work! :slight_smile:

1 Like
272

@DonStefano I don’t see any event messages coming back in your debug log extract. So I still think something is wrong and the GENA events are not arriving. A debug log from the start may be helpful, see if we can find something there. Beyond that, you may also want to look into logging org.jupnp.transport.

I don’t have a good way to catch the errors as in the example you gave. The UpnpIOService writes the error in the debug log, but eats the error and does not return it to the binding. The binding only sees (or doesn’t see) the result. I expect you would see the error in the log if you turn on debug logging for org.eclipse.smarthome.io.transport.upnp.

273

I have enabled debug log for org.eclipse.smarthome.io.transport.upnp since a while now and most of the time the service was running smoothly without problems. Only message I saw regularly in the log was:

2020-10-30 13:12:20.578 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Polling participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB' through Action 'GetCurrentConnectionIDs' of Service 'ConnectionManager'

But from time to time it seems to loose connection and is no longer responding to commands. Then the regular log sequence is like:

2020-10-30 13:12:31.504 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetCurrentConnectionInfo on service ConnectionManager with inputs {ConnectionId=0}
2020-10-30 13:12:41.504 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Current state of service prevents invoking that action. Connection error or no response received.
2020-10-30 13:12:41.505 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetCurrentConnectionInfo on service ConnectionManager reply {}
2020-10-30 13:13:26.504 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetProtocolInfo on service ConnectionManager with inputs {}

When I try to set URI it gives:

2020-10-30 13:24:00.591 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Polling participant '5F9EC1B3-ED59-79C2-4530-745E1C2337FB' through Action 'GetCurrentConnectionIDs' of Service 'ConnectionManager' 
2020-10-30 13:24:08.015 [DEBUG] [internal.handler.UpnpRendererHandler] - Handle command http://swr-edge-2022-dus-lg-cdn.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3 for channel upnpcontrol:upnprenderer:5F9EC1B3-ED59-79C2-4530-745E1C2337FB:uri on renderer XW-SMA3 2337
2020-10-30 13:24:08.016 [DEBUG] [internal.handler.UpnpRendererHandler] - New URI http://swr-edge-2022-dus-lg-cdn.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3 is same as previous on renderer XW-SMA3 2337FB
2020-10-30 13:24:08.017 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport with inputs {InstanceID=0, CurrentURI=http://swr-edge-2022-dus-lg-cdn.cast.addradio.de/swr/dasding/live/mp3/128/stream.mp3, CurrentURIMetaData=}
2020-10-30 13:24:18.018 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Current state of service prevents invoking that action. Connection error or no response received.
2020-10-30 13:24:18.018 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action SetAVTransportURI on service AVTransport reply {}
2020-10-30 13:24:18.019 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetCurrentConnectionInfo on service ConnectionManager with inputs {ConnectionId=0}
2020-10-30 13:24:28.019 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Current state of service prevents invoking that action. Connection error or no response received.
2020-10-30 13:24:28.020 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetCurrentConnectionInfo on service ConnectionManager reply {}
2020-10-30 13:24:28.020 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetProtocolInfo on service ConnectionManager with inputs {}
2020-10-30 13:24:38.021 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Current state of service prevents invoking that action. Connection error or no response received.
2020-10-30 13:24:38.021 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action GetProtocolInfo on service ConnectionManager reply {}
2020-10-30 13:24:38.022 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device XW-SMA3 2337FB invoke upnp action Play on service AVTransport with inputs {Speed=1, InstanceID=0}

This situation stays until restart of OH.

274

I’m still encountering the issue. After a few days of usage the thing becomes offline. I have done some googeling and found a similar problem exists in SONOS binding: Too much time before a Sonos thing becomes definitively ONLINE
After trying the workaround to manually restart the jupnp bundle also my device became available again. My remaining problem is, that I can’t effectively find out the situation when the thing is really offline as it also becomes offline for a short period of time when I switch off power, and comes back online after rediscovering the device, because it is not really switched off and network communication stays alive. Does the 3.0 binding use newer version of jupnp? My 2.5.11 openHAB installation shows jupnp version 2.5.2.

275

I am moving my system to openhab 3 and I can confirm, latest stable version still uses v2.5.2.

1 Like
276

It seems to be latest release when looking at: GitHub - jupnp/jupnp: UPnP/DLNA library for Java

277

There are a few bugs open right now dealing with some thread usage that may resolve this. Do you use either denonmarantz, ecobee, or samsungtv?

278

I have installed samsungtv but not really using it. You say, it interferes with UPNP?

279

Yes there are some thread issues with it that are causing an exhaustion problem.

280

I will uninstall and test without it.

281

Ok. Please hold on doing any 3.1 snapshot updates, the last commit broke something. I’ve already submitted a bug for it so hopefully the 3.1 snapshot should fix all of this soon.