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

[WIP][io.upnp] Sends periodic M-Search for devices #4527

Open
wants to merge 1 commit into
base: 4.3.x
Choose a base branch
from

Conversation

digitaldan
Copy link
Contributor

See openhab/openhab-addons#17976

@mherwege This works nicely for my WiiM, and i think my Sonos connect devices also register now more quickly (maybe, maybe not, will test some more, they seem particularly temperamental these days).

This code is called when a participant is first registered, which makes sense, but then is polled when addStatusListener is called. That seemed a little strange to me, but i struggled a bit on where to put this logic short of creating another runnable.

I'm guessing that there are 2 levels of keep alive going here? The existing one which tests if a device is responding to UPNP requests, and then this new code which keeps the underlying org.jupnp registry up to date, which the existing keep alive does not seem to affect ?

Any thoughts on this approach or an alternative way to periodically send?

@digitaldan digitaldan requested a review from a team as a code owner December 29, 2024 19:17
@digitaldan digitaldan requested a review from mherwege December 29, 2024 19:17
@mherwege
Copy link
Contributor

I'm guessing that there are 2 levels of keep alive going here? The existing one which tests if a device is responding to UPNP requests, and then this new code which keeps the underlying org.jupnp registry up to date, which the existing keep alive does not seem to affect ?

That is also my interpretation. The underlying device discovery and availability is managed in the jupnp library, and to my understanding, relies on NOTIFY alive messages from the device. For some reason, your devices stop sending these alive messages. An M-SEARCH unicast request forces the device to send the info again, and it may be enough to get it to send alive messages again for a while (I don’t know). Note the jupnp library would send an M-SEARCH multicast when starting to get a response from all devices in the network. And a device added to the network should always send a NOTIFY alive to be picked up by a control point. See https://openconnectivity.org/upnp-specs/UPnP-arch-DeviceArchitecture-v2.0-20200417.pdf and https://upnp.org/resources/documents/UPnP_UDA_tutorial_July2014.pdf.
The existing one indeed works on the highest level and does not do anything to resolve underlying issues.

If this code solves the issue, this is a good solution for me. The one question I have left is if the M-SEARCH being sent is a unicast, not a multicast. The uPnP standard only allows multicast M-SEARCH from control points at startup, only unicast afterwards. I don’t know the methods called well enough to judge.

@andrewfg
Copy link
Contributor

uPnP standard only allows multicast M-SEARCH from control points at startup, only unicast afterwards

Two things..

  1. I don't think that there is such a thing as M-SEARCH unicast. The syntax is M-SEARCH * HTTP/1.1 on the multicast ip/port where the 'M' means multicast and the '*' also means the same.

  2. In my experience there is no harm for the control point to do an occasional M-SEARCH from time to time. (Notwithstanding that the spec says it should only be done on CP startup). Indeed I think that later versions of the UPnP spec did allow or even encourage occasional M-SEARCH repeats.

@mherwege
Copy link
Contributor

mherwege commented Dec 30, 2024

@andrewfg You have more experience with this than I have. My statement comes from the specification document linked above, bottom of page 19, where it explicitly makes the statements I made above. Every device should listen to search messages on its own port 1900 an directly directed to it using unicast. Sending repeated multicast searches are explicitly disallowed.
If your experience is the multicast does not harm, I am fine with it.

@andrewfg
Copy link
Contributor

@mherwege your document relates to UPnP v2.0 which (different than v1.x) does indeed allow for M-SEARCH unicasts. So I stand corrected. However it is perhaps a slightly moot point since (analogous to the degree of take up of ipV6 vs ipV4) there are are many manufacturers who stayed with UPnP v1.x rather than migrating to 2.0. So in reality the CP (OH) probably has to do it both ways (at least until it has determined whether a specific device is on 1.x or on 2.0..

@mherwege
Copy link
Contributor

mherwege commented Dec 30, 2024

@andrewfg Version 1.1 also talks about unicast (https://openconnectivity.org/upnp-specs/UPnP-arch-DeviceArchitecture-v1.1.pdf), but anyway, if this solves the issue, I am fine with it.

Copy link
Contributor

@mherwege mherwege left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@jlaur
Copy link
Contributor

jlaur commented Dec 30, 2024

2. Indeed I think that later versions of the UPnP spec did allow or even encourage occasional M-SEARCH repeats.

Would it make sense to let JUPnP do this, i.e. move the fix upstream?

@andrewfg
Copy link
Contributor

@jlaur I seem to recall that I already did something similar .. perhaps in the upnp addon suggestion finder. I will have a look..

@andrewfg
Copy link
Contributor

andrewfg commented Dec 30, 2024

It may be related to #3933 (replicated in #3918) .. but I need to check deeper.


EDIT: yeah it is a similar issue; standard M-SEARCH uses a search target of ssdp:all (which is the specification) .. but in #3933 / #3918 it was necessary to extend that to a search target of root devices in general (since some devices are not specification compliant); and here it seems that @digitaldan needs to extend it to a search target of specific UDN (for other non compliant devices). => It might make sense to harmonise the approach between these three PRs. But I don't have a lot of time over new year as we have guests staying with us.


EDIT2: .. so right now I am trying to figure out what is the relationship (if any) between UPnpIOServiceImpl and JUpnp .. and if there is already too much duplication between the two in general??


EDIT3: @digitaldan I do wonder if you need to M-SEARCH for each specific UDN? If there are many then there may be many such searches. Perhaps my solution to search for root devices in general may be sufficient? Out of interest did you test that? It might reduce the traffic a bit..

@digitaldan
Copy link
Contributor Author

so right now I am trying to figure out what is the relationship (if any) between UPnpIOServiceImpl and JUpnp .. and if there is already too much duplication between to two in general??

If you mean UpnpService and UPnpIOServiceImpl , i was at least wondering if the latter could expose the underlying upnpService it's activated with so addons would only need to reference one openHAB provided upnp service, instead of 2

@andrewfg
Copy link
Contributor

And also -- before merging this one -- we definitely need to do regression testing to ensure that this PR does not break the upnp addon suggestion finder service and/or the upnp thing discovery service.

@digitaldan
Copy link
Contributor Author

digitaldan commented Dec 30, 2024

Perhaps my solution to search for root devices in general may be sufficient? Out of interest did you test that? It might reduce the traffic a bit..

I did not test that, but i seem to remember someone saying when they scanned for new UPNP devices, it triggered the WiiMs to go online, so its possible that would work well. I'll test that today if i can to verify. If that does work, should we have the UPnpIOServiceImpl just do that at some fixed regular interval ? I don't think it would hurt anything, and if anything might trigger the discovery of new devices faster ?

but, I guess this would be duplicating startScan here ?

protected void startScan() {
for (RemoteDevice device : upnpService.getRegistry().getRemoteDevices()) {
remoteDeviceAdded(upnpService.getRegistry(), device);
}
upnpService.getRegistry().addListener(this);
upnpService.getControlPoint().search();
upnpService.getControlPoint().search(new RootDeviceHeader());
}

Not sure if we would want to coordinate these two, or keep them separate?

EDIT: it looks like UpnpAddonFinder.java also duplicates this.

@digitaldan
Copy link
Contributor Author

So i have been running a root search every min for the last hour and my WiiM is still online and registered (and i can see it responding). So i think this solution works. I'm kinda partial to just creating its own job in UPnpIOServiceImpl that runs this every minute and not try and create a dependency between the other two classes that also search? I let this run overnight to make sure there are no issues ( or leaks).

protected void sendSearchRequest() {
        upnpService.getControlPoint().search(); 
        upnpService.getControlPoint().search(new RootDeviceHeader()); 
    }

An alternative is to have all core code reference UPnpIOServiceImpl, and make ☝️ this a public method that others could call if they needed to trigger search right away. UPnpIOServiceImpl could then expose the underlying UpnpService service for existing functionality, but this would require some refactoring of classes and test cases.

@andrewfg
Copy link
Contributor

andrewfg commented Dec 31, 2024

I am tending to go for an aligned approach between all applications. But I need to get my head around the class architecture. I will get back to you.

I'm thinking that we should not be putting hidden implicit functionality in the "Impl" implementation class; but rather expose it as explicit functionality in the interface class that it implements. So I am wondering why your binding code is calling the Impl class directly..

@mherwege
Copy link
Contributor

I am tending to go for an aligned approach between all applications. But I need to get my head around the class architecture. I will get back to you.

I am with you on this and I fully agree. It may make it harder to provide an easy fix on the 4.3 code though. While working on this more structural fix, should we make a temporary fix in the upnpcontrol binding as originally proposed anyway? This can then be removed after a 5.0 release.

So I am wondering why your binding code is calling the Impl class directly..

I don’t think it does, but it is the only implementation, part of the OSGI bundle. You get the implementation with the interface in the bundle.

@andrewfg
Copy link
Contributor

I am working on this.. I will keep you posted.

@andrewfg
Copy link
Contributor

andrewfg commented Dec 31, 2024

@digitaldan can you please help me to understand exactly what problem we are trying to fix here? I understand that your issue concerns devices that "disappear" from the OH upnp device registry. But there are several ways that such disappearance could occur as follows.

  1. Fails to respond to initial (and indeed single) M-SEARCH ssdp:all request.
  2. But maybe does respond to a (single) M-SEARCH ssdp:root-device request?
  3. Fails to send periodic SSDP NOTIFY ALIVE notifications.
  4. Sends periodic SSDP NOTIFY ALIVE notifications -- but too late.
  5. Sends malformed notification messages.
  6. Sends SSDP NOTIFY BYE-BYE notifications.
  7. Or some other issue yet to be determined..

It seems that the current proposed 'solution' (aka work around) is to periodically "prod the device with a stick" by means of a periodic M-SEARCH (either for root devices in general, or for a specific UDN in particular). However this is at best a kludge, and there may be better solutions depending on what is the cause 1. thru 7. above. For example if it is issue 4. we could apply a (configurable) leniency period. Or if 5. we should patch Jupnp. Or if 3. then apply a one-time "prod" plus leniency period when the device expires. Plus many more possible solution ideas.

So to help us move forward, can you please do a (e.g. Wireshark) trace of the Upnp UDP traffic for the device which currently fails. Please do the trace with the release versions of the OH binding and OH core i.e. without any "prod" traffic.


EDIT: and in the meantime, I would suggest that you (temporarily) move on with the fix that you had originally planned in the binding without dependency on any eventual fix in OH core. (If we do eventually add a fix at OH core level, we can eventually revert the binding fix in OH 5.0)

@digitaldan
Copy link
Contributor Author

Fails to send periodic SSDP NOTIFY ALIVE notifications.

This is the issue. If i revert all changes and go back to the stock 4.3.x code, run wireshark and filter on the device's mac address, the device is quiet and does not send any messages when idle. With the proposed changes only then does it send messages (as replies to search requests), which i am also observing in wireshark.

I would suggest that you (temporarily) move on with the fix

Sure, sound good.

@andrewfg
Copy link
Contributor

andrewfg commented Dec 31, 2024

run wireshark and filter on the device's mac address, the device is quiet and does not send any messages when idle

In your original issue someone posted the following log. This means the device had been in the registry, and was removed. So there must have been some upnp traffic between OH and the device in order for it to have got in the registry. I would like to see that traffic.

2024-07-29 09:22:07.772 [TRACE] [org.jupnp.registry.Registry         ] - Device '(RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:FF31F09E-DDF8-82A3-EB48-917FFF31F09E, Descriptor: http://172.16.1.192:49152/description.xml, Root: true'
 expires in seconds: -1

PS it is worth being aware that not receiving a NOTIFY ALIVE is not synonymous with one not having been sent. So I do wonder if perhaps the notifications may be being lost due to a routing issue on your LAN. It would help if we are sure that Wireshark is connected to the exact same physical LAN segment that the device is physically connected to. Some routers and Wifi APs do sometimes do silly things with UDP multicasts (and less silly things with UDP unicasts, which might explain why the unicast response to M-SEARCH is always received; or something like that).


PPS does the device show up in the DeviceSpy application?

@digitaldan
Copy link
Contributor Author

This means the device had been in the registry

I assume this is b/c openHAB was restarted (and it sends something when it first comes online) , or the user did a scan for new UPNP devices, and this device answered.

I can capture one or both of those events if you wish?

@andrewfg
Copy link
Contributor

I can capture one or both of those events if you wish?

Ideally both please. :)

@digitaldan
Copy link
Contributor Author

So I do wonder if perhaps the notifications may be being lost due to a routing issue on your LAN

Maybe? but i don't think so, others have this same issue with this device, so i think its specific to this manufacturer implementation of UPNP. I have run a Unifi based network for over a decade , and not had any issues.

@andrewfg
Copy link
Contributor

See what you find with this tool..

Device Sniffer.zip

@digitaldan
Copy link
Contributor Author

I don't have a windows machine, do you have a mac or linux build of that ?

@andrewfg
Copy link
Contributor

^
Nope.

@mherwege
Copy link
Contributor

3. Fails to send periodic SSDP NOTIFY ALIVE notifications.

@andrewfg Thank you for this very good analysis.

Could IPv4 and IPv6 play a role in this? I assume the device could be discovered on both. But does it also send the ALIVE over both interfaces? And does uPnP listen for ALIVE messages from a specific source address? This may not have anything to do with this, but I got triggered by the discussion in this issue: jupnp/jupnp#73

@digitaldan
Copy link
Contributor Author

Could IPv4 and IPv6 play a role in this?

fwiw, the WiiM does have a link local ipv6 address (fe80:) and i see mdns traffic on that as well as its iPV4 address.

@andrewfg
Copy link
Contributor

@mherwege I will look into the ipv4/6 and network interface issue; if there are 2 interfaces both with ipv4 and 6 then there could indeed be 4 potential input channels for search responses. I am not sure how jupnp resp. OH handles this.

FWIW a control point multicast M-SEARCH elicits NOTIFY unicast responses from the device to the control point; and a device on its own sends (slightly different format) multicast NOTIFY messages every 2/3 (approx) of its declared max-age lifetime.

@andrewfg
Copy link
Contributor

@digitaldan if your Wireshark captures both ipv6 and ipv4 traffic, we might see if there is anything odd going on.

@digitaldan
Copy link
Contributor Author

digitaldan commented Dec 31, 2024

I have not run all the tests, but this was one was the easiest to capture so i'll post what i have, when i scan for new UPNP devices (from the Main UI), the WiiM responds with 2 replies from the IPV4 and IPV6 addresses.

32602	11.818551	192.168.91.219	224.0.0.251	5353	MDNS	484	Standard query response 0x0000 PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local TXT, cache flush SRV, cache flush 0 0 7000 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:43b:ab26:7005:db24 AAAA, cache flush 2600:8801:df00:160:6d0c:8b4:ea60:345 AAAA, cache flush fe80::c739:8aac:fb3e:3f0f NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM-Pro-1.local
32604	11.819598	fe80::c739:8aac:fb3e:3f0f	ff02::fb	5353	MDNS	504	Standard query response 0x0000 PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local TXT, cache flush SRV, cache flush 0 0 7000 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:43b:ab26:7005:db24 AAAA, cache flush 2600:8801:df00:160:6d0c:8b4:ea60:345 AAAA, cache flush fe80::c739:8aac:fb3e:3f0f NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM-Pro-1.local

I ran this a couple times, each time is the same, responds with both ipv4 and ipv6. It also looks like there are devices on my network who are constantly (at least every minute) sending discovery requests for airplay and spotify services, which this device also responds to, but so far i have not seen the WiiM send anything but responses to queries. Next i'll try rebooting it and see if it announces something.

Also this was running TCPDump directly on my openHAB host.

EDIT: also this does trigger the WIiM to go ONLINE for some amount of time (maybe 30 mins?)

@digitaldan
Copy link
Contributor Author

digitaldan commented Dec 31, 2024

Here are packets when the device reboots, and the device does come ONLINE in openHAB.

I'm realize i know very little about the inner workings MDNS and UPNP. I assumed when wireshark says "standard query response" it indicates its responding to a request, but i get a feeling that a unsolicited response message is used as a notification mechanism ? So really its not always a response to something?

No.	Time	Source	Destination	Dest port	Protocol	Length	Info
117	63.432895	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	100	Standard query 0x0000 PTR _linkplay._tcp.local, "QU" question
118	63.433085	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	194	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 8.D.A.8.6.E.E.F.F.F.9.C.8.7.6.5.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
120	63.579631	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	100	Standard query 0x0000 PTR _linkplay._tcp.local, "QU" question
121	63.579787	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	194	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 8.D.A.8.6.E.E.F.F.F.9.C.8.7.6.5.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
122	63.884083	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	278	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QU" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QU" question ANY WiiM Pro-1._linkplay._tcp.local, "QU" question ANY WiiM-Pro-1.local, "QU" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local AAAA fe80::5678:c9ff:fee6:8ad8
126	64.165481	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	278	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QM" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QM" question ANY WiiM Pro-1._linkplay._tcp.local, "QM" question ANY WiiM-Pro-1.local, "QM" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local AAAA fe80::5678:c9ff:fee6:8ad8
127	64.521026	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	278	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QM" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QM" question ANY WiiM Pro-1._linkplay._tcp.local, "QM" question ANY WiiM-Pro-1.local, "QM" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local AAAA fe80::5678:c9ff:fee6:8ad8
128	64.624767	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	100	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question
129	64.624962	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	194	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 8.D.A.8.6.E.E.F.F.F.9.C.8.7.6.5.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
130	64.774431	fe80::5678:c9ff:fee6:8ad8	ff02::fb	5353	MDNS	1177	Standard query response 0x0000 TXT, cache flush PTR _airplay._tcp.local PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush PTR _raop._tcp.local PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local AAAA, cache flush fe80::5678:c9ff:fee6:8ad8 NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local NSEC, cache flush WiiM-Pro-1.local

and

No.	Time	Source	Destination	Dest port	Protocol	Length	Info
146	66.966334	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	100	Standard query 0x0000 PTR _linkplay._tcp.local, "QU" question
149	66.967987	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	409	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 219.91.168.192.in-addr.arpa NSEC, cache flush 6.2.7.4.C.5.A.B.5.6.9.F.7.C.C.8.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush D.1.8.2.C.6.1.F.F.B.7.0.2.6.0.6.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush C.5.B.2.F.0.4.A.8.2.C.A.3.9.F.7.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
151	67.334455	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	350	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QU" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QU" question ANY WiiM Pro-1._linkplay._tcp.local, "QU" question ANY WiiM-Pro-1.local, "QU" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local A 192.168.91.219 AAAA 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA 2600:8801:df00:160:6062:7bf:f16c:281d AAAA fe80::7f93:ac28:a40f:2b5c
154	67.576370	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	350	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QM" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QM" question ANY WiiM Pro-1._linkplay._tcp.local, "QM" question ANY WiiM-Pro-1.local, "QM" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local A 192.168.91.219 AAAA 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA 2600:8801:df00:160:6062:7bf:f16c:281d AAAA fe80::7f93:ac28:a40f:2b5c
156	67.865404	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	350	Standard query 0x0000 ANY WiiM Pro-1._airplay._tcp.local, "QM" question ANY 5678C9E68AD8@WiiM Pro-1._raop._tcp.local, "QM" question ANY WiiM Pro-1._linkplay._tcp.local, "QM" question ANY WiiM-Pro-1.local, "QM" question SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 7000 WiiM-Pro-1.local SRV 0 0 59152 WiiM-Pro-1.local A 192.168.91.219 AAAA 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA 2600:8801:df00:160:6062:7bf:f16c:281d AAAA fe80::7f93:ac28:a40f:2b5c
158	67.967088	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	409	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 219.91.168.192.in-addr.arpa NSEC, cache flush 6.2.7.4.C.5.A.B.5.6.9.F.7.C.C.8.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush D.1.8.2.C.6.1.F.F.B.7.0.2.6.0.6.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush C.5.B.2.F.0.4.A.8.2.C.A.3.9.F.7.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
160	68.116922	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	100	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question
162	68.171202	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	1249	Standard query response 0x0000 TXT, cache flush PTR _airplay._tcp.local PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush PTR _raop._tcp.local PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local NSEC, cache flush WiiM-Pro-1.local
166	69.169044	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	1249	Standard query response 0x0000 TXT, cache flush PTR _airplay._tcp.local PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush PTR _raop._tcp.local PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local NSEC, cache flush WiiM-Pro-1.local
168	69.881672	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	196	Standard query 0x0000 ANY Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local, "QU" question SRV 0 0 2019 WiiM-Pro-1.local
171	69.984114	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	409	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local NSEC, cache flush 219.91.168.192.in-addr.arpa NSEC, cache flush 6.2.7.4.C.5.A.B.5.6.9.F.7.C.C.8.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush D.1.8.2.C.6.1.F.F.B.7.0.2.6.0.6.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa NSEC, cache flush C.5.B.2.F.0.4.A.8.2.C.A.3.9.F.7.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
173	70.132751	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	196	Standard query 0x0000 ANY Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local, "QM" question SRV 0 0 2019 WiiM-Pro-1.local
176	70.298999	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	504	Standard query response 0x0000 PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local TXT, cache flush SRV, cache flush 0 0 7000 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM-Pro-1.local
179	70.399614	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	196	Standard query 0x0000 ANY Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local, "QM" question SRV 0 0 2019 WiiM-Pro-1.local
181	70.653680	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	365	Standard query response 0x0000 TXT, cache flush PTR _tidalconnect._tcp.local PTR Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local SRV, cache flush 0 0 2019 WiiM-Pro-1.local NSEC, cache flush Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local
189	71.099671	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	125	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question PTR WiiM Pro-1._linkplay._tcp.local
191	71.231420	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	1496	Standard query response 0x0000 TXT, cache flush PTR _airplay._tcp.local PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush PTR _raop._tcp.local PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c TXT, cache flush PTR _tidalconnect._tcp.local PTR Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local SRV, cache flush 0 0 2019 WiiM-Pro-1.local NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local
198	71.540632	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	194	Standard query response 0x0000 PTR, cache flush WiiM-Pro-1.local NSEC, cache flush C.5.B.2.F.0.4.A.8.2.C.A.3.9.F.7.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa
206	73.230444	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	485	Standard query response 0x0000 TXT, cache flush PTR _tidalconnect._tcp.local PTR Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local SRV, cache flush 0 0 2019 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local
212	73.994893	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	1512	Standard query response 0x0000 TXT, cache flush PTR _airplay._tcp.local PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush PTR _raop._tcp.local PTR 5678C9E68AD8@WiiM Pro-1._raop._tcp.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local SRV, cache flush 0 0 7000 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local PTR, cache flush WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush 5678C9E68AD8@WiiM Pro-1._raop._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local NSEC, cache flush 219.91.168.192.in-addr.arpa NSEC, cache flush 6.2.7.4.C.5.A.B.5.6.9.F.7.C.C.8.0.6.1.0.0.0.F.D.1.0.8.8.0.0.6.2.ip6.arpa
223	77.231650	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	365	Standard query response 0x0000 TXT, cache flush PTR _tidalconnect._tcp.local PTR Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local SRV, cache flush 0 0 2019 WiiM-Pro-1.local NSEC, cache flush Tidal Connect Test Platform-af3d7c5e5575a546ea5b843e238a8ca3._tidalconnect._tcp.local
229	80.131150	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	150	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question PTR WiiM Pro-1._linkplay._tcp.local PTR WiiM Pro 2._linkplay._tcp.local
249	90.370355	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	119	Standard query response 0x0000 PTR WiiM Pro-1._linkplay._tcp.local
251	90.470336	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	163	Standard query 0x0000 ANY FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local, "QU" question SRV 0 0 5356 WiiM-Pro-1.local
253	90.720776	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	163	Standard query 0x0000 ANY FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local, "QM" question SRV 0 0 5356 WiiM-Pro-1.local
256	90.970277	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	163	Standard query 0x0000 ANY FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local, "QM" question SRV 0 0 5356 WiiM-Pro-1.local
259	91.220696	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	392	Standard query response 0x0000 TXT, cache flush PTR _spotify-connect._tcp.local PTR FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local SRV, cache flush 0 0 5356 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local
261	91.404607	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	125	Standard query 0x0000 PTR _linkplay._tcp.local, "QU" question PTR WiiM Pro 2._linkplay._tcp.local
262	91.506990	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	142	Standard query 0x0000 ANY WiiM Pro-1._linkplay._tcp.local, "QU" question SRV 0 0 59152 WiiM-Pro-1.local
266	91.840719	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	142	Standard query 0x0000 ANY WiiM Pro-1._linkplay._tcp.local, "QM" question SRV 0 0 59152 WiiM-Pro-1.local
268	92.134010	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	142	Standard query 0x0000 ANY WiiM Pro-1._linkplay._tcp.local, "QM" question SRV 0 0 59152 WiiM-Pro-1.local
269	92.232273	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	416	Standard query response 0x0000 TXT, cache flush PTR _spotify-connect._tcp.local PTR FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local SRV, cache flush 0 0 5356 WiiM-Pro-1.local PTR _linkplay._tcp.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local
271	92.535463	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	125	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question PTR WiiM Pro 2._linkplay._tcp.local
272	92.535728	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	326	Standard query response 0x0000 TXT, cache flush PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local
277	93.233246	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	483	Standard query response 0x0000 TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local
281	94.274756	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	637	Standard query response 0x0000 TXT, cache flush PTR _spotify-connect._tcp.local PTR FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local SRV, cache flush 0 0 5356 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM-Pro-1.local NSEC, cache flush FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local
285	95.542948	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	150	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question PTR WiiM Pro 2._linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local
289	98.020878	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	664	Standard query response 0x0000 PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush SRV, cache flush 0 0 7000 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush WiiM-Pro-1.local
292	98.277648	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	517	Standard query response 0x0000 TXT, cache flush PTR _spotify-connect._tcp.local PTR FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local SRV, cache flush 0 0 5356 WiiM-Pro-1.local TXT, cache flush PTR _linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local SRV, cache flush 0 0 59152 WiiM-Pro-1.local NSEC, cache flush FF98F09CC0D7589BC27CCE6F._spotify-connect._tcp.local NSEC, cache flush WiiM Pro-1._linkplay._tcp.local
449	101.680942	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	664	Standard query response 0x0000 PTR WiiM Pro-1._airplay._tcp.local TXT, cache flush SRV, cache flush 0 0 7000 WiiM-Pro-1.local A, cache flush 192.168.91.219 AAAA, cache flush 2600:8801:df00:160:8cc7:f965:ba5c:4726 AAAA, cache flush 2600:8801:df00:160:6062:7bf:f16c:281d AAAA, cache flush fe80::7f93:ac28:a40f:2b5c NSEC, cache flush WiiM Pro-1._airplay._tcp.local NSEC, cache flush WiiM-Pro-1.local
454	104.561545	fe80::7f93:ac28:a40f:2b5c	ff02::fb	5353	MDNS	150	Standard query 0x0000 PTR _linkplay._tcp.local, "QM" question PTR WiiM Pro 2._linkplay._tcp.local PTR WiiM Pro-1._linkplay._tcp.local

@andrewfg
Copy link
Contributor

andrewfg commented Jan 1, 2025

@digitaldan many thanks for running the trace. However unfortunately I don’t see any UPNP traffic in it. (So there is no evidence why the device came online). I would like to see the (apparently one single) udp NOTIFY packet from the device that made it originally come on line. There must have been one such packet to have caused the device to be added to the registry.

@andrewfg
Copy link
Contributor

andrewfg commented Jan 1, 2025

@digitaldan rather than using Wireshark, it may be easier to turn on log:set TRACE org.jupnp.transport then restart OH and send me the log files. You should see the following messages..

M-SEARCH ssdp:all and typical response

2025-01-01 12:55:55.559 [TRACE] [upnp.transport.spi.DatagramProcessor] - M-SEARCH * HTTP/1.1
ST: ssdp:all
HOST: 239.255.255.250:1900
MX: 3
MAN: "ssdp:discover"

2025-01-01 12:55:55.560 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
Cache-Control: max-age=1800
Location: http://192.168.1.51:49000/fboxdesc.xml
Server: FRITZ!Box 7530 AX UPnP/1.0 AVM FRITZ!Box 7530 AX 256.08.00
Ext: 
ST: upnp:rootdevice
USN: uuid:123402409-bccb-40e7-8e6c-D424DDC82342::upnp:rootdevice

M-SEARCH upnp:rootdevice and typical response

2025-01-01 12:55:55.554 [TRACE] [upnp.transport.spi.DatagramProcessor] - M-SEARCH * HTTP/1.1
ST: upnp:rootdevice
HOST: 239.255.255.250:1900
MX: 3
MAN: "ssdp:discover"

2025-01-01 12:55:55.556 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
Cache-Control: max-age=1800
Location: http://192.168.1.51:49000/MediaServerDevDesc.xml
Server: FRITZ!Box 7530 AX UPnP/1.0 AVM FRITZ!Box 7530 AX 256.08.00
Ext: 
ST: upnp:rootdevice
USN: uuid:fa095ecc-e13e-40e7-8e6c-D424DDC82342::upnp:rootdevice

Spontaneous NOTIFY ssdp:alive message

2025-01-01 12:56:19.018 [TRACE] [upnp.transport.spi.DatagramProcessor] - NOTIFY * HTTP/1.1
SERVER: Linux, UPnP/1.0 DLNADOC/1.50, JRiver/26, JRiver_Internet_Reader/2.0 (compatible; Windows-Media-Player/10)
HOST: 239.255.255.250:1900
CACHE-CONTROL: max-age=1800
NT: upnp:rootdevice
LOCATION: http://192.168.1.122:52100/DeviceDescription.xml
NTS: ssdp:alive
USN: uuid:6b8a7ddd-a252-f840-a14f-be82cbbe39e0::upnp:rootdevice

@digitaldan
Copy link
Contributor Author

Thanks @andrewfg , for some reason i can't capture UDP 1900 with TCPDump, not sure if jupnp is binding to the interface in a way that prevents it from seeing packets.

So i rebooted the device a few times, and jupnp does not see any messages at all from the device. The device remains OFFLINE in openHAB.

If i then perform a scan in the Main UI, the device does respond, and comes back online

2025-01-01 08:25:30.617 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.617 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-upnp-org:service:AVTransport:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-upnp-org:service:AVTransport:1


2025-01-01 08:25:30.617 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.617 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.617 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.243:54015 on: /192.168.91.10:0
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.Router          ] - Trying to obtain lock with timeout milliseconds '6000': ReadLock
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.Router          ] - Acquired router lock: ReadLock
2025-01-01 08:25:30.618 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (StreamRequestMessage) GET http://192.168.91.219:49152/description.xml
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.spi.StreamClient] - Preparing HTTP request: (StreamRequestMessage) GET http://192.168.91.219:49152/description.xml
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.spi.StreamClient] - Creating HTTP request. URI: 'http://192.168.91.219:49152/description.xml' method: 'GET'
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.spi.StreamClient] - Waiting 10 seconds for HTTP request to complete: (StreamRequestMessage) GET http://192.168.91.219:49152/description.xml
2025-01-01 08:25:30.618 [TRACE] [org.jupnp.transport.spi.StreamClient] - Sending HTTP request: (StreamRequestMessage) GET http://192.168.91.219:49152/description.xml
2025-01-01 08:25:30.618 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.619 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.243:49152/description.xml
BOOTID.UPNP.ORG: 02273ae0-1dd2-11b2-93ce-9fe571eda67f
SERVER: Linux/4.9.113
ST: upnp:rootdevice
USN: uuid:FF98F09C-D303-BC8E-6E84-354CFF98F09C::upnp:rootdevice


2025-01-01 08:25:30.619 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.619 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.619 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:44419 on: /192.168.91.10:0
2025-01-01 08:25:30.619 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.620 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: upnp:rootdevice
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::upnp:rootdevice


2025-01-01 08:25:30.620 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.620 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.620 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:44419 on: /192.168.91.10:0
2025-01-01 08:25:30.620 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.620 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C


2025-01-01 08:25:30.620 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.621 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.621 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:44419 on: /192.168.91.10:0
2025-01-01 08:25:30.621 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.621 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-upnp-org:device:MediaRenderer:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-upnp-org:device:MediaRenderer:1


2025-01-01 08:25:30.621 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.621 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.622 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:57066 on: /192.168.91.10:0
2025-01-01 08:25:30.622 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.622 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-upnp-org:service:ConnectionManager:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-upnp-org:service:ConnectionManager:1


2025-01-01 08:25:30.622 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.622 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.622 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:57732 on: /192.168.91.10:0
2025-01-01 08:25:30.623 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.623 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-wiimu-com:service:PlayQueue:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-wiimu-com:service:PlayQueue:1


2025-01-01 08:25:30.623 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.623 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.623 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:57451 on: /192.168.91.10:0
2025-01-01 08:25:30.624 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.624 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-tencent-com:service:QPlay:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-tencent-com:service:QPlay:1


2025-01-01 08:25:30.624 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.625 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.625 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:44438 on: /192.168.91.10:0
2025-01-01 08:25:30.625 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.625 [TRACE] [org.jupnp.transport.spi.StreamClient] - Received HTTP response: OK
2025-01-01 08:25:30.626 [TRACE] [org.jupnp.transport.spi.StreamClient] - HTTP response message contains text entity
2025-01-01 08:25:30.626 [TRACE] [org.jupnp.transport.spi.StreamClient] - Got HTTP response in 7 ms: (StreamRequestMessage) GET http://192.168.91.219:49152/description.xml
2025-01-01 08:25:30.626 [TRACE] [org.jupnp.transport.Router          ] - Releasing router lock: ReadLock
2025-01-01 08:25:30.627 [TRACE] [org.jupnp.transport.Router          ] - Trying to obtain lock with timeout milliseconds '6000': ReadLock
2025-01-01 08:25:30.627 [TRACE] [org.jupnp.transport.Router          ] - Acquired router lock: ReadLock
2025-01-01 08:25:30.627 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (StreamRequestMessage) GET http://192.168.91.219:49152/upnp/rendertransportSCPD.xml
2025-01-01 08:25:30.627 [TRACE] [org.jupnp.transport.spi.StreamClient] - Preparing HTTP request: (StreamRequestMessage) GET http://192.168.91.219:49152/upnp/rendertransportSCPD.xml
2025-01-01 08:25:30.627 [TRACE] [org.jupnp.transport.spi.StreamClient] - Creating HTTP request. URI: 'http://192.168.91.219:49152/upnp/rendertransportSCPD.xml' method: 'GET'
2025-01-01 08:25:30.628 [TRACE] [org.jupnp.transport.spi.StreamClient] - Waiting 10 seconds for HTTP request to complete: (StreamRequestMessage) GET http://192.168.91.219:49152/upnp/rendertransportSCPD.xml
2025-01-01 08:25:30.628 [TRACE] [org.jupnp.transport.spi.StreamClient] - Sending HTTP request: (StreamRequestMessage) GET http://192.168.91.219:49152/upnp/rendertransportSCPD.xml
2025-01-01 08:25:30.628 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: urn:schemas-upnp-org:service:RenderingControl:1
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::urn:schemas-upnp-org:service:RenderingControl:1


2025-01-01 08:25:30.628 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================
2025-01-01 08:25:30.628 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) 200 OK
2025-01-01 08:25:30.628 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - UDP datagram received from: 192.168.91.219:49652 on: /192.168.91.10:0
2025-01-01 08:25:30.629 [TRACE] [upnp.transport.spi.DatagramProcessor] - ===================================== DATAGRAM BEGIN ============================================
2025-01-01 08:25:30.629 [TRACE] [upnp.transport.spi.DatagramProcessor] - HTTP/1.1 200 OK
CONNECTION: keep-alive
CACHE-CONTROL: max-age=1800
DATE: Wed, 01 Jan 2025 16:25:30 GMT
EXT:
LOCATION: http://192.168.91.219:49152/description.xml
BOOTID.UPNP.ORG: 7de82dce-1dd2-11b2-bde1-bf8eb1c95fb5
SERVER: Linux/4.9.113
ST: upnp:rootdevice
USN: uuid:FF98F09C-C0D7-589B-C27C-CE6FFF98F09C::upnp:rootdevice


2025-01-01 08:25:30.629 [TRACE] [upnp.transport.spi.DatagramProcessor] - -===================================== DATAGRAM END =============================================

@andrewfg
Copy link
Contributor

andrewfg commented Jan 2, 2025

@digitaldan many thanks for the logs. The device seems quite normal in response to M-SEARCH responses.

for some reason i can't capture UDP 1900 with TCPDump

Yeah. So my suspicion therefore is that the device is sending its notifications (on 1900) but that neither TCPDump nor OH are able to receive them. I honestly can't imagine a device claiming to be Upnp and not sending notifications, since that is so fundamental. (It is even a Linux based core, so should be quite professional). There are two things that could cause notifications to get lost -- namely..

  1. a routing issue e.g. a LAN with different subnets or different segments on the same subnets -- such as multiple ethernet legs on different switches, or wifi access points not forwarding multicasts.

  2. a TTL (time to live) hop count issue .. upnp sends out notifications with a maximum hop count of say 5, and every routing hop decrements that number, and if it drops to zero it won't forward the packet further.

I would love to get this device on a plain bare router and see what it is doing..

@andrewfg
Copy link
Contributor

andrewfg commented Jan 2, 2025

@digitaldan BTW I had a look over the Wiim forums to see if this issue had been reported there. And AFAICT it seems not. And it seems that other third party Upnp control points e.g. BubbleUpnp can find and operate these devices. That would indicate that your issue may indeed be related to the LAN stuff mentioned above. Or alternatively there is an issue in Jupnp.

@andrewfg
Copy link
Contributor

andrewfg commented Jan 2, 2025

@digitaldan / @mherwege you may want to take a look at #4534 -- although I am not entirely sure if we should really add it to the OC Core or not. ??

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants