search

nicotine-plus / nicotine-plus

Graphical client for the Soulseek peer-to-peer network
https://nicotine-plus.org
GNU General Public License v3.0
1.7k stars 134 forks source link

Nicotine+ 3.3.2 displays user as logged off while the transfers are active #2909

Closed 501NotImplemented closed 7 months ago

501NotImplemented commented 7 months ago

Nicotine+ version: 3.3.2. GTK 4.12.5 Python 3.11.8 Operating System/Distribution: Windows 11 Pro Version 23H2 OS build 22631.3155 Experience Windows Feature Experience Pack 1000.22684.1000.0

Describe the bug

The downloads status column displays the user as logged off for queued transfers, while the one transfer is active.

Expected behavior

The queued transfers should be displayed as queued

Steps to reproduce the bug

Start the app

Additional context

Screenshots, logs, stacktraces or relevant information. 29 02 2024_22 20 51_REC

mathiascode commented 7 months ago

Are they actually logged out or not? What does it say when you browse their user profile?

501NotImplemented commented 7 months ago

@mathiascode they are actually online (away) status. The issue disappeared after the app restart. Could be some connectivity issue, I guess.

slook commented 7 months ago

Without knowing more precise 'Steps to reproduce the bug' information, it will not be possible to investigate this bug.

mathiascode commented 7 months ago

A couple of questions:

501NotImplemented commented 7 months ago

@mathiascode no, not every time. I can't reproduce this issue for now. Another detail - if I manually right click on the username and select 'Resume' from the context menu - the status is changed to 'Queued'.

The issue was reproducing only on the startup.

slook commented 7 months ago
501NotImplemented commented 7 months ago

@slook image

Yes, I've tried as you've suggested. See screenshot. Nicotine+ 3.3.3.dev1

Steps to reproduce:

  1. Disable the network connection
  2. Start Nicotine+, so it attempts to connect and fails
  3. Enable the network
  4. Manually connect the Nicotine+ (Righ click on tray icon > Connect)

Actual result: Nicotine+ is connected, the transfers start from the online user, but it still shows User is logged off status on Downloads tab for Queued uploads. If the status is manually updated - right click on the root username on the Downloads pane and select Resume - the status is correctly updated to Queued.

Expected result: The status should be updated to Queued uploads on the Nicotine+ connection.

`03.03.2024 16:20:37 Loading plugin system 03.03.2024 16:20:37 Loaded plugin Nicotine+ Commands 03.03.2024 16:20:37 [Misc] Enabled plugin(s): core_commands, leech_detector, auto_user_browse 03.03.2024 16:20:37 Leech Detector: Require users have a minimum of 1 files in 1 shared public folders. 03.03.2024 16:20:37 Loaded plugin Leech Detector 03.03.2024 16:20:37 Loaded plugin Auto-Browse Shares 03.03.2024 16:20:37 Reconnecting to server in 12 seconds 03.03.2024 16:20:37 Cannot listen on port 2234. Ensure no other application uses it, or choose a different port. Error: [WinError 10051] A socket operation was attempted to an unreachable network 03.03.2024 16:20:37 [Misc] CLI input prompt is no longer available: input(): lost sys.stdin 03.03.2024 16:20:39 Rescanning shares… 03.03.2024 16:20:49 Reconnecting to server in 24 seconds 03.03.2024 16:20:49 Cannot listen on port 2234. Ensure no other application uses it, or choose a different port. Error: [WinError 10051] A socket operation was attempted to an unreachable network 03.03.2024 16:21:13 Reconnecting to server in 48 seconds 03.03.2024 16:21:13 Cannot listen on port 2234. Ensure no other application uses it, or choose a different port. Error: [WinError 10051] A socket operation was attempted to an unreachable network 03.03.2024 16:21:40 [Misc] Local IP address: ** 03.03.2024 16:21:40 [Misc] Maximum number of concurrent connections (sockets): 512 03.03.2024 16:21:40 Listening on port: 2234 03.03.2024 16:21:40 Connecting to server.slsknet.org:2242 03.03.2024 16:21:40 Connected to server server.slsknet.org:2242, logging in… 03.03.2024 16:21:41 [Misc] Creating Port Mapping rule... 03.03.2024 16:21:41 [Misc] NAT-PMP: Portmap request attempt 1 of 2: b'\x00\x02\x00\x00\x08\xba\x08\xba\x00\x00\xa8\xc0' 03.03.2024 16:21:41 [Misc] NAT-PMP not available, falling back to UPnP: [WinError 10054] An existing connection was forcibly closed by the remote host 03.03.2024 16:21:41 [Misc] UPnP: Discovering... delay=1 seconds 03.03.2024 16:21:41 [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: 1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Sent M-SEARCH IP request 1 03.03.2024 16:21:41 [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: 1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Sent M-SEARCH PPP request 1 03.03.2024 16:21:41 [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: 1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Sent M-SEARCH IGD request 1 03.03.2024 16:21:41 [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: 1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Sent M-SEARCH IP request 2 03.03.2024 16:21:41 [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: 1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Sent M-SEARCH IGD request 2 03.03.2024 16:21:41 [Misc] UPnP: Device search response: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=3600\r\nEXT: \r\nLOCATION: http://**********/gateway.xml\r\nSERVER: RouterOS/6.49.8UPnP/1.0 **** UPnP/1.0\r\nST: urn:schemas-upnp-org:service:WANIPConnection:1\r\nUSN: uuid:UUID-****-WAN-CONNECTION-DEVICE-8SBP-3M48-3::urn:schemas-upnp-org:service:WANIPConnection:1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Device description response from http://**********/gateway.xml: b'<?xml version="1.0"?>\r\n\r\n \r\n 1\r\n 0\r\n \r\n \r\n urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\n **** Router\r\n ****\r\n http://www.************.com/\r\n Router OS\r\n uuid:UUID-****-INTERNET-GATEWAY-DEVICE-8SBP-3M48\r\n \r\n \r\n image/gif\r\n 16\r\n 16\r\n 8\r\n /logo16.gif\r\n \r\n \r\n image/gif\r\n 32\r\n 32\r\n 8\r\n /logo32.gif\r\n \r\n \r\n image/gif\r\n 48\r\n 48\r\n 8\r\n /logo48.gif\r\n \r\n \r\n \r\n \r\n urn:schemas-microsoft-com:service:OSInfo:1\r\n urn:microsoft-com:serviceId:OSInfo1\r\n /osinfo.xml\r\n /upnp/control/ihikbymfdr/osinfo\r\n /upnp/event/szowfkpdjr/osinfo\r\n \r\n \r\n \r\n \r\n urn:schemas-upnp-org:device:WANDevice:1\r\n WAN Device\r\n ****\r\n http://www.************.com/\r\n Router OS\r\n uuid:UUID-****-WAN-DEVICE-8SBP-3M48-3\r\n \r\n \r\n urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1\r\n urn:upnp-org:serviceId:WANCommonIFC1\r\n /wancommonifc-3.xml\r\n /upnp/control/djubzloglr/wancommonifc-3\r\n /upnp/event/ttaegecslh/wancommonifc-3\r\n \r\n \r\n \r\n \r\n urn:schemas-upnp-org:device:WANConnectionDevice:1\r\n WAN Connection Device\r\n ****\r\n http://www.************.com/\r\n Router OS\r\n uuid:UUID-****-WAN-CONNECTION-DEVICE-8SBP-3M48-3\r\n \r\n \r\n urn:schemas-upnp-org:service:WANIPConnection:1\r\n urn:upnp-org:serviceId:WANIPConn1\r\n /wanipconn-3.xml\r\n /upnp/control/jdhzbmjqru/wanipconn-3\r\n /upnp/event/hwedxfonnc/wanipconn-3\r\n \r\n \r\n \r\n \r\n \r\n \r\n http://**/\r\n \r\n http://**\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Device details: service_type 'urn:schemas-upnp-org:service:WANIPConnection:1'; control_url 'http://1**********/upnp/control/jdhzbmjqru/wanipconn-3' 03.03.2024 16:21:41 [Misc] UPnP: Added service to list 03.03.2024 16:21:41 [Misc] UPnP: Device search response: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=3600\r\nEXT: \r\nLOCATION: http://**********/gateway.xml\r\nSERVER: RouterOS/6.49.8UPnP/1.0 **** UPnP/1.0\r\nST: urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\nUSN: uuid:UUID-****-INTERNET-GATEWAY-DEVICE-8SBP-3M48::urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\n\r\n' 03.03.2024 16:21:41 [Misc] UPnP: Device location was previously processed, ignoring 03.03.2024 16:21:42 [Misc] UPnP: 1 service(s) detected 03.03.2024 16:21:42 [Misc] UPnP: Trying to redirect external WAN port 2234 TCP => ** port 2234 TCP 03.03.2024 16:21:42 [Misc] UPnP: Adding port mapping (**, urn:schemas-upnp-org:service:WANIPConnection:1) at url 'http://**********/upnp/control/jdhzbmjqru/wanipconn-3' 03.03.2024 16:21:42 [Misc] UPnP: Add port mapping request headers: {'Host': '**', 'Content-Type': 'text/xml; charset=utf-8', 'SOAPACTION': '"urn:schemas-upnp-org:service:WANIPConnection:1#AddPortMapping"'} 03.03.2024 16:21:42 [Misc] UPnP: Add port mapping request contents: b'<?xml version="1.0"?>\r\n2234TCP2234**1NicotinePlus43200</u:AddPortMapping></s:Body></s:Envelope>\r\n' 03.03.2024 16:21:42 UPnP: Failed to forward external port 2234: HTTP Error 500: Internal Server Error 03.03.2024 16:21:42 [Misc] Traceback (most recent call last): File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 562, in _add_port_mapping File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 168, in add_port_mapping File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 155, in _request_port_mapping ConnectionResetError: [WinError 10054] An existing connection was forcibly closed by the remote host

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 569, in _add_port_mapping File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 472, in add_port_mapping File "D:/a/nicotine-plus/nicotine-plus/pynicotine/portmapper.py", line 434, in _request_port_mapping File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 216, in urlopen File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 525, in open File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 634, in http_response File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 563, in error File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 496, in _call_chain File "C:/msys64/mingw64/lib/python3.11/urllib/request.py", line 643, in http_error_default urllib.error.HTTPError: HTTP Error 500: Internal Server Error 03.03.2024 16:21:42 1992 privileged users 03.03.2024 16:21:42 You have no Soulseek privileges. While privileges are active, your downloads will be queued ahead of those of non-privileged users.`

Note, that when I initially faced the bug, the network was on. For now, I can reproduce the issue only via the steps provided, it didn't occur just starting the app.

mathiascode commented 7 months ago

This was a tricky one, but I figured out what's happening:

  1. We add a few downloads to the queue, the uploader receives the queue requests
  2. Go offline for about 1-2 minutes
  3. When logging in again, some clients (SoulseekQt, not sure what version) will immediately send both a TransferRequest and UploadFailed message, presumably from an upload attempt while we were offline
  4. The UploadFailed message handler places the transfer in the download queue
  5. We are then informed about the user's online status, but this check fails due to the previous step, and our "User logged off" downloads are not resumed
mathiascode commented 7 months ago

Thank you very much for reporting this! It's unlikely it would've been detected otherwise.