Tracker announce stuck

[skuizy]

libtorrent version (or branch): RC_1_2

platform/architecture armhf

compiler and compiler version: launchpad daily build

I have 1700+ torrents seeding, so not all anounces to trackers are working when I'm restarting deluge, some are failing with a timeout message, othres with a bad file descriptor. Some torrents are re-anounced to the tracker successully after the 3rd or 4th attempt but others aren't even re-announced : the infinite symbol is shown next the next anounce field in deluge.

I can't even force a new anounce for these torrents, it simply does nothing when I click on update tracker.

I don't think this is tracker related as I have successful and failing torrents for the same tracker.

[arvidn]

I think some logs of at least tracker_error_alert would help, and possibly also torrent_log_alert

[skuizy]

Looks like it has been resolved by something in

• 2964cbc
• 80ccc21
• a871668

I was having trouble on libtorrent-rasterbar - 1.2.1+daily10203+e9cff1d+202003280220~ubuntu19.10.1

I am now on libtorrent-rasterbar - 1.2.1+daily10206+a871668+202003291420~ubuntu19.10.1

[skuizy]

Well after all I'm still having the same problem and managed to grab some logs.

Looks like errors are occuring when all my torrents are restarted at the same time after the night (they are paused by the scheduler plugin).

Interrestingly, errors comme first and then some success (we are talking of 1600+ errors for 1700+ torrents)

In contrary to what it looks like, Bad file descriptor and Invalid argument errors are mixed up.

I don't have torrent_log_alert in my logs.

As for the torrents that won't be reannounced, there's nothing in the log, I can just try to reannounce them by individually pausing/resuming them. Yet, if the announce is failing more than 1 time, the torrent won't be reannounced without any log...

12:55:50.050 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_announce_alert: my_torrent_name (some_http_tracker_url)[10.0.0.97:64270] sending announce (started)
12:55:50.050 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_announce_alert
12:55:50.051 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_announce_alert: my_torrent_name (some_https_tracker_url)[10.0.0.97:64270] sending announce (started)
12:55:50.051 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_announce_alert

12:55:50.063 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_error_alert: my_torrent_name (hsome_http_tracker_url)[10.0.0.97:64270] Invalid argument "" (27)
12:55:50.064 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_error_alert
12:55:50.064 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_error_alert: my_torrent_name (some_http_tracker_url)[10.0.0.97:64270] Invalid argument "" (9)
12:55:50.065 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_error_alert

12:55:51.149 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_error_alert: my_torrent_name (some_http_tracker_url)[10.0.0.97:64270] Bad file descriptor "" (9)
12:55:51.149 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_error_alert
12:55:51.149 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_error_alert: my_torrent_name (some_https_tracker_url)[10.0.0.97:64270] Bad file descriptor "" (2)
12:55:51.150 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_error_alert

12:55:51.161 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_reply_alert: my_torrent_name (some_http_tracker_url)[10.0.0.97:64270] received peers: 0
12:55:51.162 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_reply_alert
12:55:51.162 [DEBUG   ][deluge.core.alertmanager            :130 ] tracker_reply_alert: my_torrent_name (some_https_tracker_url)[10.0.0.97:64270] received peers: 3
12:55:51.162 [DEBUG   ][deluge.core.alertmanager            :135 ] Handling alert: tracker_reply_alert

[arvidn]

my suspicion is that libtorrent ends up hammering the tracker causing some of the connections to fail. I think the best solution to this is #4334

[ghost]

@arvidn I noticed that most trackers just close the connection after one successful announce. It doesn’t expect multiple announces per connection. I’m bit skeptical if pipelining the requests by keeping the connection open will work across most trackers.
I think not hammering the tracker with that many requests is the way to go. Limit the maximum number of open http connections and keep excess requests in queue. We can announce to lets say 100 at a time. This will increase the time taken for all announces to go through but you won’t be hammering the tracker.

[ghost]

Also you have to keep in mind that the tracker could be timing out due to not being able to process that many announces at once. So pipelining them to a single connection might not serve the purpose of evening out the load that much. However it could be handy in terms of TLS sessions.

[skuizy]

I don't know what the good solution can be, I'm willing to give a try at any patch :)

What I do know is that being in a state where we are never re-trying to reanounce torrent status to the tracker isn't good actualy. A tracker might be down for any amount of time and up again later. I think this can especially be true with public trackers that can be seen down temporarly because of some DNS failure or for maintenance or even if my connection goes down for a bit, if our announce is failing during this time, it can safely be retried again later and it might even work again. I agree that this announces should be low priority tho.

[arvidn]

@skuizy what does the retry-counter say when the tracker is in a state to never be retried? normally it's counting down to the next announce. I don't know what causes deluge to say "infinite".

There was a patch briefly where a tracker failing with NXDOMAIN (host not found) would not be retried for 6 hours. That was reverted though. When you say you're on RC_1_2, you mean head of the git branch as of March 29?

[arvidn]

the invalid argument and bad filedescriptor errors seem obvious issues, I think it would make sense to address those first and see what happens.

[skuizy]

@skuizy what does the retry-counter say when the tracker is in a state to never be retried? normally it's counting down to the next announce. I don't know what causes deluge to say "infinite".

That's the retry-counter... So I suspect LT is sending deluge null, out of boundaries or not even sending anything... I didn't find anything usefull in deluge code regarding next_announce...

When you say you're on RC_1_2, you mean head of the git branch as of March 29?

That's right, I'm using this launchpad repo that builds it daily.

the invalid argument and bad filedescriptor errors seem obvious issues, I think it would make sense to address those first and see what happens.

Well... Not that obvious to me... Is something on my side causing the issue ?

[skuizy]

Running the debug console on the deluge webpage, I get the folowing response for the status tab of a stuck torrent :

[HTTP/1.1 200 OK 123ms]

	
JSON	
result	Object { tracker_host: "my_tracker", name: "my_torrent", total_remaining: 0, … }
tracker_host	"my_tracker"
name	"my_torrent"
total_remaining	0
max_download_speed	-1
time_since_transfer	158505
queue	-1
num_peers	0
completed_time	1588780036
download_location	"/media/DATA1/Vrac"
seeds_peers_ratio	-1
max_upload_speed	-1
total_peers	0
distributed_copies	0
total_uploaded	0
time_added	1588779526
upload_payload_rate	0
last_seen_complete	0
num_seeds	0
ratio	0
total_wanted	503020194
state	"Seeding"
total_seeds	28
progress	100
download_payload_rate	0
total_done	503020194
is_auto_managed	true
eta	0
active_time	83292
tracker_status	"Error: Connection timed out"
total_payload_download	0
shared	false
piece_length	524288
next_announce	0
num_pieces	960
seed_rank	35
owner	"localclient"
seeding_time	82688
total_payload_upload	0
error	null
id	49

This should be better than my previous assumptions.

[arvidn]

I wonder if the EINVAL and EBADF errors could be because too many sockets are opened that the process runs out of file descriptors. Could you try this patch? #4620

[arvidn]

likely related to:
#4851
#4884
#4886

[arvidn]

I would think #4620 fixes this issue