Openhab 3.4.1 and Upnpcontrol (on Docker)

Scriptwriter · February 22, 2023, 3:02pm

Hi all,
The installation:
my installation of openhab 3.4.1 is runing in docker-container from the official container.
The Container runs in Host-Mode

The Problem:
upnp renderer and other devices were not discovered automaticly and also it is not possible to get the thing online if im creating it manually.

NOT THE PROBLEM:
installation generally runs with a lot of things fine.

What i confirmed:
1.) inside container on a bash: tcpdump -vv -A -s 0 -i any host 239.255.255.250 and port 1900 | grep LOCATION
this is showing successfully the multicasts of 2 devices
2.) inside container: curl http://192.168.xx.xx:8080/MediaRenderer/desc.xml
it is possible to request the url of one multicasted renderer

What i did also:
set DEBUG org.openhab.core.config.discovery.upnp
set DEBUG org.openhab.core.io.transport.upnp
and tail -f the openhab.log to see something abould upnp but nothing.

So im asking if someone has a idea what i can do to get my dlna/upnp devices into openhab?

Best regards

Andreas

Cplant · February 22, 2023, 9:44pm

Not sure if this helps, but this is how I got openhab running on Docker on my end.

Scriptwriter · February 23, 2023, 7:15am

Hi Cplant, thank you - no, the problem is not installation on docker. this is running since multiple years fine.

the problem is as i described that openhab is not hooking up the network messages from upnp-devices. the problem is that it is not possible to get UPNPCONTROL to run but as i verified the messages are coming into the container.
Thats why im searching for a hint to get UPNP to run with openhab 3.4.1. I have 2 Devices: a NAS with music and a renderer which is a yamaha device which can play dlna…

Mherwege · February 23, 2023, 7:20am

While the upnpcontrol binding relies on the upnp transport and something should appear there, it could be useful to switch on trace logging for org.openhab.binding.upnpcontrol to see if something shows up there.

Scriptwriter · February 23, 2023, 7:28am

Hi Mark,
in caraf console i entered
set DEBUG org.openhab.binding.upnpcontrol
then i did a tailf on openhab.log and parallel a tcpdump for getting out when advices are there on multicast port 1900.
situation is that im getting absolutely nothing in the trace related to “org.openhab.binding.upnpcontrol”. im doing something wrong to enable tracing?

Mherwege · February 23, 2023, 7:50am

Try log:set TRACE org.openhab.binding.upnpcontrol.
Also check that the binding is running and active: in karaf console: bundle:list | grep UPnP. There should be 4 bundels, all active.

Scriptwriter · February 23, 2023, 10:23am

Hi Mark,
thanks for the hint. ok, i was able to activate Trace now.

openhab> bundle:list | grep UPnP                                                                                                                                                                                                
263 │ Active │  80 │ 2.6.1                  │ JUPnP Library
291 │ Active │  80 │ 3.4.1                  │ openHAB Add-ons :: Bundles :: UPnP Control Binding
294 │ Active │  80 │ 3.4.1                  │ openHAB Core :: Bundles :: Configuration UPnP Discovery
303 │ Active │  80 │ 3.4.1                  │ openHAB Core :: Bundles :: UPnP Transport

But in the trace (more than 1/2hour it was running) im only seeing the following lines:

cat  /data/openhab/openhab_userdata/logs/openhab.log|grep DEBUG
2023-02-23 10:17:10.285 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.1 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(345)] : Querying state active
2023-02-23 10:17:10.288 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.1 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(342)] : Querying state active
2023-02-23 10:17:10.291 [DEBUG] [pnpDynamicCommandDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.1 (291)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicCommandDescriptionProvider(343)] : Querying state active
2023-02-23 10:17:10.292 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - bundle org.openhab.binding.upnpcontrol:3.4.1 (291)[org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider(344)] : Querying state active

nothing else more (also if im greping for upnp)

The manually created things - here one as example still offline:
UPnP device with UDN 5f9ec1b3-ed59-1900-4530-00a0deb7b42e not yet registered
autodetection of the things was also not possible

Mherwege · February 23, 2023, 10:56am

If you run discovery, you should see a log like:
Device type {}, manufacturer {}, model {}, SN# {}, UDN {}
This would be for any upnp device detected in the network, not just media servers or networks.
If you do not see any of that, it means OH does not look for upnp messages on the right network interface. Check docker and network settings. I don’t use docker, so don’t know much about it.

Also, to get the complete picture, don’t grep the log on DEBUG, but grep on something like upnp. Grep on DEBUG will not show you TRACE logs.

Scriptwriter · February 23, 2023, 2:16pm

1 updated to the new 3.4.2 which i have seen that this was out last week.

but devices were not shown as you wrote.

output:

023-02-23 14:51:02.882 [DEBUG] [nfig.UpnpControlBindingConfiguration] - Storage path updated to /openhab/userdata/upnpcontrol/
2023-02-23 14:51:02.912 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Updated binding configuration to org.openhab.binding.upnpcontrol.internal.config.UpnpControlBindingConfiguration@57fe7322
2023-02-23 14:51:02.914 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : getting activate: activate
2023-02-23 14:51:02.915 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Locating method activate in class org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory
2023-02-23 14:51:02.944 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Declared Method org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-02-23 14:51:02.956 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2023-02-23 14:51:02.957 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2023-02-23 14:51:02.959 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2023-02-23 14:51:02.962 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : invoked activate: activate
2023-02-23 14:51:02.975 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Set implementation object for component
2023-02-23 14:51:02.980 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : Changed state from satisfied to active
2023-02-23 14:51:02.984 [DEBUG] [l.internal.UpnpControlHandlerFactory] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.UpnpControlHandlerFactory(378)] : dm $004 tracking 6 SingleStatic added {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider}={service.id=685, service.bundleid=291, service.scope=bundle, component.name=org.openhab.binding.upnpcontrol.internal.UpnpDynamicStateDescriptionProvider, component.id=380} (exit)
2023-02-23 14:51:02.987 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component created: DS=DS13, implementation=org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant]
2023-02-23 14:51:02.992 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component Services: scope=singleton, services=[org.openhab.core.config.discovery.upnp.UpnpDiscoveryParticipant]
2023-02-23 14:51:02.993 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component Properties: {}
2023-02-23 14:51:03.001 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-02-23 14:51:03.012 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-02-23 14:51:03.023 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Component can not be activated since it is in state disabled
2023-02-23 14:51:03.031 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant] : Querying state disabled
2023-02-23 14:51:03.034 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Updating target filters
2023-02-23 14:51:03.047 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Changed state from disabled to unsatisfiedReference
2023-02-23 14:51:03.056 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Component enabled
2023-02-23 14:51:03.065 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : ActivateInternal
2023-02-23 14:51:03.086 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state unsatisfiedReference
2023-02-23 14:51:03.087 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state unsatisfiedReference
2023-02-23 14:51:03.089 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Activating component from state unsatisfiedReference
2023-02-23 14:51:03.091 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state unsatisfiedReference
2023-02-23 14:51:03.093 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state unsatisfiedReference
2023-02-23 14:51:03.094 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Changed state from unsatisfiedReference to satisfied
2023-02-23 14:51:03.106 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : registration change queue [registered]
2023-02-23 14:51:03.185 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Checking constructor public org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant()
2023-02-23 14:51:03.198 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Found constructor with 0 arguments : public org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant()
2023-02-23 14:51:03.201 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : This thread collected dependencies
2023-02-23 14:51:03.219 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : getService (single component manager) dependencies collected.
2023-02-23 14:51:03.220 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state satisfied
2023-02-23 14:51:03.222 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Querying state satisfied
2023-02-23 14:51:03.223 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : getting activate: activate
2023-02-23 14:51:03.224 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Locating method activate in class org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant
2023-02-23 14:51:03.225 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Declared Method org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-02-23 14:51:03.256 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Locating method activate in class java.lang.Object
2023-02-23 14:51:03.257 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-02-23 14:51:03.263 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : activate method [activate] not found, ignoring
2023-02-23 14:51:03.264 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Set implementation object for component
2023-02-23 14:51:03.271 [DEBUG] [very.UpnpControlDiscoveryParticipant] - bundle org.openhab.binding.upnpcontrol:3.4.2 (291)[org.openhab.binding.upnpcontrol.internal.discovery.UpnpControlDiscoveryParticipant(381)] : Changed state from satisfied to active
2023-02-23 14:51:03.384 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Media renderer handler created for UPnPRenderer yamaha with UID upnpcontrol:upnprenderer:e621b4e6a0
2023-02-23 14:51:03.413 [DEBUG] [internal.handler.UpnpRendererHandler] - Initializing handler for media renderer device UPnPRenderer yamaha
2023-02-23 14:51:03.459 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Media server handler created for UPnPServer NAS with UID upnpcontrol:upnpserver:976e7c94c6
2023-02-23 14:51:03.503 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnprenderer:e621b4e6a0:playlistselect
2023-02-23 14:51:03.511 [DEBUG] [l.internal.handler.UpnpServerHandler] - Initializing handler for media server device UPnPServer NAS
2023-02-23 15:02:26.519 [DEBUG] [internal.handler.UpnpRendererHandler] - Disposing handler for media renderer device UPnPRenderer yamaha
2023-02-23 15:02:27.136 [DEBUG] [.UpnpDynamicStateDescriptionProvider] - Adding state description for channel upnpcontrol:upnpserver:976e7c94c6:upnprenderer
2023-02-23 15:02:27.139 [DEBUG] [l.internal.handler.UpnpServerHandler] - Renderer option upnpcontrol:upnprenderer:e621b4e6a0 added to UPnPServer NAS
2023-02-23 15:02:27.142 [DEBUG] [l.internal.UpnpControlHandlerFactory] - Media renderer handler created for UPnPRenderer yamaha with UID upnpcontrol:upnprenderer:e621b4e6a0
2023-02-23 15:02:27.157 [DEBUG] [pnpDynamicCommandDescriptionProvider] - Adding command description for channel upnpcontrol:upnpserver:976e7c94c6:playlistselect
2023-02-23 15:02:27.159 [DEBUG] [internal.handler.UpnpRendererHandler] - Initializing handler for media renderer device UPnPRenderer yamaha

So from my point of view it seems that it is not listening to the multicasts on port 1900 which i verified that they are available in container.

Lolodomo · February 24, 2023, 11:59am

As a reminder, UPnP stuff is managed mainly by the jupnp library.

Scriptwriter · February 27, 2023, 12:49pm

ok, i searched for other cases and got out that it is possible to debug jupnp by command
log:set TRACE org.jupnp
this told me the following:

i have a lot of docker networks and the container openhab is in host mode. in config under network i selected the main hostnetwork only but. openhab seems to ignore and SENDS upnp on all networks:

2023-02-27 14:07:22.791 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing new datagram packet with 94 bytes for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.791 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending UDP datagram packet to: /239.255.255.250:1900
2023-02-27 14:07:22.793 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /172.27.0.1:0
2023-02-27 14:07:22.794 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /172.26.0.1:0
2023-02-27 14:07:22.796 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing message data for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.796 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.798 [TRACE] [upnp.transport.spi.DatagramProcessor] - M-SEARCH * HTTP/1.1
2023-02-27 14:07:22.799 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.800 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing new datagram packet with 94 bytes for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.801 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending UDP datagram packet to: /239.255.255.250:1900
2023-02-27 14:07:22.802 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /172.26.0.1:0
2023-02-27 14:07:22.804 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /192.168.2.244:0
2023-02-27 14:07:22.812 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing message data for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.813 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.814 [TRACE] [upnp.transport.spi.DatagramProcessor] - M-SEARCH * HTTP/1.1
2023-02-27 14:07:22.815 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.816 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing new datagram packet with 94 bytes for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.817 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending UDP datagram packet to: /239.255.255.250:1900
2023-02-27 14:07:22.818 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /192.168.2.244:0
2023-02-27 14:07:22.819 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /172.31.0.1:0
2023-02-27 14:07:22.820 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing message data for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.821 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.823 [TRACE] [upnp.transport.spi.DatagramProcessor] - M-SEARCH * HTTP/1.1
2023-02-27 14:07:22.824 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------
2023-02-27 14:07:22.825 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing new datagram packet with 94 bytes for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:22.826 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending UDP datagram packet to: /239.255.255.250:1900
2023-02-27 14:07:22.829 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /172.31.0.1:0
2023-02-27 14:07:22.830 [TRACE] [org.jupnp.transport.Router          ] - Releasing router lock: ReadLock
2023-02-27 14:07:22.831 [TRACE] [g.jupnp.protocol.async.SendingSearch] - Sleeping 500 milliseconds
2023-02-27 14:07:23.020 [TRACE] [org.jupnp.registry.Registry         ] - Maintaining registry...
2023-02-27 14:07:23.021 [TRACE] [org.jupnp.registry.Registry         ] - Executing pending operations: 0
2023-02-27 14:07:23.333 [TRACE] [org.jupnp.transport.Router          ] - Trying to obtain lock with timeout milliseconds '6000': ReadLock
2023-02-27 14:07:23.334 [TRACE] [org.jupnp.transport.Router          ] - Acquired router lock: ReadLock
2023-02-27 14:07:23.335 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Sending message from address: /192.168.128.1:0
2023-02-27 14:07:23.336 [TRACE] [upnp.transport.spi.DatagramProcessor] - Writing message data for: (OutgoingSearchRequest) M-SEARCH
2023-02-27 14:07:23.338 [TRACE] [upnp.transport.spi.DatagramProcessor] - ---------------------------------------------------------------------------------

And sometimes it is starting multicast listener, but also on all interfaces not only the selected one. But why stopping them all again after starting?

2023-02-27 14:14:03.390 [TRACE] [org.jupnp.registry.Registry         ] - Maintaining registry...
2023-02-27 14:14:03.391 [TRACE] [org.jupnp.registry.Registry         ] - Executing pending operations: 0
2023-02-27 14:14:03.391 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.22.0.1
2023-02-27 14:14:03.391 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.25.0.1
2023-02-27 14:14:03.392 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.24.0.1
2023-02-27 14:14:03.392 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.27.0.1
2023-02-27 14:14:03.392 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.26.0.1
2023-02-27 14:14:03.392 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /192.168.2.244
2023-02-27 14:14:03.392 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.31.0.1
2023-02-27 14:14:03.393 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-b3d1fee00881
2023-02-27 14:14:03.462 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.463 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-d125af02b9b4
2023-02-27 14:14:03.533 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.535 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-eb09dae5f21e
2023-02-27 14:14:03.542 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.543 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-77b0d455dbc2
2023-02-27 14:14:03.544 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.544 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-5dbd2b0f47cf
2023-02-27 14:14:03.545 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.545 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-32b28ae41ba6
2023-02-27 14:14:03.546 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.548 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-c1e8628f5e78
2023-02-27 14:14:03.550 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.553 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-ba49e533177b
2023-02-27 14:14:03.553 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.555 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-37b7e1374480
2023-02-27 14:14:03.556 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.557 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-ad8705eb98cb
2023-02-27 14:14:03.557 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.558 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-4c02ad546123
2023-02-27 14:14:03.609 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.630 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-c6afe6811015
2023-02-27 14:14:03.631 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.632 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-f89f1a0e504d
2023-02-27 14:14:03.633 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.633 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-c8c8be0340ae
2023-02-27 14:14:03.634 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.749 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-2db6488b5fc1
2023-02-27 14:14:03.750 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.750 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: eth0
2023-02-27 14:14:03.751 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.752 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-46ec93053821
2023-02-27 14:14:03.752 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.752 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: br-72ac99832aa5
2023-02-27 14:14:03.753 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-02-27 14:14:03.753 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.128.1
2023-02-27 14:14:03.773 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.96.1
2023-02-27 14:14:03.774 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.80.1
2023-02-27 14:14:03.775 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.16.1
2023-02-27 14:14:03.775 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.32.1
2023-02-27 14:14:03.776 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.16.254.1
2023-02-27 14:14:03.776 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.19.0.1
2023-02-27 14:14:03.776 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.18.0.1
2023-02-27 14:14:03.776 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.21.0.1
2023-02-27 14:14:03.777 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.20.0.1
2023-02-27 14:14:03.815 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.23.0.1
2023-02-27 14:14:03.815 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.22.0.1
2023-02-27 14:14:03.828 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.25.0.1
2023-02-27 14:14:03.829 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.24.0.1
2023-02-27 14:14:04.055 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.27.0.1

From my opinion it is plausible that it cannot get multicast infos when receivers are stopped. But why its stopping them? why its ignoring my config only to use the main eth0 with ip 192.168.2.244?

system · April 10, 2023, 4:49am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.