DLNA / UPNP binding

[Mherwege (Mark Herwege)]

@yhd

My renderer seems to go from <TransportState val="STOPPED"/> to <TransportState val="PLAYING"/> without <TransportState val="TRANSITIONING"/>.
Can that cause any issues?

I don’t think that is an issue. The binding does not make assumptions on this, even filters for renderers that send multiple stop commands.

@yhd

Fyi using my renderer I noticed that the playback triggered through URI channel or an action is not always starting immediately as the docs say. I can workaround this by a stop>set uri>play sequence in my rule. Probably its related to the above?

I am not sure if it is related. Again, when that happens, logs would be usefult to debug.

Analyzing the two logs, there is one difference. The following line does not appear in the logs when the problem happens:

2023-02-24 12:20:28.526 [TRACE] [internal.handler.UpnpRendererHandler] - Ready to play 'Come Around' from queue

This is just before the binding gives the play command for the next song. I am checking for some statuses before giving that command, and if not OK, the command is not given. I don’t see yet how this happens, but I would appreciate if you could run with a test jar for 3.x. I created with an extra log statement, that shows me this check. The jar is here. I would be interested to see what is in the log when the next song fails.
I don’t think it is your renderer. From what I can see, the logs are what I expect, except for this one line and no play being called.
BTW: the shuffle issue is also solved in this jar.

[Mherwege (Mark Herwege)]

@yhd

“DenonMarantz Avr not discovered as renderer”

@yhd I loaded a new version of the test jar file. This one tries to discover and add subdevices. I cannot test myself, so if you are willing to go the extra mile, test and give me feedback, I can try to get it working.

[yhd (yahoodee)]

I will get some logs but I do not have much spare time atm.

I just set up all my devices to an openhab-only usage without bubbleupnp to minimize side effects.

[yhd (yahoodee)]

Thanks again!
Unfortunately I cannot get your jar running. I followed these instructions: Testing a new jar and how to use it locally - #2 by matt1

openhab> bundle:list -s | grep upnp
264 x Active  x  80 x 2.6.1                  x org.jupnp
293 x Active  x  80 x 3.4.2                  x org.openhab.core.config.discovery.upnp
302 x Active  x  80 x 3.4.2                  x org.openhab.core.io.transport.upnp
318 x Waiting x  80 x 3.4.2.202303021150     x org.openhab.binding.upnpcontrol

Default log:

2023-03-04 23:04:37.155 [ERROR] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(923)] : Constructor with 0 arguments not found. Component will fail.
2023-03-04 23:04:37.157 [ERROR] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(923)] : Error during instantiation of the implementation object: Constructor not found.
2023-03-04 23:04:37.165 [WARN ] [y.upnp.internal.UpnpDiscoveryService] - bundle org.openhab.core.config.discovery.upnp:3.4.2 (293)[org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService(895)] : Could not get service from ref {org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant}={service.id=1805, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, component.id=923}
2023-03-04 23:04:37.167 [WARN ] [y.upnp.internal.UpnpDiscoveryService] - bundle org.openhab.core.config.discovery.upnp:3.4.2 (293)[org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService(895)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant}={service.id=1805, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, component.id=923} for reference UpnpDiscoveryParticipant

Debug log:

2023-03-04 23:18:13.116 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2023-03-04 23:18:13.118 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : BundleComponentActivator : ComponentHolder created.
2023-03-04 23:18:13.119 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : BundleComponentActivator : ComponentHolder created.
2023-03-04 23:18:13.121 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : BundleComponentActivator : ComponentHolder created.
2023-03-04 23:18:13.132 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.io.transport.upnp.UpnpIOService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2023-03-04 23:18:13.133 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $001interface=org.jupnp.UpnpService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=1
2023-03-04 23:18:13.135 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $002interface=org.openhab.core.audio.AudioHTTPServer, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=2
2023-03-04 23:18:13.136 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $003interface=org.openhab.core.net.NetworkAddressService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=3
2023-03-04 23:18:13.138 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $004interface=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=4
2023-03-04 23:18:13.139 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Dependency Manager created $005interface=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=5
2023-03-04 23:18:13.140 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deActivate, modified=modified configuration-pid=[binding.upnpcontrol]
2023-03-04 23:18:13.142 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2023-03-04 23:18:13.143 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Component Properties: {}
2023-03-04 23:18:13.144 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Querying state disabled
2023-03-04 23:18:13.146 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Querying state disabled
2023-03-04 23:18:13.147 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Component can not be activated since it is in state disabled
2023-03-04 23:18:13.148 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory] : Querying state disabled
2023-03-04 23:18:13.149 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Updating target filters
2023-03-04 23:18:13.151 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $000: currently registered: false
2023-03-04 23:18:13.153 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $000
2023-03-04 23:18:13.154 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $000 to null
2023-03-04 23:18:13.155 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.transport.upnp.UpnpIOService), initialReferenceFilter (objectClass=org.openhab.core.io.transport.upnp.UpnpIOService)
2023-03-04 23:18:13.156 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $000 tracker reset (closed)
2023-03-04 23:18:13.160 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.transport.upnp.UpnpIOService, org.jupnp.registry.RegistryListener}={service.id=1334, service.bundleid=302, service.scope=bundle, component.name=org.openhab.core.io.transport.upnp.internal.UpnpIOServiceImpl, component.id=755} (enter)
2023-03-04 23:18:13.161 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2023-03-04 23:18:13.163 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.transport.upnp.UpnpIOService, org.jupnp.registry.RegistryListener}={service.id=1334, service.bundleid=302, service.scope=bundle, component.name=org.openhab.core.io.transport.upnp.internal.UpnpIOServiceImpl, component.id=755} (exit)
2023-03-04 23:18:13.164 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $000 tracker opened
2023-03-04 23:18:13.165 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $000
2023-03-04 23:18:13.166 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $001: currently registered: false
2023-03-04 23:18:13.167 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $001
2023-03-04 23:18:13.168 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $001 to null
2023-03-04 23:18:13.169 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.jupnp.UpnpService), initialReferenceFilter (objectClass=org.jupnp.UpnpService)
2023-03-04 23:18:13.170 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $001 tracker reset (closed)
2023-03-04 23:18:13.174 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $001 tracking 2 SingleStatic added {org.jupnp.UpnpService}={service.id=1331, service.bundleid=264, service.scope=bundle, component.name=org.jupnp.upnpservice, component.id=754} (enter)
2023-03-04 23:18:13.175 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2023-03-04 23:18:13.177 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $001 tracking 2 SingleStatic added {org.jupnp.UpnpService}={service.id=1331, service.bundleid=264, service.scope=bundle, component.name=org.jupnp.upnpservice, component.id=754} (exit)
2023-03-04 23:18:13.178 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $001 tracker opened
2023-03-04 23:18:13.179 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $001
2023-03-04 23:18:13.180 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $002: currently registered: false
2023-03-04 23:18:13.181 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $002
2023-03-04 23:18:13.182 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $002 to null
2023-03-04 23:18:13.184 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $002, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.audio.AudioHTTPServer), initialReferenceFilter (objectClass=org.openhab.core.audio.AudioHTTPServer)
2023-03-04 23:18:13.185 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $002 tracker reset (closed)
2023-03-04 23:18:13.188 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.audio.AudioHTTPServer}={service.id=276, service.bundleid=153, service.scope=bundle, component.name=org.openhab.core.audio.internal.AudioServlet, component.id=64} (enter)
2023-03-04 23:18:13.189 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $002 tracking 3 SingleStatic active: false trackerOpened: false optional: false
2023-03-04 23:18:13.191 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.audio.AudioHTTPServer}={service.id=276, service.bundleid=153, service.scope=bundle, component.name=org.openhab.core.audio.internal.AudioServlet, component.id=64} (exit)
2023-03-04 23:18:13.192 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $002 tracker opened
2023-03-04 23:18:13.193 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $002
2023-03-04 23:18:13.195 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $003: currently registered: false
2023-03-04 23:18:13.196 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $003
2023-03-04 23:18:13.198 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $003 to null
2023-03-04 23:18:13.199 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $003, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.net.NetworkAddressService), initialReferenceFilter (objectClass=org.openhab.core.net.NetworkAddressService)
2023-03-04 23:18:13.201 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $003 tracker reset (closed)
2023-03-04 23:18:13.204 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $003 tracking 4 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=150, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=52} (enter)
2023-03-04 23:18:13.206 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $003 tracking 4 SingleStatic active: false trackerOpened: false optional: false
2023-03-04 23:18:13.207 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $003 tracking 4 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=150, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=52} (exit)
2023-03-04 23:18:13.209 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $003 tracker opened
2023-03-04 23:18:13.210 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $003
2023-03-04 23:18:13.211 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $004: currently registered: false
2023-03-04 23:18:13.212 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $004
2023-03-04 23:18:13.214 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $004 to null
2023-03-04 23:18:13.215 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $004, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider), initialReferenceFilter (objectClass=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider)
2023-03-04 23:18:13.216 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $004 tracker reset (closed)
2023-03-04 23:18:13.219 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $004 tracker opened
2023-03-04 23:18:13.221 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $004
2023-03-04 23:18:13.222 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : No change in target property for dependency $005: currently registered: false
2023-03-04 23:18:13.223 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] :  No existing service listener to unregister for dependency $005
2023-03-04 23:18:13.224 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Setting target property for dependency $005 to null
2023-03-04 23:18:13.226 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : New service tracker for $005, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider), initialReferenceFilter (objectClass=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider)
2023-03-04 23:18:13.227 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $005 tracker reset (closed)
2023-03-04 23:18:13.230 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $005 tracker opened
2023-03-04 23:18:13.231 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registering service listener for dependency $005
2023-03-04 23:18:13.233 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Changed state from disabled to unsatisfiedReference
2023-03-04 23:18:13.234 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Component enabled
2023-03-04 23:18:13.235 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : ActivateInternal
2023-03-04 23:18:13.236 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.237 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.238 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.240 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.241 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.243 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Dependency not satisfied: $004
2023-03-04 23:18:13.244 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Dependency not satisfied: $005
2023-03-04 23:18:13.245 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Not all dependencies satisfied, cannot activate
2023-03-04 23:18:13.246 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Component created: DS=DS13, implementation=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider]
2023-03-04 23:18:13.248 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Component Services: scope=singleton, services=[org.openhab.core.thing.type.DynamicCommandDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider]
2023-03-04 23:18:13.249 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Component Properties: {}
2023-03-04 23:18:13.250 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.252 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.253 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Component can not be activated since it is in state disabled
2023-03-04 23:18:13.254 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.255 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Updating target filters
2023-03-04 23:18:13.256 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Changed state from disabled to unsatisfiedReference
2023-03-04 23:18:13.258 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Component enabled
2023-03-04 23:18:13.259 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : ActivateInternal
2023-03-04 23:18:13.260 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.261 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.262 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.263 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.265 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.266 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Changed state from unsatisfiedReference to satisfied
2023-03-04 23:18:13.267 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : registration change queue [registered]
2023-03-04 23:18:13.272 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Checking constructor public org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider()
2023-03-04 23:18:13.274 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Found constructor with 0 arguments : public org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider()
2023-03-04 23:18:13.275 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : This thread collected dependencies
2023-03-04 23:18:13.276 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : getService (single component manager) dependencies collected.
2023-03-04 23:18:13.277 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state satisfied
2023-03-04 23:18:13.278 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Querying state satisfied
2023-03-04 23:18:13.280 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : getting activate: activate
2023-03-04 23:18:13.281 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Locating method activate in class org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider
2023-03-04 23:18:13.282 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Declared Method org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-04 23:18:13.283 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Locating method activate in class java.lang.Object
2023-03-04 23:18:13.285 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-04 23:18:13.286 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : activate method [activate] not found, ignoring
2023-03-04 23:18:13.287 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Set implementation object for component
2023-03-04 23:18:13.288 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(933)] : Changed state from satisfied to active
2023-03-04 23:18:13.290 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $005 tracking 5 SingleStatic added {org.openhab.core.thing.type.DynamicCommandDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider}={service.id=1832, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider, component.id=933} (enter)
2023-03-04 23:18:13.291 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : ActivateInternal
2023-03-04 23:18:13.293 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.294 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.295 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.296 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.297 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.298 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Dependency not satisfied: $004
2023-03-04 23:18:13.300 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Not all dependencies satisfied, cannot activate
2023-03-04 23:18:13.301 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $005 tracking 5 SingleStatic added {org.openhab.core.thing.type.DynamicCommandDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider}={service.id=1832, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider, component.id=933} (exit)
2023-03-04 23:18:13.303 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Component created: DS=DS13, implementation=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider]
2023-03-04 23:18:13.304 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Component Services: scope=singleton, services=[org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider]
2023-03-04 23:18:13.305 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Component Properties: {}
2023-03-04 23:18:13.306 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.308 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.309 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Component can not be activated since it is in state disabled
2023-03-04 23:18:13.310 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider] : Querying state disabled
2023-03-04 23:18:13.311 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Updating target filters
2023-03-04 23:18:13.312 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Changed state from disabled to unsatisfiedReference
2023-03-04 23:18:13.313 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Component enabled
2023-03-04 23:18:13.314 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : ActivateInternal
2023-03-04 23:18:13.315 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.317 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.318 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.319 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.320 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.321 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Changed state from unsatisfiedReference to satisfied
2023-03-04 23:18:13.322 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : registration change queue [registered]
2023-03-04 23:18:13.327 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Checking constructor public org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider()
2023-03-04 23:18:13.329 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Found constructor with 0 arguments : public org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider()
2023-03-04 23:18:13.330 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : This thread collected dependencies
2023-03-04 23:18:13.331 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : getService (single component manager) dependencies collected.
2023-03-04 23:18:13.332 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state satisfied
2023-03-04 23:18:13.332 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Querying state satisfied
2023-03-04 23:18:13.334 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : getting activate: activate
2023-03-04 23:18:13.335 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Locating method activate in class org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider
2023-03-04 23:18:13.336 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Declared Method org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-04 23:18:13.337 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Locating method activate in class java.lang.Object
2023-03-04 23:18:13.338 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-04 23:18:13.339 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : activate method [activate] not found, ignoring
2023-03-04 23:18:13.339 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Set implementation object for component
2023-03-04 23:18:13.340 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(934)] : Changed state from satisfied to active
2023-03-04 23:18:13.342 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $004 tracking 6 SingleStatic added {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider}={service.id=1833, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, component.id=934} (enter)
2023-03-04 23:18:13.344 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : ActivateInternal
2023-03-04 23:18:13.345 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.346 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.347 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.348 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.349 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.350 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Changed state from unsatisfiedReference to satisfied
2023-03-04 23:18:13.351 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : registration change queue [registered]
2023-03-04 23:18:13.355 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Checking constructor public org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(org.openhab.core.io.transport.upnp.UpnpIOService,org.jupnp.UpnpService,org.openhab.core.audio.AudioHTTPServer,org.openhab.core.net.NetworkAddressService,org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider,org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider,java.util.Map)
2023-03-04 23:18:13.356 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.upnp.UpnpIOService through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.357 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.openhab.core.io.transport.upnp.UpnpIOService
2023-03-04 23:18:13.358 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.jupnp.UpnpService through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.359 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.jupnp.UpnpService
2023-03-04 23:18:13.360 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.openhab.core.audio.AudioHTTPServer through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.361 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.openhab.core.audio.AudioHTTPServer
2023-03-04 23:18:13.362 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.openhab.core.net.NetworkAddressService through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.363 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.openhab.core.net.NetworkAddressService
2023-03-04 23:18:13.363 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.364 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider
2023-03-04 23:18:13.365 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getReferenceClass: Looking for interface class org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider through loader of org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.366 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getParameterClass: Found class org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider
2023-03-04 23:18:13.367 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Found constructor with 7 arguments : public org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(org.openhab.core.io.transport.upnp.UpnpIOService,org.jupnp.UpnpService,org.openhab.core.audio.AudioHTTPServer,org.openhab.core.net.NetworkAddressService,org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider,org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider,java.util.Map)
2023-03-04 23:18:13.368 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : This thread collected dependencies
2023-03-04 23:18:13.369 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getService (single component manager) dependencies collected.
2023-03-04 23:18:13.370 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state satisfied
2023-03-04 23:18:13.371 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Querying state satisfied
2023-03-04 23:18:13.372 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.upnp.UpnpIOService, org.jupnp.registry.RegistryListener}={service.id=1334, service.bundleid=302, service.scope=bundle, component.name=org.openhab.core.io.transport.upnp.internal.UpnpIOServiceImpl, component.id=755}] service: [null]]]
2023-03-04 23:18:13.373 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.jupnp.UpnpService}={service.id=1331, service.bundleid=264, service.scope=bundle, component.name=org.jupnp.upnpservice, component.id=754}] service: [null]]]
2023-03-04 23:18:13.375 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $002, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.audio.AudioHTTPServer}={service.id=276, service.bundleid=153, service.scope=bundle, component.name=org.openhab.core.audio.internal.AudioServlet, component.id=64}] service: [null]]]
2023-03-04 23:18:13.376 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $003, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=150, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=52}] service: [null]]]
2023-03-04 23:18:13.377 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $004, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider}={service.id=1833, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, component.id=934}] service: [null]]]
2023-03-04 23:18:13.378 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : For dependency $005, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.DynamicCommandDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider}={service.id=1832, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider, component.id=933}] service: [null]]]
2023-03-04 23:18:13.382 [DEBUG] [nfig.UpnpControlBindingConfiguration] - Storage path updated to /var/lib/openhab/upnpcontrol/
2023-03-04 23:18:13.383 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Updated binding configuration to org.openhab.binding.upnpcontrol.internal.config.UpnpControlBindingConfiguration@307ede
2023-03-04 23:18:13.385 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : getting activate: activate
2023-03-04 23:18:13.385 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Locating method activate in class org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-03-04 23:18:13.386 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Declared Method org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-04 23:18:13.387 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2023-03-04 23:18:13.390 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2023-03-04 23:18:13.391 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2023-03-04 23:18:13.393 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : invoked activate: activate
2023-03-04 23:18:13.394 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Set implementation object for component
2023-03-04 23:18:13.395 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : Changed state from satisfied to active
2023-03-04 23:18:13.400 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(932)] : dm $004 tracking 6 SingleStatic added {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider}={service.id=1833, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, component.id=934} (exit)
2023-03-04 23:18:13.402 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component created: DS=DS13, implementation=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant]
2023-03-04 23:18:13.403 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component Services: scope=singleton, services=[org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant]
2023-03-04 23:18:13.404 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component Properties: {}
2023-03-04 23:18:13.405 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-03-04 23:18:13.406 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-03-04 23:18:13.408 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component can not be activated since it is in state disabled
2023-03-04 23:18:13.409 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-03-04 23:18:13.409 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Updating target filters
2023-03-04 23:18:13.410 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Changed state from disabled to unsatisfiedReference
2023-03-04 23:18:13.411 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Component enabled
2023-03-04 23:18:13.412 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : ActivateInternal
2023-03-04 23:18:13.413 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.414 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.415 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Activating component from state unsatisfiedReference
2023-03-04 23:18:13.416 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.417 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state unsatisfiedReference
2023-03-04 23:18:13.418 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Changed state from unsatisfiedReference to satisfied
2023-03-04 23:18:13.420 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : registration change queue [registered]
2023-03-04 23:18:13.424 [ERROR] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Constructor with 0 arguments not found. Component will fail.
2023-03-04 23:18:13.425 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : This thread collected dependencies
2023-03-04 23:18:13.426 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : getService (single component manager) dependencies collected.
2023-03-04 23:18:13.427 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state satisfied
2023-03-04 23:18:13.428 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state satisfied
2023-03-04 23:18:13.429 [ERROR] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Error during instantiation of the implementation object: Constructor not found.
2023-03-04 23:18:13.434 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Failed creating the component instance; see log for reason
2023-03-04 23:18:13.435 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Querying state satisfied
2023-03-04 23:18:13.435 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2.202303021150 (318)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(935)] : Changed state from satisfied to satisfied
2023-03-04 23:18:13.437 [WARN ] [y.upnp.internal.UpnpDiscoveryService] - bundle org.openhab.core.config.discovery.upnp:3.4.2 (293)[org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService(895)] : Could not get service from ref {org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant}={service.id=1835, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, component.id=935}
2023-03-04 23:18:13.438 [WARN ] [y.upnp.internal.UpnpDiscoveryService] - bundle org.openhab.core.config.discovery.upnp:3.4.2 (293)[org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService(895)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant}={service.id=1835, service.bundleid=318, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, component.id=935} for reference UpnpDiscoveryParticipant

Thanks again!

[Mherwege (Mark Herwege)]

@yhd Sorry for the late reply. Indeed, it looks like the trick I tried to use to also add the discovered embedded devices did not work. I removed it, but put in some logging to at least show the embedded devices are found. I will need to get some clarification on how to do this, should the embedded devices be found.
The new jar file with only logging is under the same link I posted before.

[yhd (yahoodee)]

No worries. I have plenty of others tasks to do…

2023-03-17 21:22:44.358 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Marantz, model Marantz SR6015, SN# null, UDN 3c2012a3-5a3a-1311-0080-00067851e9ee
2023-03-17 21:22:44.360 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Marantz, Marantz SR6015
2023-03-17 21:22:44.361 [DEBUG] [very.UpnpControlDiscoveryParticipant] - <-- Embedded device found
2023-03-17 21:22:44.362 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaRenderer, manufacturer Marantz, model Marantz SR6015, SN# null, UDN 3c2012a3-5a3a-1311-0080-00067851e9ee
2023-03-17 21:22:44.364 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media renderer found: Marantz, Marantz SR6015
2023-03-17 21:22:44.365 [DEBUG] [very.UpnpControlDiscoveryParticipant] - End embedded device -->
2023-03-17 21:22:44.366 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type AiosServices, manufacturer Marantz, model Marantz SR6015, SN# null, UDN c36f6efc-5213-1f98-0080-00067851e9ee
2023-03-17 21:22:44.367 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type ACT-Denon, manufacturer Marantz, model Marantz SR6015, SN# MBCL112003130, UDN 96b0c26a-f70b-b69d-0a28-9261cd04cdca
2023-03-17 21:22:44.368 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaServer, manufacturer Marantz, model Marantz SR6015, SN# MBCL112003130, UDN caaa05a1-913b-cfbd-974e-2b4ba9ef7541
2023-03-17 21:22:44.369 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media server found: Marantz, Marantz SR6015
2023-03-17 21:22:44.371 [DEBUG] [very.UpnpControlDiscoveryParticipant] - <-- Embedded device found
2023-03-17 21:22:44.372 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type MediaServer, manufacturer Marantz, model Marantz SR6015, SN# MBCL112003130, UDN caaa05a1-913b-cfbd-974e-2b4ba9ef7541
2023-03-17 21:22:44.373 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Media server found: Marantz, Marantz SR6015
2023-03-17 21:22:44.374 [DEBUG] [very.UpnpControlDiscoveryParticipant] - End embedded device -->
2023-03-17 21:22:44.375 [DEBUG] [very.UpnpControlDiscoveryParticipant] - Device type AiosDevice, manufacturer Marantz, model Marantz SR6015, SN# MBCL112003130, UDN 49ffc712-b43c-174b-0080-00067851e9ee

I did not see any other info that could be relevant for you. But I checked which device my bubbleupnp can successfully use and it seem to be the last one from above (SN# and UDN matches). This is the referenced deviceinfo if it helps:

<root xmlns="urn:schemas-upnp-org:device-1-0" xmlns:DMH="http://www.dmglobal.com" xmlns:qq="http://www.tencent.com" xmlns:avega_media_server="urn:schemas-avegasystems-com:media-server:metadata-1-0:DIDL-Lite">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<device>
<deviceType>urn:schemas-denon-com:device:AiosDevice:1</deviceType>
<friendlyName>Living Room</friendlyName>
<manufacturer>Marantz</manufacturer>
<manufacturerURL>http://www.marantz.com</manufacturerURL>
<modelName>Marantz SR6015</modelName>
<modelNumber>Aios 4.025</modelNumber>
<serialNumber>MBCL112003130</serialNumber>
<UDN>uuid:49ffc712-b43c-174b-0080-00067851e9ee</UDN>
<DMH:X_Audyssey>00000002</DMH:X_Audyssey>
<DMH:X_AudysseyPort>1256</DMH:X_AudysseyPort>
<DMH:X_WebAPIPort>8080</DMH:X_WebAPIPort>
<deviceList>
<device>
<deviceType>urn:schemas-upnp-org:device:MediaRenderer:1</deviceType>
<friendlyName>Living Room</friendlyName>
<manufacturer>Marantz</manufacturer>
<manufacturerURL>http://www.marantz.com</manufacturerURL>
<modelName>Marantz SR6015</modelName>
<modelNumber>Aios 4.025</modelNumber>
<UDN>uuid:3c2012a3-5a3a-1311-0080-00067851e9ee</UDN>
<qq:X_QPlay_SoftwareCapability>QPlay:1</qq:X_QPlay_SoftwareCapability>
<serviceList>
<service>
<serviceType>urn:schemas-upnp-org:service:AVTransport:1</serviceType>
<serviceId>urn:upnp-org:serviceId:AVTransport</serviceId>
<SCPDURL>/upnp/scpd/renderer_dvc/AVTransport.xml</SCPDURL>
<controlURL>/upnp/control/renderer_dvc/AVTransport</controlURL>
<eventSubURL>/upnp/event/renderer_dvc/AVTransport</eventSubURL>
</service>
<service>
<serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType>
<serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId>
<SCPDURL>/upnp/scpd/renderer_dvc/ConnectionManager.xml</SCPDURL>
<controlURL>/upnp/control/renderer_dvc/ConnectionManager</controlURL>
<eventSubURL>/upnp/event/renderer_dvc/ConnectionManager</eventSubURL>
</service>
<service>
<serviceType>urn:schemas-upnp-org:service:RenderingControl:1</serviceType>
<serviceId>urn:upnp-org:serviceId:RenderingControl</serviceId>
<SCPDURL>/upnp/scpd/renderer_dvc/RenderingControl.xml</SCPDURL>
<controlURL>/upnp/control/renderer_dvc/RenderingControl</controlURL>
<eventSubURL>/upnp/event/renderer_dvc/RenderingControl</eventSubURL>
</service>
</serviceList>
</device>
<device>
<deviceType>urn:schemas-denon-com:device:AiosServices:1</deviceType>
<friendlyName>AiosServices</friendlyName>
<manufacturer>Marantz</manufacturer>
<manufacturerURL>http://www.marantz.com</manufacturerURL>
<modelName>Marantz SR6015</modelName>
<modelNumber>Aios 4.025</modelNumber>
<UDN>uuid:c36f6efc-5213-1f98-0080-00067851e9ee</UDN>
<serviceList>
<service>
<serviceType>urn:schemas-denon-com:service:ErrorHandler:1</serviceType>
<serviceId>urn:denon-com:serviceId:ErrorHandler</serviceId>
<SCPDURL>/upnp/scpd/AiosServicesDvc/ErrorHandler.xml</SCPDURL>
<controlURL>/upnp/control/AiosServicesDvc/ErrorHandler</controlURL>
<eventSubURL>/upnp/event/AiosServicesDvc/ErrorHandler</eventSubURL>
</service>
<service>
<serviceType>urn:schemas-denon-com:service:ZoneControl:2</serviceType>
<serviceId>urn:denon-com:serviceId:ZoneControl</serviceId>
<SCPDURL>/upnp/scpd/AiosServicesDvc/ZoneControl.xml</SCPDURL>
<controlURL>/upnp/control/AiosServicesDvc/ZoneControl</controlURL>
<eventSubURL>/upnp/event/AiosServicesDvc/ZoneControl</eventSubURL>
</service>
<service>
<serviceType>urn:schemas-denon-com:service:GroupControl:1</serviceType>
<serviceId>urn:denon-com:serviceId:GroupControl</serviceId>
<SCPDURL>/upnp/scpd/AiosServicesDvc/GroupControl.xml</SCPDURL>
<controlURL>/upnp/control/AiosServicesDvc/GroupControl</controlURL>
<eventSubURL>/upnp/event/AiosServicesDvc/GroupControl</eventSubURL>
</service>
</serviceList>
</device>
<device>
<deviceType>urn:schemas-denon-com:device:ACT-Denon:1</deviceType>
<friendlyName>Living Room</friendlyName>
<manufacturer>Marantz</manufacturer>
<manufacturerURL>http://www.marantz.com</manufacturerURL>
<modelName>Marantz SR6015</modelName>
<modelNumber>Aios 4.025</modelNumber>
<serialNumber>MBCL112003130</serialNumber>
<UDN>uuid:96b0c26a-f70b-b69d-0a28-9261cd04cdca</UDN>
<DeviceID>AIOS:0001</DeviceID>
<capability_version>2</capability_version>
<firmwareRevision>1678263089</firmwareRevision>
<firmware_date>Wed 2023-03-08 23:51:00</firmware_date>
<firmware_version>2.98.130</firmware_version>
<lanMac>00:06:78:51:E9:EC</lanMac>
<locale>en_EU</locale>
<moduleRevision>4</moduleRevision>
<moduleType>Aios 4.025</moduleType>
<productRevision>1</productRevision>
<releaseType>Production</releaseType>
<wlanMac>00:06:78:51:E9:EE</wlanMac>
<serviceList>
<service>
<serviceType>urn:schemas-denon-com:service:ACT:1</serviceType>
<serviceId>urn:denon-com:serviceId:ACT</serviceId>
<SCPDURL>/ACT/SCPD.xml</SCPDURL>
<controlURL>/ACT/control</controlURL>
<eventSubURL>/ACT/event</eventSubURL>
</service>
</serviceList>
</device>
<device>
<deviceType>urn:schemas-upnp-org:device:MediaServer:1</deviceType>
<friendlyName>Living Room</friendlyName>
<manufacturer>Marantz</manufacturer>
<manufacturerURL>http://www.marantz.com</manufacturerURL>
<modelDescription>Shares User defined folders and files to other Universal Plug and Play media devices.</modelDescription>
<modelName>Marantz SR6015</modelName>
<modelNumber>Aios 4.025</modelNumber>
<serialNumber>MBCL112003130</serialNumber>
<UDN>uuid:caaa05a1-913b-cfbd-974e-2b4ba9ef7541</UDN>
<avega_media_server:X_VirtualServersSupported>True</avega_media_server:X_VirtualServersSupported>
<avega_media_server:X_VirtualServersSupported>True</avega_media_server:X_VirtualServersSupported>
<avega_media_server:X_VirtualServersSupported>True</avega_media_server:X_VirtualServersSupported>
<avega_media_server:X_VirtualServersSupported>True</avega_media_server:X_VirtualServersSupported>
<serviceList>
<service>
<serviceType>urn:schemas-upnp-org:service:ContentDirectory:1</serviceType>
<serviceId>urn:upnp-org:serviceId:ContentDirectory</serviceId>
<SCPDURL>/upnp/scpd/ams_dvc/ContentDirectory.xml</SCPDURL>
<controlURL>/upnp/control/ams_dvc/ContentDirectory</controlURL>
<eventSubURL>/upnp/event/ams_dvc/ContentDirectory</eventSubURL>
</service>
<service>
<serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType>
<serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId>
<SCPDURL>/upnp/scpd/ams_dvc/ConnectionManager.xml</SCPDURL>
<controlURL>/upnp/control/ams_dvc/ConnectionManager</controlURL>
<eventSubURL>/upnp/event/ams_dvc/ConnectionManager</eventSubURL>
</service>
</serviceList>
</device>
</deviceList>
</device>
</root>

Thanks

[Mherwege (Mark Herwege)]

@yhd Thanks for the feedback. It least it shows the devices can be picked up.

I created a new version of the binding jar with a complete rewrite of the discovery part. This one, I hope, should discover the embedded devices. The new binding jar is here. I don’t know yet if the events come through correctly after discovery and thing creation for such an embedded device. For me, it still did discover the top level devices well. As I can’t test for embedded devices, I hope you can give me feedback.

@yhd

• “Device disappearing after 30 mins” - Is there any chance to keep it alive nevertheless?
• “Playback sometimes stops after playing a song” - I moved to another renderer which has not “disappearing after 30 mins” issues → Pi with Moode Audio Player which also uses Upmpd.

• The binding now implements a grace period which keeps it alive a (default) extra 50s after a device is gone. That is configurable.
• I still think there should be improvements possible in the binding on this. There is extra logging in the binding. I would be keen to get a log.

EDIT: I uploaded a new version. Please use that one. Chances of success should be higher.

[yhd (yahoodee)]

Hi Mark,

sorry for the very late reply. I dropped the jar in the addons folder, set trace logging and restartet org.openhab.binding.upnpcontrol and org.openhab.core.config.discovery.upnp. My AVR (3c2012a3-5a3a-1311-0080-00067851e9ee) gets discovered but I cannot use it (UPnP device … not yet registered).

Many thanks

[Mherwege (Mark Herwege)]

Some logs would be helpful to understand what happens after adding the subdevice thing. does it go online, or stay offline?
Also, with this version, do devices still disappear after 30 min?

[yhd (yahoodee)]

Sorry, I forgot to post the logs…

https://www.dropbox.com/s/gvwvcdm86sfifdl/upnp.log?dl=0

The thing does not go online. INITIALIZING > UNKNOWN > OFFLINE (COMMUNICATION_ERROR)

Also, with this version, do devices still disappear after 30 min?

No, it stays online!

Thanks

[Mherwege (Mark Herwege)]

That is already good news.

I created a new version trying to get one step further with the embedded devices. It looks like the OH upnp transport wrongly assumed we are not interested in embedded devices. I tried to work around that, but no guarantee that we have reached the end goal yet.
Still you can try the new version available here.

[yhd (yahoodee)]

Indeed it goes a step further but fails later on:

Thing 'upnpcontrol:upnprenderer:3c2012a3-5a3a-1311-0080-00067851e9ee' changed from UNKNOWN to OFFLINE (COMMUNICATION_ERROR): No connection Ids set for UPnP device with UDN {0}

New trace log of bundle start:

upnp2.log

Thanks

[Mherwege (Mark Herwege)]

There is a new version with more logging. No functional change, but it should give me more info on where it goes wrong.
Can you also remove the thing before updating the binding? I believe you had the thing already created, and channels are being created from the past thing.

[yhd (yahoodee)]

Some syslog messages are showing up since the previous (including the last) iteration:

Jun  7 15:59:23 openHABianDevice karaf[18733]: java.lang.IllegalArgumentException: Duplicate channels upnpcontrol:upnprenderer:3c2012a3-5a3a-1311-0080-00067851e9ee:Zone4mute
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:128)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.core.thing.binding.builder.ThingBuilder.withChannels(ThingBuilder.java:86)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.binding.upnpcontrol.internal.handler.UpnpHandler.updateChannels(UpnpHandler.java:303)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.binding.upnpcontrol.internal.handler.UpnpRendererHandler.updateDeviceConfig(UpnpRendererHandler.java:270)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory.remoteDeviceUpdated(UpnpControlHandlerFactory.java:299)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at org.jupnp.registry.RemoteItems$2.run(RemoteItems.java:170)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jun  7 15:59:23 openHABianDevice karaf[18733]: #011at java.base/java.lang.Thread.run(Thread.java:829)

This leads to the system getting unresponsive:

I updated the binding, stopped the bundle, deleted the thing, started the bundle and discovered the thing again. Is that also ok?

upnp3.log

Thanks again

[Mherwege (Mark Herwege)]

New version available that should at least solve the CPU utilization issue. I reworked a few things, hoping to get one step further again. It is difficult to debug, as I don’t have any device with embedded media server or renderer. Still trying to go step by step.

[yhd (yahoodee)]

No worries! I am very thankful for your support!
https://www.dropbox.com/s/wf0v02ly9rf646s/upnp4.log?dl=0
Channel log entries are gone, cpu stays low.

[Mherwege (Mark Herwege)]

@yhd

3c2012a3-5a3a-1311-0080-00067851e9ee

It took me a while to have a look at this again. Are you still on 3.4?

If you are, could you also put org.openhab.core.io.transport.upnp in TRACE log mode and org.jupnp in DEBUG log mode? I suspect I have to change the org.openhab.core.io.transport.upnp code to make subdevices work, but would like to see what already shows up in traces.

If you moved to 4.0 already, I will make a modified version of the jar available for 4.0 (that actually makes it easier for me, only 1 development environment needed). If not, let’s stick to 3.4 for now.

[yhd (yahoodee)]

I am still on 3.4 and pulled some logs: Dropbox - upnp5.log - Simplify your life

I also planned to move to v4 next week so I would welcome a matching jar.

Thanks

[joh]

Hello & thanks to all contributing here

I have a widget partially working using this binding (OH3.4.5). I have a couple of questions.

1. I use the control channel, for which pause seems to work to stop, but not to play again. This is what shows after a pause press on the control:

2023-10-08 16:52:07.721 [TRACE] [internal.handler.UpnpRendererHandler] - UPnP device ropieeexl [RoPieeeXL]-UPnP/AV received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS">
<InstanceID val="0">
<PlaybackStorageMedium val="NONE"/>
<AbsoluteTimePosition val="0:00:00"/>
<TransportState val="STOPPED"/>
<CurrentTransportActions val="Next,Previous,Play"/>
<CurrentMediaDuration val="00:00:00"/>
<CurrentTrackDuration val="00:00:00"/>
<RelativeTimePosition val="0:00:00"/>
</InstanceID>
</Event>
 from service AVTransport

Could it be that I am mixing OpenHome and UPnP/AV controls? Does it work for others if you strictly use UPnP/AV?

2. Is it possible to get the AlbumArt channel to populate? It shows UNDEF. Or is this a function of the renderer (upmpdcli running under Ropieee).

<CurrentTrackMetaData val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;utf-8&quot;?&gt;&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=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot;&gt;&lt;item restricted=&quot;1&quot; searchable=&quot;0&quot;&gt;&lt;dc:title&gt;V. Gigue&lt;/dc:title&gt;&lt;orig&gt;mpd&lt;/orig&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;upnp:album&gt;Bach: Suite No. 3 in D BWV 1068 (Lamon 2002)&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;5&lt;/upnp:originalTrackNumber&gt;&lt;res sampleFrequency=&quot;44100&quot; bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot;&gt;http://192.168.xxx.xxx:9790/minimserver/*/Music/HR/Classical/Jeanne*20Lamon/Bach*3b*20Suite*20No.*203*20in*20D*20BWV*201068*20(Lamon*202002)/05*20V.*20Gigue.flac&lt;/res&gt;&lt;upnp:genre&gt;Classical&lt;/upnp:genre&gt;&lt;dc:creator&gt;Jeanne Lamon&lt;/dc:creator&gt;&lt;upnp:artist&gt;Jeanne Lamon&lt;/upnp:artist&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>
<AVTransportURIMetaData val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;utf-8&quot;?&gt;&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=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot;&gt;&lt;item restricted=&quot;1&quot; searchable=&quot;0&quot;&gt;&lt;dc:title&gt;V. Gigue&lt;/dc:title&gt;&lt;orig&gt;mpd&lt;/orig&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;upnp:album&gt;Bach: Suite No. 3 in D BWV 1068 (Lamon 2002)&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;5&lt;/upnp:originalTrackNumber&gt;&lt;res sampleFrequency=&quot;44100&quot; bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot;&gt;http://192.168.xxx.xxx:9790/minimserver/*/Music/HR/Classical/Jeanne*20Lamon/Bach*3b*20Suite*20No.*203*20in*20D*20BWV*201068*20(Lamon*202002)/05*20V.*20Gigue.flac&lt;/res&gt;&lt;upnp:genre&gt;Classical&lt;/upnp:genre&gt;&lt;dc:creator&gt;Jeanne Lamon&lt;/dc:creator&gt;&lt;upnp:artist&gt;Jeanne Lamon&lt;/upnp:artist&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"/>

Sorry if these are basic questions. I’m a big fan of DLNA and would really like to use this binding much more extensively.

Thanks!

[yhd (yahoodee)]

I can’t say much, but when I (on 4.0.2) press pause this happens

2023-10-14 14:44:51.772 [DEBUG] [internal.handler.UpnpRendererHandler] - UPnP device Lautsprecher Arbeitszimmer received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS">
<InstanceID val="0">
<AbsoluteTimePosition val="0:03:31"/>
<TransportState val="PAUSED_PLAYBACK"/>
<CurrentTransportActions val="Next,Previous,Play,Stop,Seek"/>
<RelativeTimePosition val="0:03:31"/>
</InstanceID>
</Event>
 from service AVTransport

And this happens on stop

2023-10-14 14:46:34.441 [DEBUG] [internal.handler.UpnpRendererHandler] - UPnP device Lautsprecher Arbeitszimmer received variable LastChange with value <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS">
<InstanceID val="0">
<PlaybackStorageMedium val="NONE"/>
<AbsoluteTimePosition val="0:00:00"/>
<TransportState val="STOPPED"/>
<CurrentTransportActions val="Next,Previous,Play"/>
<CurrentMediaDuration val="00:00:00"/>
<CurrentTrackDuration val="00:00:00"/>
<RelativeTimePosition val="0:00:00"/>
</InstanceID>
</Event>
 from service AVTransport

Probably you are using accindetially your control item on the stop channel?

Album Art is working fine for me also using upmpdcli (moode audio player) configured as upnp-av.

I hope this helps…