UPnP stopped working with current unstable build

[vodzl]

Nicotine+ version: 3.2.0.dev1 portable
Operating System/Distribution:
Win10, x64, TL-WR743ND

Describe the bug

Hello,
UPnP has stopped working after latest changes.
It was working flawlessly since it was fixed a few months ago.
Several day old unstable build has UPnP working.
Probably related to #1566 (it was working for me at that time)
16:45:06 UPnP error: UPnP does not work on this network
16:45:06 Failed to automate the creation of UPnP Port Mapping rule.

[slook]

Thanks for this report @vodzl please can you post the full output of the [Miscellaneous] Debug Logging category.

Menu > View > Show Debug Log Controls

[vodzl]

Yes, sure here it is:

18:15:09 Loading GTK 3.24.30
18:15:09 Loading Nicotine+ 3.2.0.dev1, using Python 3.9.7 (default, Sep 22 2021, 08:13:19) [GCC 10.3.0 32 bit]
18:15:09 [Misc] Creating Port Mapping rule via UPnP...
18:15:09 [Misc] Loading plugin handler
18:15:09 [Misc] UPnP: Discovering... delay=2 seconds
18:15:09 Connecting to server.slsknet.org:2242
18:15:09 [Misc] UPnP: SSDP request: b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nST: urn:schemas-upnp-org:service:WANIPConnection:1\r\nMAN: "ssdp:discover"\r\nMX: 2\r\n\r\n'
18:15:09 [Misc] UPnP: Sent M-SEARCH IP request 1
18:15:09 [Misc] UPnP: SSDP request: b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nST: urn:schemas-upnp-org:service:WANPPPConnection:1\r\nMAN: "ssdp:discover"\r\nMX: 2\r\n\r\n'
18:15:09 [Misc] UPnP: Sent M-SEARCH PPP request 1
18:15:09 [Misc] UPnP: SSDP request: b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nST: urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\nMAN: "ssdp:discover"\r\nMX: 2\r\n\r\n'
18:15:09 [Misc] UPnP: Sent M-SEARCH IGD request 1
18:15:09 [Misc] UPnP: SSDP request: b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nST: urn:schemas-upnp-org:service:WANIPConnection:2\r\nMAN: "ssdp:discover"\r\nMX: 2\r\n\r\n'
18:15:09 [Misc] UPnP: Sent M-SEARCH IP request 2
18:15:09 [Misc] UPnP: SSDP request: b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nST: urn:schemas-upnp-org:device:InternetGatewayDevice:2\r\nMAN: "ssdp:discover"\r\nMX: 2\r\n\r\n'
18:15:09 [Misc] UPnP: Sent M-SEARCH IGD request 2
18:15:09 Listening on port 2234
18:15:09 Connected to server server.slsknet.org:2242, logging in...
18:15:10 1681 privileged users
18:15:10 You have no privileges. Privileges are not required, but allow your downloads to be queued ahead of non-privileged users.
18:15:10 [Misc] UPnP: Device search response: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=100\r\nDATE: Fri, 24 Sep 2021 18:15:09 GMT\r\nEXT:\r\nLOCATION: http://192.168.0.1:1900/igd.xml\r\nSERVER: ipos/7.0 UPnP/1.0 TL-WR743ND/2.0\r\nST: urn:schemas-upnp-org:service:WANIPConnection:1\r\nUSN: uuid:9f0865b3-f5da-4ad5-85b7-7404637fdf37::urn:schemas-upnp-org:service:WANIPConnection:1\r\n\r\n'
18:15:10 [Misc] UPnP: Device search response: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=100\r\nDATE: Fri, 24 Sep 2021 18:15:09 GMT\r\nEXT:\r\nLOCATION: http://192.168.0.1:1900/igd.xml\r\nSERVER: ipos/7.0 UPnP/1.0 TL-WR743ND/2.0\r\nST: urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\nUSN: uuid:060b7353-fca6-4070-85f4-1fbfb9add62c::urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\n\r\n'
18:15:11 [Misc] UPnP: %s device(s) detected
18:15:11 UPnP error: UPnP does not work on this network
18:15:11 [Misc] Traceback (most recent call last):
File "pynicotine/upnp.py", line 333, in update_port_mapping
File "pynicotine/upnp.py", line 364, in _update_port_mapping
RuntimeError: UPnP does not work on this network
18:15:11 Failed to automate the creation of UPnP Port Mapping rule.

[slook]

@mathiascode I don't know if it's relevant, on my network UPnP is expected to not work and there has always been a logged Traceback similar to the OP but with additional information shown about line 333 (local_ip_address) and line 364 (raise):

16:21:46 Loading Nicotine+ 3.2.0.dev1, using Python 3.5.3 (default, Apr  5 2021, 09:00:41) [GCC 6.3.0 20170516]
...
16:21:47 [Misc] UPnP: %s device(s) detected
16:21:47 UPnP error: UPnP does not work on this network
16:21:47 [Misc] Traceback (most recent call last):
  File "/home/sli/Git/dev/nicotine-plus/pynicotine/upnp.py", line 333, in update_port_mapping
    local_ip_address = self._update_port_mapping(listening_port)
  File "/home/sli/Git/dev/nicotine-plus/pynicotine/upnp.py", line 364, in _update_port_mapping
    raise RuntimeError("UPnP does not work on this network")
RuntimeError: UPnP does not work on this network
16:21:47 Failed to automate the creation of UPnP Port Mapping rule.

[mathiascode]

The latest unstable build contains additional logging. Could you share the output once you've downloaded the build?

[slook]

I can confirm N+ now reports the correct number devices on my network: 17:16:49 [Misc] UPnP: 0 device(s) detected amongst other additional details.

How about you @vodzl does your debug log now include the data needed to diagnose your issue? Please post another full log output.

[vodzl]

I think this is an extra logging you asked for.
So much of data github doesn't display it correct so i have attached a txt file
extralog.txt

[mathiascode]

d17a402 should fix this. Can you confirm?

[vodzl]

Yes. Thank you! There is no UPnP port forwarding success message but port test tells it is open and last log message is:
20:39:15 [Misc] Managed to map external WAN port 2234 to your local host 192.168.0.100 port 2234.

[slook]

@vodzl Thank you for taking the time to report this so promptly, as others will be less likely to suffer the same regression, the update is likely to make the UPnP more robust for everybody.

@mathiascode I suggest assigning the success message into the Standard Log, otherwise there is no evidence that UPnP is enabled unless there is an error. Also prepend message with "UPnP: "...

UPnP: External WAN port 2234 successfully mapped to your local host 192.168.0.100 port 2234

[mathiascode]

Done in 2d52abc