Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New version 3.0.0 of JUPnP library is breaking at least Sonos binding when several interfaces are up #4140

Closed
lolodomo opened this issue Mar 10, 2024 · 61 comments · Fixed by #4165
Labels
bug An unexpected problem or unintended behavior of the Core

Comments

@lolodomo
Copy link
Contributor

say in DSL rule is doing nothing.
In console, voice:say or audio:play are not working. The console commands I tried:

voice say "Voici un test de son"
audio play barking.mp3
audio play doorbell.mps3
audio play sonos:PLAY5:chambre barking.mp3
audio play sonos:PLAY5:chambre doorbell.mp3

I am using Sonos as audio sink and VoiceRSS as TTS.

The only DEBUG logs I can find are:

09:44:31.712 [DEBUG] [nhab.core.audio.internal.AudioServlet] - timeout 10 seconds => timestamp 4363672656075242 nanoseconds
09:44:41.718 [DEBUG] [nhab.core.audio.internal.AudioServlet] - Removed timed out stream 7e9d3aa8-00b5-406f-ba96-adb591315993

If I check the audio and voice bundles:

openhab> bundle:list -s | grep audio
160 x Active   x  80 x 4.2.0.M1               x org.openhab.core.audio
184 x Active   x  80 x 4.2.0.M1               x org.openhab.core.io.rest.audio
openhab> bundle:list -s | grep voice
193 x Active   x  80 x 4.2.0.M1               x org.openhab.core.io.rest.voice
225 x Active   x  80 x 4.2.0.M1               x org.openhab.core.voice
293 x Active   x  80 x 4.2.0.M1               x org.openhab.voice.voicerss
294 x Active   x  80 x 4.2.0.M1               x org.openhab.voice.voskstt
openhab>

@GiviMAD : as you are the one that updated this part recently, I am very afraid you broke it.

I am going to switch back to OH 4.1.1 to check if audio/voice stuff is working again.

@lolodomo lolodomo added the bug An unexpected problem or unintended behavior of the Core label Mar 10, 2024
@lolodomo
Copy link
Contributor Author

I can confirm that audio and voice stuff is working well in OH 4.1.1.
So this was broken after 4.1 was released.

@lolodomo
Copy link
Contributor Author

Suspected PR: #3960 or #4116

@openhab-bot
Copy link
Collaborator

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

https://community.openhab.org/t/openhab-4-2-milestone-discussion/154316/36

@GiviMAD
Copy link
Member

GiviMAD commented Mar 10, 2024

Hello @lolodomo, I think it should be related to #4116 because I have the 4.2.0 snapshot running without it and voice features seems to work fine. I will try to take a look these afternoon.

@GiviMAD
Copy link
Member

GiviMAD commented Mar 10, 2024

Taking a quick look, I think this line in #4116 is incorrect:

Integer bitRate = Math.round(format.getFrameRate() * format.getSampleSizeInBits() * format.getChannels());

It should be:

Integer bitRate = Math.round(format.getSampleRate() * format.getSampleSizeInBits() * format.getChannels());

I don't know if that could be the problem.

@GiviMAD
Copy link
Member

GiviMAD commented Mar 10, 2024

I've also reviewed #3960 and I don't think I have broken this with it. The only one I think can affect these is the change in the AudioStream::equal method but I think it's ok and I don't see any other thing suspicious.

@lolodomo
Copy link
Contributor Author

@openhab/core-maintainers : am I alone to not be able to use OH 4.2 due to this critical issue ?
@GiviMAD : is audio working for you ?

How can we progress ? Do you need I enable some logs ?

@GiviMAD
Copy link
Member

GiviMAD commented Mar 15, 2024

Hello @lolodomo
I installed the 4.2.0M1 and audio is working fine for me. I don't have a Sonos device but I tested with the pulseaudiobinding and also with the MainUI webaudiosink and both text-to-speech and sounds seems to work. Can you check if it works for you using the webaudiosink? Maybe the problem is at the Sonos binding.

@lolodomo
Copy link
Contributor Author

The Sonos audio sink and more generally the Sonos binding was not changed in 4.2.

I will try the WEB audio sink.

@lolodomo
Copy link
Contributor Author

Audio and voice is working when using the WEB audio sink.

So that means something was changed in the core framework breaking only certain audio sinks.
There was no change in the Sonos audio sink in OH 4.2.

@lolodomo
Copy link
Contributor Author

I got these strange DEBUG logs from the Sonos audio sink !

12:46:29.531 [DEBUG] [os.internal.handler.ZonePlayerHandler] - playNotificationSoundURI: currentURI null metadata null
12:46:29.564 [DEBUG] [os.internal.handler.ZonePlayerHandler] - Notification feature not yet implemented while the current media is being played

@lolodomo
Copy link
Contributor Author

The Sonos binding seems to be broken in 4.2, I do not receive anymore some of the important messages from UPnP subscriptions. Channels are no more updated.

@wborn : OH 4.2 is packaged with a new version of JUPnP for which you made a lot of changes. It could be the origin of the problem. Does one of your changes in JUPnP require a change in the bindings ?

bundle:list -s | grep upnp
259 x Active   x  80 x 3.0.0                  x org.jupnp
260 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.addon.upnp
261 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.jupnp
287 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.upnp
288 x Active   x  80 x 4.2.0.M1               x org.openhab.core.io.transport.upnp

@lolodomo
Copy link
Contributor Author

In OH 4.1.1, JUPnP library is in version 2.7.1.OH1 and the Sonos binding is working well.

I am now convinced that the problem is not the audio stuff in general (sorry to ping you @GiviMAD ) but the new version of the JUPnP library that broke the Sonos binding (and probably other bindings) .

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 16, 2024

I could try to install the old version of JUPnP library in OH 4.2M1 to confirm what I suspect but I am not yet sure how I can retrieve this old version (or build it).

Edit: ok, I can simply find the jar at this place runtime/system/org/jupnp/org.jupnp/2.7.1.OH1/org.jupnp-2.7.1.OH1.jar in my OH 4.1.1 installation.

@GiviMAD
Copy link
Member

GiviMAD commented Mar 16, 2024

I am now convinced that the problem is not the audio stuff in general (sorry to ping you @GiviMAD ) but the new version of the JUPnP library that broke the Sonos binding (and probably other bindings) .

No worries, happy to help!

@wborn
Copy link
Member

wborn commented Mar 17, 2024

Does one of your changes in JUPnP require a change in the bindings ?

Not that I know of but there were many changes so there could also be regressions. The changes were mostly cleanup, upgrades and switching the build from tycho to bnd.

@lolodomo
Copy link
Contributor Author

Unfortunately; if I install the 2.7.1 version of the JUPnP bundle in OH 4.2M1, bundles including the Sonos binding are no more running. So I cannot prove that the problem is the new version of JUPnP but I am almost certain that it is.

@lolodomo
Copy link
Contributor Author

I don't know how to proceed now ?

@lolodomo lolodomo changed the title Audio/voice stuff fully broken in 4.2 milestone 1 New version 3.0.0 of JUPnP library is breaking at least Sonos binding in OH 4.2M1 Mar 17, 2024
@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 17, 2024

What is happening is that events from Sonos devices are no more arriving to the binding even if I see in logs that subscriptions to UPnP services are mentioned as succeeded.

@lolodomo
Copy link
Contributor Author

@wborn : if I can't simply update the jupnp bundle to another version like in the past, is it due to the bundle org.openhab.core.config.jupnp you introduced in PR #4098 ?

in addition to the update of the jupnp bundle itself, what should I do to switch to previous version of jupnp in my OH 4.2M1 ?

@wborn
Copy link
Member

wborn commented Mar 18, 2024

The addon/core bundles will now have 3.0.0 as lowerbound in the jUPnP compatible version range so bundles will not properly resolve unless you recompile them or change the manifest manually.

@lolodomo
Copy link
Contributor Author

or change the manifest manually

You mean I should update manually the bundle version to 3.0.0 in the manifest of the old jupnp jar file ?
Would worth testing that.

@wborn
Copy link
Member

wborn commented Mar 18, 2024

Yes that may be a quick way to find out if it is due to the upgrade.

@lolodomo
Copy link
Contributor Author

I tried.
I patched the manifest naming my version 3.0.0.OH42
I used "3.0.0..OH42" to differentiate with the official version which is "3.0.0".
When I update the bundle, some bundles remains in Waiting state.


openhab> bundle:list -s | grep upnp
259 x Active   x  80 x 3.0.0.OH42             x org.jupnp
260 x Waiting  x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.addon.upnp
261 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.jupnp
287 x Waiting  x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.upnp
288 x Waiting  x  80 x 4.2.0.M1               x org.openhab.core.io.transport.upnp
openhab> bundle:list -s | grep sonos
283 x Waiting  x  80 x 4.2.0.M1               x org.openhab.binding.sonos

If I restart OH, in a very first time, I can catch that

openhab> bundle:list -s | grep upnp
259 x Resolved  x  80 x 3.0.0.OH42             x org.jupnp
260 x Installed x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.addon.upnp
261 x Installed x  80 x 4.2.0.M1               x org.openhab.core.config.jupnp
287 x Installed x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.upnp
288 x Installed x  80 x 4.2.0.M1               x org.openhab.core.io.transport.upnp
openhab> bundle:list -s | grep sonos
283 x Installed x  80 x 4.2.0.M1               x org.openhab.binding.sonos

but when the startup process ends, finally my jupnp bundle is automatically replaced by the official one having version 3.0.0.

openhab> bundle:list -s | grep upnp
259 x Active   x  80 x 3.0.0                  x org.jupnp
260 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.addon.upnp
261 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.jupnp
287 x Active   x  80 x 4.2.0.M1               x org.openhab.core.config.discovery.upnp
288 x Active   x  80 x 4.2.0.M1               x org.openhab.core.io.transport.upnp
openhab> bundle:list -s | grep sonos
283 x Active   x  80 x 4.2.0.M1               x org.openhab.binding.sonos

Why my bundle is overwritten at startup ?

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 18, 2024

I found something interesting in the logs at startup with the packaged JUPnP library (3.0.0), several lines of this kind:

21:00:02.381 [WARN ] [f.transport.servlet.ServletController] - Can't find the request for http://192.168.x.xxx:8080/upnpcallback/dev/RINCON_000E588EAE6601400_MR/svc/upnp-org/AVTransport/event/cb's Observer

This IP is the Wifi IP of my RPI, not the LAN IP.

In OH settings, I can see these two IP in the network settings but I selected the LAN IP as main network interface, not the Wifi interface.

I assume "f.transport.servlet.ServletController" is a class from JUPnP ? Why is my Wifi IP used ?

@lolodomo
Copy link
Contributor Author

Making slow progress with installation of the old JUPnP library.
Finally, I believe I found the culpit which was replacing my JUPnP bundle at startup. It was because I setup to not use suggestions !
Ok, I can see that the resolution is still failing for the other bundles. Maybe I should try with "3.0.1" rather than "3.0.0.OH42".

@lolodomo
Copy link
Contributor Author

Even with version "3.0.1", I still have problems:

21:47:40.116 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.core.config.discovery.addon.upnp [260]
  Unresolved requirement: Import-Package: org.jupnp; version="[3.0.0,4.0.0)"

        at org.eclipse.osgi.container.Module.start(Module.java:463) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]
21:47:40.165 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.core.config.jupnp [261]
  Unresolved requirement: Import-Package: org.jupnp; version="[3.0.0,4.0.0)"

        at org.eclipse.osgi.container.Module.start(Module.java:463) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.18.0.jar:?]
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.18.0.jar:?]

Let's make a last try using 3.0.0 as version.

@jlaur
Copy link
Contributor

jlaur commented Mar 27, 2024

The commit message is

For reference: jupnp/jupnp@c988925 (I also went looking for it 😉)

@lolodomo
Copy link
Contributor Author

What could make a difference between 4.2 and 4.1.1 is if ServiceReference serviceReference = context.getServiceReference(HttpService.class.getName()); was returning null in 4.1.1 while not null in 4.2.

@wborn : I am not enough expert in OSGi to understand where in the code HttpService is registered.

@wborn
Copy link
Member

wborn commented Mar 27, 2024

Is it also null in OH 4.1.1 if you restart the jupnp bundle after everything is started? If not it maybe timing related.

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 27, 2024

Is it also null in OH 4.1.1 if you restart the jupnp bundle after everything is started?

I can't verify, I don't think I can build the old JUPnP library. Is it possible ?

If so it maybe timing related.

Maybe.

Does the context.ungetService(httpServiceReference); make any sense to you ?

@lolodomo
Copy link
Contributor Author

The difference in code when the HTTP service is there or not seems to be mainly the computation of the listen port.

Maybe all this block could be ignored but I am not yet sure at all:

        if (serviceReference != null) {

            if (httpServiceReference != null) {
                // context.ungetService(httpServiceReference);
            }

            httpServiceReference = serviceReference;

            HttpService httpService = (HttpService) context.getService(serviceReference);

            if (httpService != null) {
                logger.debug("call new ServletStreamServerImpl {} {}", httpProxyPort,
                        callbackURI.getBasePath().getPort());
                return new ServletStreamServerImpl(new ServletStreamServerConfigurationImpl(
                        HttpServiceServletContainerAdapter.getInstance(httpService, context),
                        httpProxyPort != -1 ? httpProxyPort : callbackURI.getBasePath().getPort()));
            }
        }

to finally run that

return transportConfiguration.createStreamServer(networkAddressFactory.getStreamListenPort());

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 28, 2024

JUPnP main bundle is referencing the HttpService bundle but apparently the HttpService can be started after and in this case the code seems to restart JUPnP:
https://github.com/jupnp/jupnp/blob/261787b3ad5b322c68baae4822150a14657b523b/bundles/org.jupnp/src/main/java/org/jupnp/UpnpServiceImpl.java#L135

So the block I was talking about in my previous message is necessary. In fact, two cases are supported, when an HttpService bundle is started and it is not. It probably allows JUPnP to work even without an HttpService bundle ?

@wborn
Copy link
Member

wborn commented Mar 28, 2024

It probably allows JUPnP to work even without an HttpService bundle ?

Yes the HttpService only exists when using OSGi and JUPnP also supports OSGi-less Java stacks and Android Apps.

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 29, 2024

@wborn: I have a doubt about required/mandatory OSGi reference. In our case, we have:

@Component(configurationPid = "org.jupnp.upnpservice")
@Designate(ocd = UpnpServiceImpl.Config.class)
public class UpnpServiceImpl implements UpnpService {

    @ObjectClassDefinition(id = "org.jupnp.upnpservice", name = "jUPnP service configuration", description = "Configuration for jUPnP OSGi service")
    public @interface Config {
        @AttributeDefinition(name = "initialSearchEnabled", description = "Enable initial search when starting jUPnP service.")
        boolean initialSearchEnabled() default true;
    }

    public UpnpServiceImpl() {
    }

    public UpnpServiceImpl(UpnpServiceConfiguration configuration) {
        this.configuration = configuration;
    }

    @Activate
    public void activate(Config config) {
        scheduledFuture = null;
        scheduledExecutorService = createExecutor();
        isInitialSearchEnabled = config.initialSearchEnabled();
        startup();
    }

    @Deactivate
    public void deactivate() {
        if (scheduledFuture != null) {
            scheduledFuture.cancel(true);
        }

        scheduledExecutorService.shutdownNow();
        shutdown();
    }

    @Reference
    public void setUpnpServiceConfiguration(UpnpServiceConfiguration configuration) {
        this.configuration = configuration;
        if (isRunning) {
            restart(true);
        }
    }

    public void unsetUpnpServiceConfiguration(UpnpServiceConfiguration configuration) {
        this.configuration = null;
    }

    @Reference
    public void setHttpService(HttpService httpService) {
        // Only need to restart jupnp after/if HttpService appears
        if (isRunning) {
            shutdown(false);
            delayedStartup(1500);
        }
    }

    public void unsetHttpService(HttpService httpService) {
        // Only need to restart jupnp after/if HttpService disappears
        if (isRunning) {
            shutdown(false);
            delayedStartup(1500);
        }
    }
}

Are references to UpnpServiceConfiguration and HttpService required or optional ? I mean, will setUpnpServiceConfiguration and setHttpService always be called before activate is called ?

If it was a mandatory reference, I don't understand the comment "Only need to restart jupnp after/if HttpService appears".

What is sure is that there is no reference defined between OSGiUpnpServiceConfiguration and HttpService

@lolodomo
Copy link
Contributor Author

Maybe an attribute configurationPolicy is missing to set it to REQUIRED ? I am searching what is the default value...

@lolodomo
Copy link
Contributor Author

The default would be OPTIONAL (to be confirmed by someone who knows well OSGi).
In that case, I would understand the code restarting everything when the HttpService is injected.
My current feeling is that we should define a REQUIRED policy to activate the bundle only once OSGiUpnpServiceConfiguration and HttpService are injected.
WDYT @wborn ?

@lolodomo
Copy link
Contributor Author

On my RPI with snapshot 4012 and a patched version of JUPnP, here is the order at startup:

11:50:00.466 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.OSGiUpnpServiceConfiguration] : BundleComponentActivator : ComponentHolder created.
11:50:00.489 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : BundleComponentActivator : ComponentHolder created.
11:50:00.513 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.OSGiUpnpServiceConfiguration] : ConfigurableComponentHolder configuration updated for pid org.jupnp with change count 2
11:50:00.542 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Dependency Manager created HttpServiceinterface=org.osgi.service.http.HttpService, filter=null, policy=static, cardinality=1..1, bind=setHttpService, unbind=unsetHttpService, updated=null, field=null, field-option=null, collection-type=null, parameter=null
11:50:00.561 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Dependency Manager created UpnpServiceConfigurationinterface=org.jupnp.UpnpServiceConfiguration, filter=null, policy=static, cardinality=1..1, bind=setUpnpServiceConfiguration, unbind=unsetUpnpServiceConfiguration, updated=null, field=null, field-option=null, collection-type=null, parameter=null
11:50:00.582 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
11:50:00.601 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Component created: DS=DS13, implementation=org.jupnp.UpnpServiceImpl, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.jupnp.upnpservice]
11:50:00.621 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Component Services: scope=singleton, services=[org.jupnp.UpnpService]
11:50:00.634 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Component Properties: {initialSearchEnabled=true, osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
11:50:00.649 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Querying state disabled
11:50:00.661 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Querying state disabled
11:50:00.673 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Component can not be activated since it is in state disabled
11:50:00.686 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl] : Querying state disabled
11:50:00.697 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Updating target filters
11:50:00.709 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : No change in target property for dependency HttpService: currently registered: false
11:50:00.723 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] :  No existing service listener to unregister for dependency HttpService
11:50:00.737 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Setting target property for dependency HttpService to null
11:50:00.749 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : New service tracker for HttpService, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.http.HttpService), initialReferenceFilter (objectClass=org.osgi.service.http.HttpService)
11:50:00.767 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm HttpService tracker reset (closed)
11:50:00.780 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm HttpService tracking 1 SingleStatic added {org.osgi.service.http.HttpService, org.ops4j.pax.web.service.WebContainer}={org.ops4j.pax.web.log.ncsa.extended=true, org.ops4j.pax.web.ssl.keystore.password=********, service.scope=bundle, org.ops4j.pax.web.ssl.key.password=********, org.ops4j.pax.web.session.cookie.name=JSESSIONID, org.osgi.service.http.connector.name=default, org.ops4j.pax.web.enc.iterationcount=1000, org.ops4j.pax.web.log.ncsa.file=yyyy_mm_dd.request.log, org.ops4j.pax.web.server.eventDispatcherThreadCount=1, org.osgi.service.http.checkForwardedHeaders=false, org.ops4j.pax.web.enc.suffix=), org.ops4j.pax.web.digestAuth.maxNonceAge=60000, org.ops4j.pax.web.ssl.ciphersuites.included=, org.ops4j.pax.web.session.url=jsessionid, org.ops4j.pax.web.formAuth.errorRedirect=false, org.ops4j.pax.web.ssl.ciphersuites.excluded=^.*_(MD5|SHA|SHA1)$,^TLS_RSA_.*$,^SSL_.*$,^.*_NULL_.*$,^.*_anon_.*, org.ops4j.pax.web.enc.prefix=ENC(, org.ops4j.pax.web.server.maxThreads=50, org.ops4j.pax.web.validatePeerCerts=false, service.id=163, org.ops4j.pax.web.session.cookie.maxAge=-1, org.ops4j.pax.web.ssl.truststore.password=********, org.ops4j.pax.web.ssl.session.cacheSize=-1, org.ops4j.pax.web.ssl.truststore.type=JKS, org.ops4j.pax.web.ssl.keystore.type=JKS, org.ops4j.pax.web.ssl.session.enabled=true, org.ops4j.pax.web.ssl.protocol=TLSv1.3, org.osgi.service.http.port=8080, org.ops4j.pax.web.log.ncsa.file.date.format=yyyy-MM-dd, org.ops4j.pax.web.ssl.renegotiationLimit=-1, org.osgi.service.http.secure.enabled=true, org.osgi.service.http.enabled=true, org.ops4j.pax.web.server.idleTimeout=300000, org.ops4j.pax.web.log.ncsa.retaindays=90, org.ops4j.pax.web.log.ncsa.logtimezone=GMT, org.ops4j.pax.web.enc.algorithm=PBEWithHmacSHA256AndAES_128, org.ops4j.pax.web.validateCerts=false, org.ops4j.pax.web.config.files=/home/pi/openhab/runtime/etc/jetty.xml, org.ops4j.pax.web.ssl.renegotiationAllowed=true, org.ops4j.pax.web.digestAuth.maxNonceCount=1024, org.ops4j.pax.web.enableOCSP=false, org.ops4j.pax.web.ssl.clientauth.needed=false, org.ops4j.pax.web.enc.enabled=false, org.osgi.service.http.port.secure=8443, javax.servlet.context.tempdir=/home/pi/openhab/userdata/tmp, org.ops4j.pax.web.enableCRLDP=false, org.ops4j.pax.web.server.connector.idleTimeout=30000, org.ops4j.pax.web.session.timeout=10, org.ops4j.pax.web.ssl.clientauth.wanted=false, org.ops4j.pax.web.ssl.protocols.excluded=SSL,SSLv2,SSLv2Hello,SSLv3, service.bundleid=233, org.ops4j.pax.web.server.minThreads=2, org.ops4j.pax.web.session.cookie.secure=false, org.ops4j.pax.web.enc.masterpassword=********, org.ops4j.pax.web.log.ncsa.append=true, org.osgi.service.http.secure.connector.name=secureDefault, org.ops4j.pax.web.ssl.session.timeout=-1, org.ops4j.pax.web.listening.addresses=0.0.0.0, org.ops4j.pax.web.log.ncsa.buffered=true, org.ops4j.pax.web.session.cookie.sameSite=unset, org.ops4j.pax.web.log.ncsa.enabled=false, org.ops4j.pax.web.ssl.protocols.included=, org.ops4j.pax.web.session.cookie.httpOnly=true, org.ops4j.pax.web.server.showStacks=false} (enter)
11:50:00.885 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm HttpService tracking 1 SingleStatic active: false trackerOpened: false optional: false
11:50:00.899 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm HttpService tracking 1 SingleStatic added {org.osgi.service.http.HttpService, org.ops4j.pax.web.service.WebContainer}={org.ops4j.pax.web.log.ncsa.extended=true, org.ops4j.pax.web.ssl.keystore.password=********, service.scope=bundle, org.ops4j.pax.web.ssl.key.password=********, org.ops4j.pax.web.session.cookie.name=JSESSIONID, org.osgi.service.http.connector.name=default, org.ops4j.pax.web.enc.iterationcount=1000, org.ops4j.pax.web.log.ncsa.file=yyyy_mm_dd.request.log, org.ops4j.pax.web.server.eventDispatcherThreadCount=1, org.osgi.service.http.checkForwardedHeaders=false, org.ops4j.pax.web.enc.suffix=), org.ops4j.pax.web.digestAuth.maxNonceAge=60000, org.ops4j.pax.web.ssl.ciphersuites.included=, org.ops4j.pax.web.session.url=jsessionid, org.ops4j.pax.web.formAuth.errorRedirect=false, org.ops4j.pax.web.ssl.ciphersuites.excluded=^.*_(MD5|SHA|SHA1)$,^TLS_RSA_.*$,^SSL_.*$,^.*_NULL_.*$,^.*_anon_.*, org.ops4j.pax.web.enc.prefix=ENC(, org.ops4j.pax.web.server.maxThreads=50, org.ops4j.pax.web.validatePeerCerts=false, service.id=163, org.ops4j.pax.web.session.cookie.maxAge=-1, org.ops4j.pax.web.ssl.truststore.password=********, org.ops4j.pax.web.ssl.session.cacheSize=-1, org.ops4j.pax.web.ssl.truststore.type=JKS, org.ops4j.pax.web.ssl.keystore.type=JKS, org.ops4j.pax.web.ssl.session.enabled=true, org.ops4j.pax.web.ssl.protocol=TLSv1.3, org.osgi.service.http.port=8080, org.ops4j.pax.web.log.ncsa.file.date.format=yyyy-MM-dd, org.ops4j.pax.web.ssl.renegotiationLimit=-1, org.osgi.service.http.secure.enabled=true, org.osgi.service.http.enabled=true, org.ops4j.pax.web.server.idleTimeout=300000, org.ops4j.pax.web.log.ncsa.retaindays=90, org.ops4j.pax.web.log.ncsa.logtimezone=GMT, org.ops4j.pax.web.enc.algorithm=PBEWithHmacSHA256AndAES_128, org.ops4j.pax.web.validateCerts=false, org.ops4j.pax.web.config.files=/home/pi/openhab/runtime/etc/jetty.xml, org.ops4j.pax.web.ssl.renegotiationAllowed=true, org.ops4j.pax.web.digestAuth.maxNonceCount=1024, org.ops4j.pax.web.enableOCSP=false, org.ops4j.pax.web.ssl.clientauth.needed=false, org.ops4j.pax.web.enc.enabled=false, org.osgi.service.http.port.secure=8443, javax.servlet.context.tempdir=/home/pi/openhab/userdata/tmp, org.ops4j.pax.web.enableCRLDP=false, org.ops4j.pax.web.server.connector.idleTimeout=30000, org.ops4j.pax.web.session.timeout=10, org.ops4j.pax.web.ssl.clientauth.wanted=false, org.ops4j.pax.web.ssl.protocols.excluded=SSL,SSLv2,SSLv2Hello,SSLv3, service.bundleid=233, org.ops4j.pax.web.server.minThreads=2, org.ops4j.pax.web.session.cookie.secure=false, org.ops4j.pax.web.enc.masterpassword=********, org.ops4j.pax.web.log.ncsa.append=true, org.osgi.service.http.secure.connector.name=secureDefault, org.ops4j.pax.web.ssl.session.timeout=-1, org.ops4j.pax.web.listening.addresses=0.0.0.0, org.ops4j.pax.web.log.ncsa.buffered=true, org.ops4j.pax.web.session.cookie.sameSite=unset, org.ops4j.pax.web.log.ncsa.enabled=false, org.ops4j.pax.web.ssl.protocols.included=, org.ops4j.pax.web.session.cookie.httpOnly=true, org.ops4j.pax.web.server.showStacks=false} (exit)
11:50:01.003 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm HttpService tracker opened
11:50:01.014 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : registering service listener for dependency HttpService
11:50:01.027 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : No change in target property for dependency UpnpServiceConfiguration: currently registered: false
11:50:01.041 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] :  No existing service listener to unregister for dependency UpnpServiceConfiguration
11:50:01.054 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Setting target property for dependency UpnpServiceConfiguration to null
11:50:01.067 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : New service tracker for UpnpServiceConfiguration, initial active: false, previous references: {}, classFilter: (objectClass=org.jupnp.UpnpServiceConfiguration), initialReferenceFilter (objectClass=org.jupnp.UpnpServiceConfiguration)
11:50:01.085 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm UpnpServiceConfiguration tracker reset (closed)
11:50:01.098 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm UpnpServiceConfiguration tracker opened
11:50:01.110 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : registering service listener for dependency UpnpServiceConfiguration
11:50:01.124 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
11:50:01.137 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
11:50:01.151 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
11:50:01.170 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm osgi.ds.satisfying.condition tracker reset (closed)
11:50:01.183 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
11:50:01.202 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
11:50:01.221 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm osgi.ds.satisfying.condition tracker opened
11:50:01.234 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : registering service listener for dependency osgi.ds.satisfying.condition
11:50:01.247 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Changed state from disabled to unsatisfiedReference
11:50:01.259 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Component enabled
11:50:01.271 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : ActivateInternal
11:50:01.282 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.294 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.306 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Activating component from state unsatisfiedReference
11:50:01.318 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.330 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.342 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Dependency not satisfied: UpnpServiceConfiguration
11:50:01.354 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Not all dependencies satisfied, cannot activate
11:50:01.428 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm UpnpServiceConfiguration tracking 3 SingleStatic added {org.jupnp.UpnpServiceConfiguration}={autoEnable=false, service.id=491, service.bundleid=250, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), threadPoolSize=15, component.name=org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration, component.id=319, asyncThreadPoolSize=30, felix.fileinstall.filename=file:/home/pi/openhab/userdata/etc/org.jupnp.cfg, service.pid=org.jupnp, multicastResponsePort=0} (enter)
11:50:01.454 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : ActivateInternal
11:50:01.466 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.478 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.490 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Activating component from state unsatisfiedReference
11:50:01.503 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.516 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state unsatisfiedReference
11:50:01.529 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Changed state from unsatisfiedReference to satisfied
11:50:01.542 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : registration change queue [registered]
11:50:01.574 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Checking constructor public org.jupnp.UpnpServiceImpl()
11:50:01.588 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Found constructor with 0 arguments : public org.jupnp.UpnpServiceImpl()
11:50:01.602 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getting bind: setHttpService
11:50:01.614 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Locating method setHttpService in class org.jupnp.UpnpServiceImpl
11:50:01.628 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: Looking for method org.jupnp.UpnpServiceImpl.setHttpService
11:50:01.644 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Declared Method org.jupnp.UpnpServiceImpl.setHttpService([interface org.osgi.framework.ServiceReference]) not found
11:50:01.659 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Declared Method org.jupnp.UpnpServiceImpl.setHttpService([interface org.osgi.service.component.ComponentServiceObjects]) not found
11:50:01.675 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getClassFromComponentClassLoader: Looking for interface class org.osgi.service.http.HttpService through loader of org.jupnp.UpnpServiceImpl
11:50:01.691 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getClassFromComponentClassLoader: Found class org.osgi.service.http.HttpService
11:50:01.705 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: No method taking ServiceReference found, checking method taking org.osgi.service.http.HttpService
11:50:01.720 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: Found Method public void org.jupnp.UpnpServiceImpl.setHttpService(org.osgi.service.http.HttpService)
11:50:01.735 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Found bind method: public void org.jupnp.UpnpServiceImpl.setHttpService(org.osgi.service.http.HttpService)
11:50:01.749 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getting bind: setUpnpServiceConfiguration
11:50:01.762 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Locating method setUpnpServiceConfiguration in class org.jupnp.UpnpServiceImpl
11:50:01.776 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: Looking for method org.jupnp.UpnpServiceImpl.setUpnpServiceConfiguration
11:50:01.791 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Declared Method org.jupnp.UpnpServiceImpl.setUpnpServiceConfiguration([interface org.osgi.framework.ServiceReference]) not found
11:50:01.806 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Declared Method org.jupnp.UpnpServiceImpl.setUpnpServiceConfiguration([interface org.osgi.service.component.ComponentServiceObjects]) not found
11:50:01.823 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getClassFromComponentClassLoader: Looking for interface class org.jupnp.UpnpServiceConfiguration through loader of org.jupnp.UpnpServiceImpl
11:50:01.838 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getClassFromComponentClassLoader: Found class org.jupnp.UpnpServiceConfiguration
11:50:01.852 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: No method taking ServiceReference found, checking method taking org.jupnp.UpnpServiceConfiguration
11:50:01.867 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : doFindMethod: Found Method public void org.jupnp.UpnpServiceImpl.setUpnpServiceConfiguration(org.jupnp.UpnpServiceConfiguration)
11:50:01.883 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Found bind method: public void org.jupnp.UpnpServiceImpl.setUpnpServiceConfiguration(org.jupnp.UpnpServiceConfiguration)
11:50:01.910 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration 0 0 true
11:50:01.939 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration activate
11:50:01.949 [INFO ] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createConfiguration threadPoolSize = 15 true
11:50:01.961 [INFO ] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createConfiguration asyncThreadPoolSize = 30 true
11:50:01.973 [INFO ] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration retryAfterSeconds = 600
11:50:01.984 [INFO ] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration retryIterations = 5
11:50:01.994 [INFO ] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration timeoutSeconds = 10
11:50:02.005 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - Creating mainThreadPool
11:50:02.020 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - Creating asyncThreadPool
11:50:02.030 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - Creating remoteThreadPool
11:50:02.151 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration@ebc57b activated
11:50:02.163 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : This thread collected dependencies
11:50:02.175 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getService (single component manager) dependencies collected.
11:50:02.189 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state satisfied
11:50:02.201 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Querying state satisfied
11:50:02.214 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : For dependency HttpService, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.http.HttpService, org.ops4j.pax.web.service.WebContainer}={org.ops4j.pax.web.log.ncsa.extended=true, org.ops4j.pax.web.ssl.keystore.password=********, service.scope=bundle, org.ops4j.pax.web.ssl.key.password=********, org.ops4j.pax.web.session.cookie.name=JSESSIONID, org.osgi.service.http.connector.name=default, org.ops4j.pax.web.enc.iterationcount=1000, org.ops4j.pax.web.log.ncsa.file=yyyy_mm_dd.request.log, org.ops4j.pax.web.server.eventDispatcherThreadCount=1, org.osgi.service.http.checkForwardedHeaders=false, org.ops4j.pax.web.enc.suffix=), org.ops4j.pax.web.digestAuth.maxNonceAge=60000, org.ops4j.pax.web.ssl.ciphersuites.included=, org.ops4j.pax.web.session.url=jsessionid, org.ops4j.pax.web.formAuth.errorRedirect=false, org.ops4j.pax.web.ssl.ciphersuites.excluded=^.*_(MD5|SHA|SHA1)$,^TLS_RSA_.*$,^SSL_.*$,^.*_NULL_.*$,^.*_anon_.*, org.ops4j.pax.web.enc.prefix=ENC(, org.ops4j.pax.web.server.maxThreads=50, org.ops4j.pax.web.validatePeerCerts=false, service.id=163, org.ops4j.pax.web.session.cookie.maxAge=-1, org.ops4j.pax.web.ssl.truststore.password=********, org.ops4j.pax.web.ssl.session.cacheSize=-1, org.ops4j.pax.web.ssl.truststore.type=JKS, org.ops4j.pax.web.ssl.keystore.type=JKS, org.ops4j.pax.web.ssl.session.enabled=true, org.ops4j.pax.web.ssl.protocol=TLSv1.3, org.osgi.service.http.port=8080, org.ops4j.pax.web.log.ncsa.file.date.format=yyyy-MM-dd, org.ops4j.pax.web.ssl.renegotiationLimit=-1, org.osgi.service.http.secure.enabled=true, org.osgi.service.http.enabled=true, org.ops4j.pax.web.server.idleTimeout=300000, org.ops4j.pax.web.log.ncsa.retaindays=90, org.ops4j.pax.web.log.ncsa.logtimezone=GMT, org.ops4j.pax.web.enc.algorithm=PBEWithHmacSHA256AndAES_128, org.ops4j.pax.web.validateCerts=false, org.ops4j.pax.web.config.files=/home/pi/openhab/runtime/etc/jetty.xml, org.ops4j.pax.web.ssl.renegotiationAllowed=true, org.ops4j.pax.web.digestAuth.maxNonceCount=1024, org.ops4j.pax.web.enableOCSP=false, org.ops4j.pax.web.ssl.clientauth.needed=false, org.ops4j.pax.web.enc.enabled=false, org.osgi.service.http.port.secure=8443, javax.servlet.context.tempdir=/home/pi/openhab/userdata/tmp, org.ops4j.pax.web.enableCRLDP=false, org.ops4j.pax.web.server.connector.idleTimeout=30000, org.ops4j.pax.web.session.timeout=10, org.ops4j.pax.web.ssl.clientauth.wanted=false, org.ops4j.pax.web.ssl.protocols.excluded=SSL,SSLv2,SSLv2Hello,SSLv3, service.bundleid=233, org.ops4j.pax.web.server.minThreads=2, org.ops4j.pax.web.session.cookie.secure=false, org.ops4j.pax.web.enc.masterpassword=********, org.ops4j.pax.web.log.ncsa.append=true, org.osgi.service.http.secure.connector.name=secureDefault, org.ops4j.pax.web.ssl.session.timeout=-1, org.ops4j.pax.web.listening.addresses=0.0.0.0, org.ops4j.pax.web.log.ncsa.buffered=true, org.ops4j.pax.web.session.cookie.sameSite=unset, org.ops4j.pax.web.log.ncsa.enabled=false, org.ops4j.pax.web.ssl.protocols.included=, org.ops4j.pax.web.session.cookie.httpOnly=true, org.ops4j.pax.web.server.showStacks=false}] service: [Proxy for HttpService (enabled) for bundle org.jupnp_3.0.1.202403291044 [248]]]]
11:50:02.323 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : For dependency UpnpServiceConfiguration, optional: false; to bind: [[RefPair: ref: [{org.jupnp.UpnpServiceConfiguration}={autoEnable=false, service.id=491, service.bundleid=250, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), threadPoolSize=15, component.name=org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration, component.id=319, asyncThreadPoolSize=30, felix.fileinstall.filename=file:/home/pi/openhab/userdata/etc/org.jupnp.cfg, service.pid=org.jupnp, multicastResponsePort=0}] service: [org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration@ebc57b]]]
11:50:02.353 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
11:50:02.374 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoking bind: setHttpService: parameters [org.ops4j.pax.web.service.internal.HttpServiceProxy]
11:50:02.388 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - UpnpServiceImpl setHttpService
11:50:02.398 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoked bind: setHttpService
11:50:02.465 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoking bind: setUpnpServiceConfiguration: parameters [org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration]
11:50:02.480 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - UpnpServiceImpl setUpnpServiceConfiguration
11:50:02.491 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoked bind: setUpnpServiceConfiguration
11:50:02.504 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : getting activate: activate
11:50:02.516 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Locating method activate in class org.jupnp.UpnpServiceImpl
11:50:02.529 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Declared Method org.jupnp.UpnpServiceImpl.activate([interface org.osgi.service.component.ComponentContext]) not found
11:50:02.545 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Found activate method: public void org.jupnp.UpnpServiceImpl.activate(org.jupnp.UpnpServiceImpl$Config)
11:50:02.564 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoking activate: activate: parameters [jdk.proxy23.$Proxy127]
11:50:02.578 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - UpnpServiceImpl activate
11:50:02.589 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - UpnpServiceImpl startup configurationInjected true httpServiceInjected true
11:50:02.601 [INFO ] [org.jupnp.UpnpServiceImpl            ] - Starting UPnP service...
11:50:02.611 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - Using configuration: org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration
11:50:02.695 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createStreamServer true false
11:50:02.710 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - call new ServletStreamServerImpl -1 -1
11:50:02.760 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createStreamServer true true
11:50:02.771 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - call new ServletStreamServerImpl -1 -1
11:50:02.784 [DEBUG] [rg.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createStreamClient
11:50:02.812 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - UPnP service started successfully
11:50:02.854 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : invoked activate: activate
11:50:02.867 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Set implementation object for component
11:50:02.880 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : Changed state from satisfied to active
11:50:02.961 [DEBUG] [org.jupnp.UpnpServiceImpl            ] - bundle org.jupnp:3.0.1.202403291044 (248)[org.jupnp.UpnpServiceImpl(316)] : dm UpnpServiceConfiguration tracking 3 SingleStatic added {org.jupnp.UpnpServiceConfiguration}={autoEnable=false, service.id=491, service.bundleid=250, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), threadPoolSize=15, component.name=org.openhab.core.config.jupnp.internal.OHUpnpServiceConfiguration, component.id=319, asyncThreadPoolSize=30, felix.fileinstall.filename=file:/home/pi/openhab/userdata/etc/org.jupnp.cfg, service.pid=org.jupnp, multicastResponsePort=0} (exit)

The sequence is as if the policy was REQUIRED ?

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 29, 2024

Looking more attentively at the first lines, it seems to be rather optional:

[org.jupnp.UpnpServiceImpl] : Component created: DS=DS13, implementation=org.jupnp.UpnpServiceImpl, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.jupnp.upnpservice]

That would mean the loading order could be different and my dependencies could be not yet injected when the component is activated ?

@lolodomo
Copy link
Contributor Author

lolodomo commented Mar 29, 2024

In addition to the fact that I would expect required OSGi dependencies to avoid potential re-init of all stuff in the bundle, I also see no valid reason to release the OSGi HttpService. The idea was maybe to trigger the unset method in the main bundle and then restart all the stuff but this time without using the HttpService. In addition to the fact that it apparently does not work well, my question is what is the interest of doing that (because this is ok to use the HttpService) ?

lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 29, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 29, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 29, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 30, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 30, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Mar 30, 2024
Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
lolodomo added a commit to lolodomo/jupnp that referenced this issue Apr 1, 2024
Move OSGi dependency to HttpService from UpnpServiceImpl to OSGiUpnpServiceConfiguration.

Fix openhab/openhab-core#4140

Signed-off-by: Laurent Garnier <lg.hc@free.fr>
@lolodomo
Copy link
Contributor Author

lolodomo commented Apr 1, 2024

Issue has to be reopened until OH switchs to JUPnP 3.0.1.

@wborn
Copy link
Member

wborn commented Apr 1, 2024

I already thought that might happen based on the "Fix ..." text in your PR. 😉

@wborn wborn reopened this Apr 1, 2024
@openhab-bot
Copy link
Collaborator

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

https://community.openhab.org/t/openhab-4-2-milestone-discussion/154316/103

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of the Core
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants