MulticastHandler exception

[sebeksd]

Hi, Im using Open Media Vault 5 in two locations, home and company. In company server logs I'm getting frequent (every 1 minute) exceptions (which spams my syslog). Version of wsdd.py is 0.6.4. Im guessing this is probably because some device in company network (there is ton of random IP cameras, DVRs and other random network connected equipment).

Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: ERROR: Exception in callback MulticastHandler.handle_request(<socket.socke...5.250', 3702)>) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: handle: <Handle MulticastHandler.handle_request(<socket.socke...5.250', 3702)>)> Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: Traceback (most recent call last): Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: self._context.run(self._callback, *self._args) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "/usr/sbin/wsdd.py", line 195, in handle_request Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: handler.handle_request(msg, address) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "/usr/sbin/wsdd.py", line 744, in handle_request Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: reply = self.handle_message(msg, self.mch, address) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "/usr/sbin/wsdd.py", line 354, in handle_message Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: tree = ElementTree.fromstring(msg) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "/usr/lib/python3.7/xml/etree/ElementTree.py", line 1315, in XML Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: parser.feed(text) Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: File "", line None Feb 21 00:00:28 NEXTSRV04 wsdd.py[12290]: xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1, column 105

Link to original forum thread: https://forum.openmediavault.org/index.php?thread/42170-wsdd-py-multicasthandler-exception/

[christgau]

Thanks for sharing the issue and providing details. Looks like duplicate of #81. Maybe it's best to catch the exception when the message is parsed. This would make your logs quite again.

[sebeksd]

Is there a way to find this bad behaving device? Part of first line looks like an IP address '5.250' but our network has range of 192.168.0.0/24.

[christgau]

You can start wsdd with -v/--verbose, but stop the daemon first. It then prints out where UDP datagrams come from which should help to do identify the devices.

[sebeksd]

I guess IP 192.168.0.83 or 192.168.0.84 is a culprit, am I right ?

(uuid removed form log) Feb 22 12:42:31 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:31,669:wsdd INFO(pid 25286): 192.168.0.84:40500(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:32 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:32,514:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:37 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:37,904:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:42 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:42,524:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:47 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:47,234:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:51 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:51,934:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:42:56 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:42:56,684:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:01 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:01,784:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:06 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:06,654:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:07 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:07,505:wsdd INFO(pid 25286): 192.168.0.50:63346(enp3s0f0) - - "Resolve urn:uuid: UDP" - - Feb 22 12:43:09 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:09,063:wsdd INFO(pid 25286): 192.168.0.55:3702(enp3s0f0) - - "Hello urn:uuid: UDP" - - Feb 22 12:43:11 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:11,334:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:16 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:16,104:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:20 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:20,824:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:25 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:25,854:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:30 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:30,564:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:31,653:asyncio ERROR(pid 25286): Exception in callback MulticastHandler.handle_request(<socket.socke...5.250', 3702)>) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: handle: <Handle MulticastHandler.handle_request(<socket.socke...5.250', 3702)>)> Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: Traceback (most recent call last): Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: self._context.run(self._callback, *self._args) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "/usr/sbin/wsdd.py", line 195, in handle_request Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: handler.handle_request(msg, address) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "/usr/sbin/wsdd.py", line 744, in handle_request Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: reply = self.handle_message(msg, self.mch, address) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "/usr/sbin/wsdd.py", line 354, in handle_message Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: tree = ElementTree.fromstring(msg) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "/usr/lib/python3.7/xml/etree/ElementTree.py", line 1315, in XML Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: parser.feed(text) Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: File "", line None Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1, column 105 Feb 22 12:43:31 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:31,653:wsdd INFO(pid 25286): 192.168.0.84:40500(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:35 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:35,174:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:39 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:39,904:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:44 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:44,574:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:49 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:49,654:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:54 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:54,414:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:43:59 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:43:59,244:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:04 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:04,354:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:09 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:09,063:wsdd INFO(pid 25286): 192.168.0.55:3702(enp3s0f0) - - "Hello urn:uuid: UDP" - - Feb 22 12:44:09 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:09,404:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:14 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:14,904:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:19 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:19,975:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:24 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:24,724:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - - Feb 22 12:44:29 NEXTSRV04 wsdd.py[25286]: 2022-02-22 12:44:29,484:wsdd INFO(pid 25286): 192.168.0.83:34455(enp3s0f0) - - "Probe uuid: UDP" - -

[christgau]

Naaah, too bad. I hadn't looked into the code and replied out of my memory. The logging with "... UDP" only works for valid wsdd messages. There is currently no additional (debug) output that would help you finding out the "suspicious" device. However, you may add some print calls or calls to the logger in MulticastHandler's read_socket method. Alternatively, you may fire up wireshark or similar tools.

[sebeksd]

I was thinking, if this is known problem (rare one) with some devices maybe it would be good to make the exception less "frightening" and put simple single line message something like "Handle request: badly formatted XML from '127.0.0.1'" or similar.

Second thing that I'm thinking is, if this happens user has no real way to deal with it, only way is to turn bad device off, maybe adding new parameter '--ignore_bad_xml' would be good solution, it would hide exception in this exact place?

What do you think?

[christgau]

I was thinking, if this is known problem (rare one) with some devices maybe it would be good to make the exception less "frightening" and put simple single line message something like "Handle request: badly formatted XML from '127.0.0.1'" or similar.

That's my intention as I wrote in my first comment: https://github.com/christgau/wsdd/issues/131#issuecomment-1047203931 😉

Second thing that I'm thinking is, if this happens user has no real way to deal with it, only way is to turn bad device off, maybe adding new parameter '--ignore_bad_xml' would be good solution, it would hide exception in this exact place?

IMO, a log (with debug prio) message about a malformed XML from a certain IP, similar to what you suggested above, would be sufficient.

[christgau]

The actual issue, i.e. the raised exception for malformed/invalid XML, was already fixed in cffedb2b. You may update and try again. Please report back, if the error still exists.