search

ioBroker / ioBroker.discovery

This adapter tries to discover all known devices
MIT License
28 stars 48 forks source link

upnp method does not reliably find all ssdp servers in the network #278

Closed pdbjjens closed 1 year ago

pdbjjens commented 1 year ago

Describe the bug
I am developing a detector plugin for the frontier_silicon adapter using the upnp method of the discovery adapter https://github.com/pdbjjens/ioBroker.discovery I have forked the discovery adapter and cloned it to my dev-server running on a Windows laptop. The frontier_silicon devices can be discovered by upnp, thus I used the upnp-method of the discovery adapter to implement the plugin. The issue I have is the following: Each time I run the discovery adapter the ssdp-search finds a different number of upnp devices and most of the times the frontier_silicon devices are not among the found devices. Just once one of the frontier_silicon devices was found and the frontier_silicon adapter was correctly added to the list of suggested adapters. So I assume that the problem is not related to the frontier_silicon plugin but to the upnp device search. Btw: The ioBroker.upnp adapter running on the same ioBroker instance reliably finds all upnp devices in my network, so the reason can not be firewalls/traffic analyzers. During the tests the ioBroker.upnp adapter was not running of course.

To Reproduce
Steps to reproduce the behavior:

  1. Go to 'ioBroker webUI'
  2. Click on 'Find Devices and Services'
  3. Unselect all methods except 'upnp'
  4. Click on 'Discover'
  5. See error description above

Expected behavior
The upnp method should reliably find all ssdp servers in the network. The following log contains the discovery phase of the only successfull detection (the device to be looked for has the IP 192.168.1.163). upnp_discovery.txt

Screenshots & Logfiles
This is part of the log of an incomplete search. The whole log deals with checking the the found IP adresses against the available plugins and is too big to be posted here.

[HPM] Client disconnected [HPM] Upgrading to WebSocket 2023-07-28 11:37:53.096 - debug: host.dev-discovery-Jenss-Lifebook Incoming Host message getLogs 2023-07-28 11:38:00.081 - debug: discovery.0 (9384) Received "listMethods" event 2023-07-28 11:38:06.210 - debug: discovery.0 (9384) Received "browse" event 2023-07-28 11:38:06.696 - info: discovery.0 (9384) Discovering UPnP devices... 2023-07-28 11:38:06.701 - debug: discovery.0 (9384) Discover Test 2 2023-07-28 11:38:07.328 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.110 : {"_addr":"192.168.1.110","_name":"","_upnp":{"CACHE-CONTROL":"max-age=1900","ST":"upnp:rootdevice","USN":"uuid:73796E6F-6473-6D00-0000-00113230cc8c::upnp:rootdevice","EXT":"","SERVER":"Synology/DSM/192.168.1.110","LOCATION":"http://192.168.1.110:5000/ssdp/desc-DSM-eth0.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"1","BOOTID.UPNP.ORG":"1","CONFIGID.UPNP.ORG":"1337"}} 2023-07-28 11:38:07.347 - debug: discovery.0 (9384) main.addDevice: ip=192.168.1.110 source=upnp 2023-07-28 11:38:07.352 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.118 : {"_addr":"192.168.1.118","_name":"","_upnp":{"LOCATION":"http://192.168.1.118:49000/fboxdesc.xml","SERVER":"FRITZRepeater1750E UPnP/1.0 AVM FRITZ!WLAN Repeater 1750E 134.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"upnp:rootdevice","USN":"uuid:123402409-bccb-40e7-8e6c-3810D598A848::upnp:rootdevice"}} 2023-07-28 11:38:07.510 - debug: discovery.0 (9384) main.addDevice: ip=192.168.1.118 source=upnp 2023-07-28 11:38:07.888 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.118 : {"_addr":"192.168.1.118","_name":"","_upnp":{"LOCATION":"http://192.168.1.118:49000/fboxdesc.xml","SERVER":"FRITZRepeater1750E UPnP/1.0 AVM FRITZ!WLAN Repeater 1750E 134.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"uuid:123402409-bccb-40e7-8e6c-3810D598A848","USN":"uuid:123402409-bccb-40e7-8e6c-3810D598A848"}} 2023-07-28 11:38:08.443 - debug: discovery.0 (9384) extended Device: 192.168.1.118 source=upnp 2023-07-28 11:38:08.636 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.118 : {"_addr":"192.168.1.118","_name":"","_upnp":{"LOCATION":"http://192.168.1.118:49000/fboxdesc.xml","SERVER":"FRITZRepeater1750E UPnP/1.0 AVM FRITZ!WLAN Repeater 1750E 134.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"urn:schemas-any-com:service:fritzbox:1","USN":"uuid:123402409-bccb-40e7-8e6c-3810D598A848::urn:schemas-any-com:service:fritzbox:1"}} 2023-07-28 11:38:08.984 - debug: discovery.0 (9384) extended Device: 192.168.1.118 source=upnp 2023-07-28 11:38:09.147 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.118 : {"_addr":"192.168.1.118","_name":"","_upnp":{"LOCATION":"http://192.168.1.118:49000/fboxdesc.xml","SERVER":"FRITZRepeater1750E UPnP/1.0 AVM FRITZ!WLAN Repeater 1750E 134.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"urn:schemas-upnp-org:device:fritzbox:1","USN":"uuid:123402409-bccb-40e7-8e6c-3810D598A848::urn:schemas-upnp-org:device:fritzbox:1"}} 2023-07-28 11:38:09.497 - debug: discovery.0 (9384) extended Device: 192.168.1.118 source=upnp 2023-07-28 11:38:09.987 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/MediaServerDevDesc.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"upnp:rootdevice","USN":"uuid:fa095ecc-e13e-40e7-8e6c-3481c40866fd::upnp:rootdevice"}} 2023-07-28 11:38:10.309 - debug: discovery.0 (9384) main.addDevice: ip=192.168.1.1 source=upnp 2023-07-28 11:38:10.564 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/MediaServerDevDesc.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"uuid:fa095ecc-e13e-40e7-8e6c-3481c40866fd","USN":"uuid:fa095ecc-e13e-40e7-8e6c-3481c40866fd"}} 2023-07-28 11:38:10.595 - debug: discovery.0 (9384) extended Device: 192.168.1.1 source=upnp 2023-07-28 11:38:10.715 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/MediaServerDevDesc.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"urn:schemas-upnp-org:device:MediaServer:1","USN":"uuid:fa095ecc-e13e-40e7-8e6c-3481c40866fd::urn:schemas-upnp-org:device:MediaServer:1"}} 2023-07-28 11:38:11.624 - debug: discovery.0 (9384) extended Device: 192.168.1.1 source=upnp 2023-07-28 11:38:11.837 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49153/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"5adfecc6-3c5f-11ed-b85b-b84de7580f2d","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.22","X-USER-AGENT":"redsonic","ST":"upnp:rootdevice","USN":"uuid:48502D53-454D-502D-312D-0280-AD21C9CD::upnp:rootdevice"}} 2023-07-28 11:38:12.247 - debug: discovery.0 (9384) main.addDevice: ip=192.168.1.108 source=upnp 2023-07-28 11:38:13.047 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49153/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"5adfecc6-3c5f-11ed-b85b-b84de7580f2d","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.22","X-USER-AGENT":"redsonic","ST":"uuid:48502D53-454D-502D-312D-0280-AD21C9CD","USN":"uuid:48502D53-454D-502D-312D-0280-AD21C9CD"}} 2023-07-28 11:38:13.840 - debug: discovery.0 (9384) extended Device: 192.168.1.108 source=upnp 2023-07-28 11:38:14.085 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49153/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"5adfecc6-3c5f-11ed-b85b-b84de7580f2d","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.22","X-USER-AGENT":"redsonic","ST":"urn:schemas-simple-energy-management-protocol:device:Gateway:1","USN":"uuid:48502D53-454D-502D-312D-0280-AD21C9CD::urn:schemas-simple-energy-management-protocol:device:Gateway:1"}} 2023-07-28 11:38:14.353 - debug: discovery.0 (9384) extended Device: 192.168.1.108 source=upnp 2023-07-28 11:38:14.578 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49153/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"5adfecc6-3c5f-11ed-b85b-b84de7580f2d","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.22","X-USER-AGENT":"redsonic","ST":"urn:schemas-simple-energy-management-protocol:service:NULL:1:service:NULL:1","USN":"uuid:48502D53-454D-502D-312D-0280-AD21C9CD::urn:schemas-simple-energy-management-protocol:service:NULL:1:service:NULL:1"}} 2023-07-28 11:38:14.693 - debug: discovery.0 (9384) extended Device: 192.168.1.108 source=upnp 2023-07-28 11:38:15.375 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/aura.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"upnp:rootdevice","USN":"uuid:22617c0d-cb0f-4fb9-a31f-3481C40866FD::upnp:rootdevice"}} 2023-07-28 11:38:16.156 - debug: discovery.0 (9384) extended Device: 192.168.1.1 source=upnp 2023-07-28 11:38:16.253 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.157 : {"_addr":"192.168.1.157","_name":"","_upnp":{"CACHE-CONTROL":"max-age=1800","LOCATION":"http://192.168.1.157:49000/fboxdesc.xml","SERVER":"FRITZBox7590 UPnP/1.0 AVM FRITZ!Box 7590 154.07.56","EXT":"","ST":"uuid:123402409-bccb-40e7-8e6c-74427F1DE096","USN":"uuid:123402409-bccb-40e7-8e6c-74427F1DE096"}} 2023-07-28 11:38:16.432 - debug: discovery.0 (9384) main.addDevice: ip=192.168.1.157 source=upnp 2023-07-28 11:38:16.994 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.157 : {"_addr":"192.168.1.157","_name":"","_upnp":{"CACHE-CONTROL":"max-age=1800","LOCATION":"http://192.168.1.157:49000/fboxdesc.xml","SERVER":"FRITZBox7590 UPnP/1.0 AVM FRITZ!Box 7590 154.07.56","EXT":"","ST":"upnp:rootdevice","USN":"uuid:123402409-bccb-40e7-8e6c-74427F1DE096::upnp:rootdevice"}}
2023-07-28 11:38:17.080 - debug: discovery.0 (9384) extended Device: 192.168.1.157 source=upnp 2023-07-28 11:38:17.571 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/aura.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"uuid:22617c0d-cb0f-4fb9-a31f-3481C40866FD","USN":"uuid:22617c0d-cb0f-4fb9-a31f-3481C40866FD"}}
2023-07-28 11:38:18.167 - debug: discovery.0 (9384) extended Device: 192.168.1.1 source=upnp 2023-07-28 11:38:18.483 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.157 : {"_addr":"192.168.1.157","_name":"","_upnp":{"CACHE-CONTROL":"max-age=1800","LOCATION":"http://192.168.1.157:49000/fboxdesc.xml","SERVER":"FRITZBox7590 UPnP/1.0 AVM FRITZ!Box 7590 154.07.56","EXT":"","ST":"urn:schemas-upnp-org:device:fritzbox:1","USN":"uuid:123402409-bccb-40e7-8e6c-74427F1DE096::urn:schemas-upnp-org:device:fritzbox:1"}} 2023-07-28 11:38:18.999 - debug: discovery.0 (9384) extended Device: 192.168.1.157 source=upnp 2023-07-28 11:38:19.590 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.1 : {"_addr":"192.168.1.1","_name":"","_upnp":{"LOCATION":"http://192.168.1.1:49000/aura.xml","SERVER":"FRITZ!Box 7490 UPnP/1.0 AVM FRITZ!Box 7490 113.07.29","CACHE-CONTROL":"max-age=1800","EXT":"","ST":"urn:schemas-upnp-org:device:aura:1","USN":"uuid:22617c0d-cb0f-4fb9-a31f-3481C40866FD::urn:schemas-upnp-org:device:aura:1"}} 2023-07-28 11:38:19.905 - debug: discovery.0 (9384) extended Device: 192.168.1.1 source=upnp 2023-07-28 11:38:20.447 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49152/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"3179ef9e-1dd2-11b2-830d-c67a76b2e14f","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.19","X-USER-AGENT":"redsonic","ST":"upnp:rootdevice","USN":"uuid:ISG-1_0-0280AD21C9CD::upnp:rootdevice"}} 2023-07-28 11:38:21.106 - debug: discovery.0 (9384) extended Device: 192.168.1.108 source=upnp 2023-07-28 11:38:21.560 - debug: discovery.0 (9384) UPNP Answer from 192.168.1.108 : {"_addr":"192.168.1.108","_name":"","_upnp":{"CACHE-CONTROL":"max-age=120","DATE":"Fri, 28 Jul 2023 09:38:04 GMT","EXT":"","LOCATION":"http://192.168.1.108:49152/description.xml","OPT":"\"http://schemas.upnp.org/upnp/1/0/\"; ns=01","01-NLS":"3179ef9e-1dd2-11b2-830d-c67a76b2e14f","SERVER":"Linux/2.6.24.7, UPnP/1.0, Portable SDK for UPnP devices/1.6.19","X-USER-AGENT":"redsonic","ST":"uuid:ISG-1_0-0280AD21C9CD","USN":"uuid:ISG-1_0-0280AD21C9CD"}} 2023-07-28 11:38:21.911 - debug: discovery.0 (9384) extended Device: 192.168.1.108 source=upnp 2023-07-28 11:38:22.207 - info: discovery.0 (9384) Done discovering upnp devices. 20 packages received 2023-07-28 11:38:22.795 - info: discovery.0 (9384) Found 6 addresses

Versions:

Additional context Since this is my first discovery plugin, maybe I am missing something, so that you can give me a hint what I am doing wrong

pdbjjens commented 1 year ago

I have traced down this problem to the line 36 in upnp.js: client.on('response', (headers, statusCode, rinfo) => self.parseMessage(headers, statusCode, rinfo)); It seems that if there are many devices answering to a M-SEARCH, the processing in the discovery adapter takes too long, so that many responses are lost. I have changed the line to client.on('response', (headers, statusCode, rinfo) => setTimeout(() => self.parseMessage(headers, statusCode, rinfo), 3000)); so that processing the responses is delayed until all resonses should have arrived (the default maximum wait time MX in the node-ssdp is 3 secc). With this modification, the detection works reliably. I would like to issue the PR for the frontier-silicon.js detector module including this modification.

Btw: Since the purpose of the multicast-client is not clear to me, I did not modify the lines 35 and 37. I guess the multicast-client is thought to catch advertise messages which are sent by ssdp servers from time to time or when they are entering the network. But since the discovery adapter is not running permanently in the background and thus will not catch any advertisements, I do not see much sense in the multicast-client.
From my understanding the second ssdp (multicast-) client is not necessary for the working of the upnp discovery and could safely be removed from upnp.js. So if you are preparing a new release of the discovery adapter, please consider removing the multicast-client code from upnp.js.

Apollon77 commented 1 year ago

Copied answer (german) here from telegram:

Hhmm … sorry aber das macht irgendwie keinen Sinn. Der event wird getriggert mit einem Datenpaket und wenn mehrere kommen sollte einfach Event mehrfach getriggert werden. An sich ist JavaScript da schön asynchron - es seinen die Library limitiert das. Versuch mal ob ein „setImmediate“ oder ein timeout mit 0s auch schon geht.

Das was du gerade tust ist am Ende die Verarbeitung jedes einzelnen Pakets um 3s nach hinten zu verschieben. Das ist denke ich nicht was du wirklich willst. Die Daten werden an sich nicht magisch mehr nur weil es später verarbeitet wird.

pdbjjens commented 1 year ago

@Apollon77 Hallo Ingo, ich bin dafür, die Diskussion hier fortzusetzen, in Telegram verliert man leicht den "Faden". Ich habe mal etwas mit den timeouts experimentiert: Die Varianten mit „setImmediate“ oder timeout mit 0s habe ich probiert. Das führt dazu, das genau nach 15s der timeout der upnp methode zuschlägt. Bis dahin wurde aber nur ~ein Drittel (50) der responses verarbeitet und damit nicht alle Geräte gefunden.
Wenn ich den timeout der upnp methode auf 60s hochsetze, werden 160 responses empfangen und alle Geräte(11) erkannt. Ich vermute, dass die hohe Anzahl von responses durch zusätzlich empfangene ssdp:alive messages zustande kommt.

Wenn ich den timeout der upnp methode bei 15s belasse, aber den settimeout von 0 auf 3s erhöhe, so werden um die 130 responses empfangen und alle Geräte erkannt. Merkwürdigerweise wird in diesem Fall der Test nicht nach 15s abgebrochen sondern endet erst in ~35s. Wenn ich in diesem Fall den timeout der upnp methode auf 60s hochsetze, ändert sich nur die Anzahl der responses (vermutlich durch ssdp:alive messages), die Anzahl der gefundenen Geräte ändern sich nicht. settimeouts unter 3s (z.B. 1s) führen zu weniger responses (113), kürzerer Dauer bis zum Ende der Discovery (31s) und es werden nicht alle Geräte erkannt.
settimeouts über 3s (z.B. 4s) führen zu kaum mehr responses (135), wenig längerer Dauer bis zum Ende der Discovery (37s) und es werden alle Geräte erkannt. Aus diesem Verhalten habe ich geschlossen, dass ein settimout von 3s optimal ist. Ich habe mir das so erklärt: Die Verarbeitung der responses wird verzögert, bis alle responses eingetroffen sein sollten (die standardmäßige maximale Wartezeit MX im Node-SsDP beträgt 3 Sekunden). Die Variation der Anzahl der responses kommt vermutlich durch zusätzlich empfangene ssdp:alive messages. (die Notwendigkeit des Empfangs der advertisments habe ich ja schon oben infrage gestellt). Nur als Anmerkung dazu - es gibt in meinem Netzwerk einen nicht normgerechten ssdp-Server (genauer ein SEMP Gateway, dass auf meinem ioBroker 192.168.1.154 läuft), der sich nur durch gelegentliche ssdp:alive messages bemerkbar macht. Auf M-SEARCH reagiert er nicht. Allerdings wäre das für mich kein Grund, den Empfangs der advertisments beizubehalten, denn es ist ja reiner Zufall, wenn sich das SEMP-Gateway während der Detektionsphase meldet.

Hast Du vielleicht eine andere Erklärung oder Sichtweise auf dieses issue? Ich habe das etwas längliche logfile meiner Experimente mal angehängt, falls Du Lust hast meine o.g. findings nachzuvollziehen. iobroker.2023-08-03.log.txt