Connection closed and other connectivity problems

[DarkVoyage]

Connection closed and other connectivity problems

[DarkVoyage]

Has been waiting until user returns. New version relaunches Connection closed and doesn't stuck on Paused. So I think the head question was resolved.

I think the only thing I could do to improve things slightly is to keep a separate list of removed

Yeah, keeping a list for some time might help.

[mathiascode]

Debug logging would be helpful here. Please enable Connections + Messages + Transfers debug logging while this issue happens: https://nicotine-plus.org/doc/DEVELOPING.html#debug-logging

peer (or download entry) simply ignores start/pause command.

What do you mean by this? Does the download status change, but nothing happens after that? Or is nothing happening at all?

So it would be right to start with what status "connection closed" means in first place.

• Connection closed: an established connection was abruptly closed
• Connection timeout: failed to establish a connection (e.g. if both ports are closed), or an established connection was inactive for 60 seconds

[DarkVoyage]

Does the download status change, but nothing happens after that?

When you normally click Resume/Pause in menu (I use keys R/T), you see that there's a change in status. When you click Resume on active queue, it works like retry and you also see change. When I tried these actions on "connection closed" files, nothing happens, no status change. You can only remove them or leave. But as I said, this might be a different problem, because this ignorance happens only to peer that is currently the last in download list. Status may differ, it can be normally queued too, but Resume/Pause do nothing.

Any connection problem mentioned is on my side mostly because of VPN/NAT limitations. But different peers behave differently. Some connect fine and fast, some become very unstable and connection fails every minute and there are lots of timeouts, but timeout restart fast and may show timeout 100 times more, but suddenly connect and download. And some simply stop and gradually change to connection closed and stay in that status for some time.

The change in something since newer version (or I don't know what) that I've never seen "connection closed" before, for example, last year. But I see it now on a peer that earlier showed "connection timeout" a lot. Timeouts are more often and happen all the time on 50% of peers. Only 2 peers of all I worked with closed connection. Too bad they are rare visitors and as always - very important to be available for download (exclusive content providers).

Curious, can the "last peer in list" problem be connected to #2926.

[DarkVoyage]

By the way, sometimes clicking Resume on peers is the only way to keep them giving the files, as other user said - they stuck in queue status. You click Resume and download starts right away, even is some files show queue of 100-200, it resets to 0. Generally, this is not like it works in classic client. When you click retry, you see no visible change at all, works only for errored downloads. You can use pause/unpause to reset queue, but it never skips only by resume and retry like in N+.

[DarkVoyage]

Here's what I see in 3.3.4. Same problematic peer that I can't normally download, connect, grab list most of the time and very important to me. Sure, problems are on my side. But in this case something breaks inside N+. When all these statuses gradually become Connection closed - I can't resume them, they don't react. Only way to relaunch them - disconnect/connect server. I can sometimes pause jobs from this user and then Pause mode doesn't react on Resume, they are locked as Paused until disconnect. After some unknown timeout they restart, maybe minute or more.

Sometimes queued jobs don't move at all until you kick them with Resume. Then one file gets downloaded and then it waits again for next kick. This means that there's a need for some better automatic system of cyclic restart of downloads to keep them downloading in problematic situations (connection fails, errors, refusals, timeouts, etc.)...

[slook]

Same problematic peer that I can't normally download

Are you able to determine what client the peer is using?

[DarkVoyage]

How can I do this? Can you tell, if I see root as @ xxxxx - does it mean that share is made in Nicotine or opposite?
I think he uses classic, because he speaks like "I need to rehash share", it sounds not like Nicotine user would say, because it is done in background and doesn't break the normal work, which is a huge advantage. And frankly speaking Nicotine is not so well known as alternative, Soulseek was most of the time a monopoly.

[slook]

I see root as @ xxxxx

It is likely an official client but an old version. You could him if he runs "Soulseek Qt" (the modern version), or "Soulseek NS" (the old version). NS has been unsupported for many years as it has several issues like this which do cause transfer failures.

[DarkVoyage]

He knows about Nicotine, not sure how he uses both... I believe his current client is SoulseekQT 2023.4.22. I've told him that there's an update to 2024. I don't think that root means NS, because I see this in most shares and it can't be that everybody use 10 year outdated client. And actually it helps filtering by user in wishlist, this id is kind of permanent.

[slook]

Yes you are correct the default @@ root prefix is common amongst all official clients. I meant that the fact that transfer errors are being encountered indicates use of an old NS version, but as you have established this isn't the case so the problem must arise due to something else.

In any case, N+'s handling of this scenario does seem to be incorrect in some way, but it is difficult to know what to do about it without deeper investigations.

Perhaps some clues can be offered by enabling the "[Debug] Connections" and "[Debug] Transfers" log categories (but don't post any of those logs containing user names/IP's here). It could be useful to observe what occurs in the Conn log when the transfer fails and also when you hit Retry.

[DarkVoyage]

Here's what I collected from log:

2024-06-19 22:14:56 [Transfer] Adding file @@.....flac from user USERXXXXX to download queue
2024-06-19 22:14:57 [Conn] Attempting direct connection of type P to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:14:57 [Conn] Attempting indirect connection to user USERXXXXX with token 2538
2024-06-19 22:14:57 [Conn] Sending message of type <class 'pynicotine.slskmessages.PlaceInQueueRequest'> to user USERXXXXX on existing connection
2024-06-19 22:14:57 [Conn] Sending message of type <class 'pynicotine.slskmessages.QueueUpload'> to user USERXXXXX on existing connection
2024-06-19 22:14:57 [Conn] Established outgoing connection of type P with user USERXXXXX. List of outgoing messages: [<pynicotine.slskmessages.PlaceInQueueRequest object at 0x000001ae50ecaf20>, <pynicotine.slskmessages.PlaceInQueueRequest object at 0x000001ae50ecb600>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecb060>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50eca980>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecb330>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50eca070>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec9760>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecabb0>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec9580>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecade0>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec8b80>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec8db0>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec8bd0>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecac50>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecb100>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec9490>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ecab10>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec98f0>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50eca250>, <pynicotine.slskmessages.QueueUpload object at 0x000001ae50ec9ad0>]
2024-06-19 22:14:58 [Conn] Sending PeerInit message of type P to user USERXXXXX
2024-06-19 22:14:58 [Transfer] Received download request with token 420991 for file @@.......flac from user USERXXXXX
2024-06-19 22:14:58 [Transfer] Responding to download request with token 420991 for file @@......flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:14:58 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:14:59 [Conn] Received indirect connection request of type F from user USERXXXXX, token 711, address ('IPADDRESS', 51150)
2024-06-19 22:14:59 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:00 [Transfer] Adding file @@.....flac from user USERXXXXX to download queue
2024-06-19 22:15:00 [Transfer] Received download request with token 420992 for file @@.....flac from user USERXXXXX
2024-06-19 22:15:00 [Transfer] Responding to download request with token 420992 for file @@.....flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:00 [Conn] Sending message of type <class 'pynicotine.slskmessages.QueueUpload'> to user USERXXXXX on existing connection
2024-06-19 22:15:00 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:00 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:00 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 711
2024-06-19 22:15:00 [Conn] Shutting down socket <socket.socket fd=1184, family=2, type=1, proto=0, laddr=('10.211.1.4', 64221), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:00 [Conn] Closing socket <socket.socket fd=1184, family=2, type=1, proto=0, laddr=('10.211.1.4', 64221), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:00 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:01 [Conn] Received indirect connection request of type F from user USERXXXXX, token 712, address ('IPADDRESS', 51150)
2024-06-19 22:15:01 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:01 [Transfer] Adding file @@.flac from user USERXXXXX to download queue
2024-06-19 22:15:01 [Transfer] Received download request with token 420993 for file @@.flac from user USERXXXXX
2024-06-19 22:15:01 [Transfer] Responding to download request with token 420993 for file @@.flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:01 [Conn] Sending message of type <class 'pynicotine.slskmessages.QueueUpload'> to user USERXXXXX on existing connection
2024-06-19 22:15:01 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:01 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:01 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 712
2024-06-19 22:15:02 [Conn] Shutting down socket <socket.socket fd=2672, family=2, type=1, proto=0, laddr=('10.211.1.4', 64392), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:02 [Conn] Closing socket <socket.socket fd=2672, family=2, type=1, proto=0, laddr=('10.211.1.4', 64392), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:02 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:02 [Conn] Received indirect connection request of type F from user USERXXXXX, token 713, address ('IPADDRESS', 51150)
2024-06-19 22:15:02 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:03 [Transfer] Upload attempt by user USERXXXXX for file @@.flac failed. Reason: Connection closed
2024-06-19 22:15:03 [Transfer] Received download request with token 420994 for file @@.flac from user USERXXXXX
2024-06-19 22:15:03 [Transfer] Responding to download request with token 420994 for file @@.flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:03 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:03 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:03 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 713
2024-06-19 22:15:03 [Conn] Shutting down socket <socket.socket fd=792, family=2, type=1, proto=0, laddr=('10.211.1.4', 64491), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:04 [Conn] Closing socket <socket.socket fd=792, family=2, type=1, proto=0, laddr=('10.211.1.4', 64491), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:04 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:04 [Conn] Received indirect connection request of type F from user USERXXXXX, token 714, address ('IPADDRESS', 51150)
2024-06-19 22:15:04 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:04 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:04 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 714
2024-06-19 22:15:04 [Transfer] Upload attempt by user USERXXXXX for file @@.flac failed. Reason: Connection closed
2024-06-19 22:15:05 [Transfer] Received download request with token 420995 for file @@.flac from user USERXXXXX
2024-06-19 22:15:05 [Transfer] Responding to download request with token 420995 for file @@.flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:05 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:05 [Conn] Shutting down socket <socket.socket fd=1928, family=2, type=1, proto=0, laddr=('10.211.1.4', 64601), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:05 [Conn] Closing socket <socket.socket fd=1928, family=2, type=1, proto=0, laddr=('10.211.1.4', 64601), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:05 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:05 [Conn] Received indirect connection request of type F from user USERXXXXX, token 715, address ('IPADDRESS', 51150)
2024-06-19 22:15:05 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:07 [Transfer] Adding file @@.flac from user USERXXXXX to download queue
2024-06-19 22:15:07 [Transfer] Received download request with token 420996 for file @@.flac from user USERXXXXX
2024-06-19 22:15:07 [Transfer] Responding to download request with token 420996 for file @@.flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:07 [Conn] Sending message of type <class 'pynicotine.slskmessages.QueueUpload'> to user USERXXXXX on existing connection
2024-06-19 22:15:07 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:07 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:07 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 715
2024-06-19 22:15:07 [Conn] Shutting down socket <socket.socket fd=1932, family=2, type=1, proto=0, laddr=('10.211.1.4', 64761), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:07 [Conn] Closing socket <socket.socket fd=1932, family=2, type=1, proto=0, laddr=('10.211.1.4', 64761), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:07 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:07 [Conn] Received indirect connection request of type F from user USERXXXXX, token 716, address ('IPADDRESS', 51150)
2024-06-19 22:15:07 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:08 [Transfer] Adding file @@.flac from user USERXXXXX to download queue
2024-06-19 22:15:08 [Transfer] Received download request with token 420997 for file @@.flac from user USERXXXXX
2024-06-19 22:15:08 [Transfer] Responding to download request with token 420997 for file @@.flac from user: USERXXXXX, allowed: True, reason: None
2024-06-19 22:15:08 [Conn] Sending message of type <class 'pynicotine.slskmessages.QueueUpload'> to user USERXXXXX on existing connection
2024-06-19 22:15:08 [Conn] Sending message of type <class 'pynicotine.slskmessages.TransferResponse'> to user USERXXXXX on existing connection
2024-06-19 22:15:08 [Conn] Established outgoing connection of type F with user USERXXXXX. List of outgoing messages: []
2024-06-19 22:15:08 [Conn] Responding to indirect connection request of type F from user USERXXXXX, token 716
2024-06-19 22:15:09 [Conn] Shutting down socket <socket.socket fd=4532, family=2, type=1, proto=0, laddr=('10.211.1.4', 64962), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:09 [Conn] Closing socket <socket.socket fd=4532, family=2, type=1, proto=0, laddr=('10.211.1.4', 64962), raddr=('IPADDRESS', 51150)>
2024-06-19 22:15:09 [Conn] Removed connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:15:09 [Conn] Received indirect connection request of type F from user USERXXXXX, token 717, address ('IPADDRESS', 51150)
2024-06-19 22:15:09 [Conn] Attempting direct connection of type F to user USERXXXXX ('IPADDRESS', 51150)
2024-06-19 22:16:10 [Conn] Indirect connect request of type P to user USERXXXXX with token 14474 expired

[DarkVoyage]

Also noticed strange behavior - some files return to download list after being deleted. I added something to download, removed and see that it is there downloading. Remove again - it returns again. It needs to be removed several times to finally stop adding back. I don't think this problem was around before 3.3.4 or maybe 3.3.3.

[mathiascode]

Also noticed strange behavior - some files return to download list after being deleted. I added something to download, removed and see that it is there downloading. Remove again - it returns again. It needs to be removed several times to finally stop adding back. I don't think this problem was around before 3.3.4 or maybe 3.3.3.

Make sure Preferences -> Downloads -> Allow users to send you any files is disabled, otherwise cancelled downloads will be counted as sent files and added to the list again when the user tries to upload them.

I found two issues in the code, one where downloads could get stuck in active/transferring mode internally, and one where retries didn't work properly. Please try the latest development build of Nicotine+ and see if the situation has improved.

[mathiascode]

Another fix added in 36d962c.

[DarkVoyage]

Make sure Preferences -> Downloads -> Allow users to send you any files is disabled, otherwise cancelled downloads will be counted as sent files and added to the list again when the user tries to upload them.

This was exactly correct. I never used this option, but one user wanted me to use it.

[mathiascode]

Make sure Preferences -> Downloads -> Allow users to send you any files is disabled, otherwise cancelled downloads will be counted as sent files and added to the list again when the user tries to upload them.

This was exactly correct. I never used this option, but one user wanted me to use it.

This "send files" feature has never worked great (SoulseekQt disabled/removed it for that reason). I think the only thing I could do to improve things slightly is to keep a separate list of removed, queued downloads, and reject them when the user eventually tries to initiate the upload.