search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
925 stars 428 forks source link

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

Closed lolodomo closed 7 months ago

lolodomo commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

Suspected PR: #3960 or #4116

openhab-bot commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

@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 commented 8 months ago

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 commented 8 months ago

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

I will try the WEB audio sink.

lolodomo commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 8 months ago

I don't know how to proceed now ?

lolodomo commented 8 months ago

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 commented 7 months ago

@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 commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

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

lolodomo commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

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.

lolodomo commented 7 months ago

Even with the jar manifest patched to version "3.0.0", the resolution is still failing:

21:55:33.398 [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:55:33.447 [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:?]
21:55:35.633 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.hue [273]
  Unresolved requirement: Import-Package: org.jupnp.model.meta; version="[3.0.0,4.0.0)"
  Unresolved requirement: Import-Package: org.openhab.core.config.discovery.upnp
    -> Export-Package: org.openhab.core.config.discovery.upnp; bundle-symbolic-name="org.openhab.core.config.discovery.upnp"; bundle-version="4.2.0.M1"; version="4.2.0"; uses:="org.jupnp.model.meta,org.openhab.core.config.discovery,org.openhab.core.thing"
       org.openhab.core.config.discovery.upnp [287]
         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:55:35.714 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.lgwebos [274]
  Unresolved requirement: Import-Package: org.jupnp.model.meta; version="[3.0.0,4.0.0)"
  Unresolved requirement: Import-Package: org.openhab.core.config.discovery.upnp
    -> Export-Package: org.openhab.core.config.discovery.upnp; bundle-symbolic-name="org.openhab.core.config.discovery.upnp"; bundle-version="4.2.0.M1"; version="4.2.0"; uses:="org.jupnp.model.meta,org.openhab.core.config.discovery,org.openhab.core.thing"
       org.openhab.core.config.discovery.upnp [287]
         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:55:38.076 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.sonos [283]
  Unresolved requirement: Import-Package: org.jupnp.model.meta; version="[3.0.0,4.0.0)"
  Unresolved requirement: Import-Package: org.openhab.core.config.discovery.upnp
    -> Export-Package: org.openhab.core.config.discovery.upnp; bundle-symbolic-name="org.openhab.core.config.discovery.upnp"; bundle-version="4.2.0.M1"; version="4.2.0"; uses:="org.jupnp.model.meta,org.openhab.core.config.discovery,org.openhab.core.thing"
       org.openhab.core.config.discovery.upnp [287]
         Unresolved requirement: Import-Package: org.jupnp; version="[3.0.0,4.0.0)"
  Unresolved requirement: Import-Package: org.openhab.core.io.transport.upnp
    -> Export-Package: org.openhab.core.io.transport.upnp; bundle-symbolic-name="org.openhab.core.io.transport.upnp"; bundle-version="4.2.0.M1"; version="4.2.0"
       org.openhab.core.io.transport.upnp [288]
         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:?]
org.osgi.framework.BundleException: Could not resolve module: org.openhab.core.config.discovery.upnp [287]
  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:55:38.977 [ERROR] [Events.Framework                     ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.core.io.transport.upnp [288]
  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:?]
openhab> bundle:list -s | grep upnp
259 x Active    x  80 x 3.0.0                  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

@wborn : any idea ? I only updated one line in META-INF/MANIFEST.MF:

Bundle-Version: 3.0.0
lolodomo commented 7 months ago

In the following days, I will try again with the packaged jupnp library but I will try to disable my Wifi on the RPI in case the library is no more working well when several network interfaces are on. Unfortunately, this is the only idea I have.

When I enabled DEBUG logs for org.jupnp today, I got no logs at all, don't know if this is expected.

lolodomo commented 7 months ago

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.

I just discovered I have sometimes these warnings also in 4.1.1 but UPnP and the Sonos binding are working. This is probably not the cause of the problem.

lolodomo commented 7 months ago

Finally, I believe I found the culpit which was replacing my JUPnP bundle at startup. It was because I setup to not use suggestions !

I have reset the 3 settings to true. Maybe there is something wrong with the handling of these settings and UPnP is in fact "disabled" ( even if I see the bundle active).

I will probably retry a full install of OH 4.2M1 in the next days, keeping the default values for the 3 suggestions settings.

lolodomo commented 7 months ago

I just tried a new OH installation, this time keeping default for all suggestions bundles. No change, the Sonos binding is still not working.

lolodomo commented 7 months ago

Interesting: if I disable my wifi interface, then the Sonos binding seems to be alive again, now channels are initialized.

lolodomo commented 7 months ago

@wborn : to summarize: I found that we have a problem when several IP v4 interfaces are up on the server (in my case a LAN interface and a wifi interface). If I disable the wifi interface, then it works well when I restart OH. I never encountered this problem before 4.2, I don't know if this by chance or if the new JUPnP library (or any other component in OH 4.2 involved in UPnP stuff) has suddenly a problem to handle several IP interfaces.

lolodomo commented 7 months ago

Enabling logging for Sonos binding + core.io.transport.upnp and comparing logs when WiFi interface is up or down, I can see in both cases that the Sonos is requesting GENA subscriptions and get a positive feedback for all. Then UPnP actions invoked from the OH server are also working in both cases but no events are received by the binding from the Sonos devices in the case both interfaces are up.

I will have now to go deeply in the JUPnP library (and adds logs) but here is my current hypothesis : the JUPnP library registered the OH server to the Sonos devices with a feedback URL built from my WiFi interface rather than my LAN interface. These HTTP URLs when invoked by the Sonos devices would then be rejected by the OH server that only listen to HTTP URLs based on my OH LAN server IP.

@wborn : do you remember to have changed the way the library handles the different interfaces ? I do not remember how the library is handling when there are several interfaces but it should normally also considered how the network settings are setup in the OH server.

lolodomo commented 7 months ago

Making small progress. The JUPnP library is searching devices on all interfaces that are up and store found devices. Discovered devices are probably in the order they notified their existence. When a binding wants to register to events delivered by a UPnP device/service, the first UPnP device in the registry matching the UDN is returned, this device can be sometimes the one discovered through the LAN interface, sometimes the WiFi interface. Depending on that, the callback URL setup when subscribing to events is either the one for the LAN interface or the one for the WiFi interface. It seems to be a problem for Sonos (I even see sometimes HTTP subscribe requests failing in timeout). I still do not understand why it does not work but I will try to force the retrieval of the right UPnP device in the registry so that the LAN IP is preferred and I will see if at least it solves the problem with Sonos.

wborn commented 7 months ago

Maybe you ran into https://github.com/jupnp/jupnp/issues/73?

lolodomo commented 7 months ago

Maybe you ran into jupnp/jupnp#73?

Not really but that is also very interesting because if getDevice is returning a different result during the time, it may explain why the core framework is not distributing events to bindings due to this test: https://github.com/openhab/openhab-core/blob/main/bundles/org.openhab.core.io.transport.upnp/src/main/java/org/openhab/core/io/transport/upnp/internal/UpnpIOServiceImpl.java#L157

Here is the getDevice method I am talking about: https://github.com/openhab/openhab-core/blob/main/bundles/org.openhab.core.io.transport.upnp/src/main/java/org/openhab/core/io/transport/upnp/internal/UpnpIOServiceImpl.java#L218

I have not yet verified but I expect several devices stored in the registry for the same UPnP device. Maybe there is only one per UPnP device, alternating.

lolodomo commented 7 months ago

I quickly checked the implementation of equals and it is mainly a comparison of the UDN in the objects. So it should not be a problem even if getDevice returns a different object, because UDN will be the same.

openhab-bot commented 7 months ago

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/66

lolodomo commented 7 months ago

In fact, there is only one RemoteDevice in registry per UPnP device. If the same device is discovered through different network interfaces, the object in registry is not duplicated but only updated. The local IP of the machine that started the discovery is part of this object. It is then used when creating the subscribe message to build the callback URL for transmitting events. Depending on the order of UPnP devices responding to SEARCH request on the different network interfacers, the event subscriptions will use as callback URL either the OH server LAN IP or the OH server WiFi IP. In practice, in my case with RPI and Sonos devices, it is often the WiFi IP that is selected. When WiFi IP is used, either Sonos devices are sending no events or the JUPnP library is just ignoring them. The most probable is a bug in the JUPnP library because no events are also received when some Sonos devices should use the LAN IP and others the WiFi IP. I imagine there is code in the library that registers HTTP services for each local IP, I should check and log this part of the code.

lolodomo commented 7 months ago

The JUPnP library is finally registering only one HTTP service on /upnpcallback whatever the number of interfaces. This service should work whatever valid host in URL is used (LAN IP or WiFi IP). I enabled new logs and I can confirm that no event subscribed is received on this service. That looks good to me in the library. Maybe the problem is on Sonos... Next step will be to hardcode the callback URL with a specific IP to see if it solves the problem.

lolodomo commented 7 months ago

I am now suspecting this line: https://github.com/jupnp/jupnp/blob/261787b3ad5b322c68baae4822150a14657b523b/bundles/org.jupnp/src/main/java/org/jupnp/OSGiUpnpServiceConfiguration.java#L245

lolodomo commented 7 months ago

I am now suspecting this line: https://github.com/jupnp/jupnp/blob/261787b3ad5b322c68baae4822150a14657b523b/bundles/org.jupnp/src/main/java/org/jupnp/OSGiUpnpServiceConfiguration.java#L245

@wborn : BINGO ! If I comment this line, the problem is solved !

In case you have several interfaces, createStreamServer is called for each interface. For each of them, this will finally lead to the call of the method registerServlet that will attach a servlet to the context path /upnpcallback: https://github.com/jupnp/jupnp/blob/261787b3ad5b322c68baae4822150a14657b523b/bundles/org.jupnp/src/main/java/org/jupnp/transport/impl/osgi/HttpServiceServletContainerAdapter.java#L81 The context patch is the same at each call, so the second and next calls will do nothing due to a check at the beginning of the method.

I do not understand what was the logic to unregister the HTTP service at the second call to createStreamServer. WDYT @wborn ?

PS: This is not something that was apparently changed recently so I still do not understand why it does not occur in OH 4.1.1.

lolodomo commented 7 months ago

I found the commit that introduced this code, it was in June 2015 ! The commit message is:

Added support for the upnpcallback servlet to work with both Servlet 2.4 (Synchronously) and Servlet 3.0 (Asynchronously). Made sure the upnpcallback servlet does not use the default HttpContext which may be secured, but instead always an unsecured one.

Whenever HttpService disappears/appears shutdown is performed synchronously and startup asynchronously after a delay of 1500 ms in order to properly reinitialize jupnp.

jlaur commented 7 months ago

The commit message is

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

lolodomo commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

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());