[upnpcontrol] Error when parsing URI

[mjcumming]

I am on 4.2 S4020 (the error has been present since I started with OH 3.0). The bridge connects correctly to the device at startup but eventually goes offline. There is a Java error in the console that seems to be related to the UPNP service. Error and trace output below.

https://community.openhab.org/t/upnp-device-not-registered-error/155081

2024-03-31 07:39:04.828 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackMetaData with value <?xml version="1.0" encoding="UTF-8"?> <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:song="www.wiimu.com/song/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"> <upnp:class>object.item.audioItem.musicTrack</upnp:class> <item id="0"> <song:subid></song:subid> <song:description></song:description> <song:skiplimit>0</song:skiplimit> <song:id></song:id> <song:like>0</song:like> <song:singerid>0</song:singerid> <song:albumid>0</song:albumid> <song:rate_hz></song:rate_hz> <song:format_s></song:format_s> <song:bitrate>0</song:bitrate> <res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;" duration="00:00:00.000"></res> <dc:title></dc:title> <dc:creator></dc:creator> <upnp:artist></upnp:artist> <upnp:album></upnp:album> <upnp:albumArtURI>un_known</upnp:albumArtURI> </item> </DIDL-Lite>  from service AVTransport
2024-03-31 07:39:04.835 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen, received media ID: 0
2024-03-31 07:39:04.836 [TRACE] [internal.handler.UpnpRendererHandler] - Current queue res: 
2024-03-31 07:39:04.836 [TRACE] [internal.handler.UpnpRendererHandler] - Updated media res: 
2024-03-31 07:39:04.837 [TRACE] [internal.handler.UpnpRendererHandler] - Received meta data is for current entry: true
2024-03-31 07:39:04.838 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Illegal character in path at index 8: un_known 
	at java.net.URI.create(URI.java:906) ~[?:?]
	at org.eclipse.jetty.client.HttpClient.newRequest(HttpClient.java:473) ~[?:?]
	at org.openhab.core.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:212) ~[?:?]
	at org.openhab.core.io.net.http.HttpUtil.downloadData(HttpUtil.java:443) ~[?:?]
	at org.openhab.core.io.net.http.HttpUtil.downloadImage(HttpUtil.java:406) ~[?:?]
	at org.openhab.core.io.net.http.HttpUtil.downloadImage(HttpUtil.java:377) ~[?:?]
	at org.openhab.core.io.net.http.HttpUtil.downloadImage(HttpUtil.java:363) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.updateMetaDataState(UpnpRendererHandler.java:1654) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.onValueReceivedCurrentMetaData(UpnpRendererHandler.java:1306) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:1089) ~[?:?]
	at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.lambda$3(UpnpRendererHandler.java:1161) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: java.net.URISyntaxException: Illegal character in path at index 8: un_known 
	at java.net.URI$Parser.fail(URI.java:2976) ~[?:?]
	at java.net.URI$Parser.checkChars(URI.java:3147) ~[?:?]
	at java.net.URI$Parser.parseHierarchical(URI.java:3229) ~[?:?]
	at java.net.URI$Parser.parse(URI.java:3188) ~[?:?]
	at java.net.URI.<init>(URI.java:623) ~[?:?]
	at java.net.URI.create(URI.java:904) ~[?:?]
	... 16 more

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/upnp-device-not-registered-error/155081/3

[mjcumming]

If I disable and re-enable the thing I get the following output.

2024-03-31 19:28:54.880 [DEBUG] [internal.handler.UpnpRendererHandler] - Disposing handler for media renderer device Arylic Kitchen
2024-03-31 19:28:54.873 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet registered to UNINITIALIZED
2024-03-31 19:28:54.884 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenTrackposition' updated to 0 s
2024-03-31 19:28:54.885 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenReltrackposition' updated to 0
2024-03-31 19:28:54.885 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ArylicKitchenControl' updated to PLAY
2024-03-31 19:28:54.898 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2024-03-31 19:28:56.069 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Media renderer handler created for Arylic Kitchen with UID upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D
2024-03-31 19:28:56.077 [DEBUG] [ontrol.internal.util.UpnpControlUtil] - No .lst files in /var/lib/openhab/upnpcontrol/
2024-03-31 19:28:56.078 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF31F09E-7AAF-270E-A4C0-10F6FF31F09E:playlistselect
2024-03-31 19:28:56.078 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:FF31F09E-253B-7EF5-AF4E-0004FF31F09E:playlistselect
2024-03-31 19:28:56.078 [DEBUG] [internal.handler.UpnpRendererHandler] - Initializing handler for media renderer device Arylic Kitchen
2024-03-31 19:28:56.072 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2024-03-31 19:28:56.080 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from INITIALIZING to UNKNOWN
2024-03-31 19:28:56.081 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from UNKNOWN to OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet registered

[mjcumming]

With this change, I am now seeing the following error:

2024-04-06 06:18:00.224 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable InstanceID with value 0 from service AVTransport 2024-04-06 06:18:00.225 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device Arylic Kitchen received variable CurrentTrackMetaData with value <?xml version="1.0" encoding="UTF-8"?> <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:song="www.wiimu.com/song/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"> <upnp:class>object.item.audioItem.musicTrack</upnp:class> <item id="0"> <song:subid></song:subid> <song:description></song:description> <song:skiplimit>0</song:skiplimit> <song:id></song:id> <song:like>0</song:like> <song:singerid>0</song:singerid> <song:albumid>0</song:albumid> <song:rate_hz></song:rate_hz> <song:format_s></song:format_s> <song:bitrate>0</song:bitrate> <res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;" duration="00:00:00.000"></res> <dc:title></dc:title> <dc:creator></dc:creator> <upnp:artist></upnp:artist> <upnp:album></upnp:album> <upnp:albumArtURI>un_known</upnp:albumArtURI> </item> </DIDL-Lite> from service AVTransport 2024-04-06 06:18:00.228 [TRACE] [internal.handler.UpnpRendererHandler] - Renderer Arylic Kitchen, received media ID: 0 2024-04-06 06:18:00.229 [TRACE] [internal.handler.UpnpRendererHandler] - Current queue res: 2024-04-06 06:18:00.230 [TRACE] [internal.handler.UpnpRendererHandler] - Updated media res: 2024-04-06 06:18:00.230 [TRACE] [internal.handler.UpnpRendererHandler] - Received meta data is for current entry: true at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.updateMetaDataState(UpnpRendererHandler.java:1654) ~[?:?] at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.onValueReceivedCurrentMetaData(UpnpRendererHandler.java:1306) ~[?:?] at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.onValueReceived(UpnpRendererHandler.java:1089) ~[?:?] at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.lambda$3(UpnpRendererHandler.java:1161) ~[?:?] 2024-04-06 06:18:11.072 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Rakoit Technology(SZ) Co., Ltd., model H50, SN# 00001, UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D 2024-04-06 06:18:11.074 [DEBUG] [control.internal.handler.UpnpHandler] - UPnP device Arylic Kitchen received status update false 2024-04-06 06:18:11.074 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Rakoit Technology(SZ) Co., Ltd., H50 2024-04-06 06:18:11.077 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Communication lost with Arylic Kitchen 2024-04-06 06:19:00.151 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'upnpcontrol:upnprenderer:FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D' changed from OFFLINE (COMMUNICATION_ERROR): Communication lost with Arylic Kitchen to OFFLINE (COMMUNICATION_ERROR): UPnP device with UDN FF97F35D-4C0A-1EB1-DA5E-0714FF97F35D not yet registered