Tribler: all downloads regularly go to 0kb/sec

[Rik44444]

hi all,
i have an issue with Tribler: all my downloads regularly regress to 0 kb/sec. They pick up again after a while. I've tried to create logs for this to share with the developers, but even with the log option checked in the options, my log folder stays empty. What did i miss?
I'm on Windows 10, using latest stable version 7.4.4 from the Tribler.org website.
Rik

[devos50]

Thanks for the report! Does this issue still persist?

[Rik44444]

jep still happening. I'll be happy to upload an error log, as soon as you can help me figure out how to make one :P

[aaguilarjimenez]

This has started to happen to me recently too. I was on 7.4.4 and upgraded to 7.5.0-rc5, still same behavior. It stays at 0 Kb/s for a long time, hours even, then maybe after a while it finally resumes downloading, pretty fast. Sometimes closing the program and opening it up again solves it, at least momentarily.

I just upgraded my Ubuntu MATE from 19.10 to 20.04. I think it coincided with the moment in which the problem started to happen, but cannot confirm it at 100%.

Also, I remember to have had this same problem last year, but then stopped. I don't remember how or why it stopped. Possibly due to updating my Ubuntu or Tribler. I was on Ubuntu MATE 18.04 back then, with whichever was Tribler's latest version.

[synctext]

interesting.. Seems dupe of #5307

[synctext]

Seems Windows 10, Mate, and Mac users have seen this performance bug. We should try to catch this in our app stress tester infrastructure.

[ichorid]

Deluge users reported similiar problem from time to time. Apparently, Libtorrent blocking on disk i/o is the cause of this.

[ichorid]

@aaguilarjimenez , @Rik44444 , please indicate does it happen only with anonymous downloads or with non-anonymous too?

[Rik44444]

@aaguilarjimenez , @Rik44444 , please indicate does it happen only with anonymous downloads or with non-anonymous too?

sorry i've always only tried anonymous. I'll try non-anonymous next time

[aaguilarjimenez]

@aaguilarjimenez , @Rik44444 , please indicate does it happen only with anonymous downloads or with non-anonymous too?

Same as Rik44444, only ever tried with anon downloads (1 hop). I'll try to download something non-anon when my downloads are frozen and come back at you with the result...

[devos50]

We are trying to capture this nasty bug on our testing machines so hopefully we will have a solution for this issue soon.

[egbertbouman]

I have no problems with 0-hop downloads, but I am also getting regular speed drops with anonymity enabled. While this is expected to some extent, since circuits only have a limited lifetime, I often see circuits getting destroyed well before their traffic limits are met. The cause seems to be that exit nodes are destroying the circuits intentionally, because my balance is too low.

[devos50]

It could be that there are not enough slots and users are kicked out (and their circuits are thus destroyed). I'm not sure how often this problem occurs specifically but a user is likely to maintain multiple circuits with distinct exit nodes.

Can we return the reason why the circuit got destroyed to the user somehow? If we get multiple of circuit destructions within a short time, we can display a warning to the user (something like: the performance of anonymous downloads might be affected by a low token balance). This will not solve the root problem since users should be able to increase their balance again (which can currently only be done by relaying traffic), but it would inform the user at least.

[qstokkink]

Can we return the reason why the circuit got destroyed to the user somehow?

There is actually a backwards-compatible reason in the wire format for this. We should be able to extend it and deliver it to the user using the Tribler notifier in the TriblerTunnel subclass. Reference:

https://github.com/Tribler/py-ipv8/blob/c5118c3929ce2b0ed9aacdea6561b6a81283e79a/ipv8/messaging/anonymization/community.py#L433-L456

[egbertbouman]

From what I can tell by looking at the code, the most likely reason why an exit would destroy a circuit after creation is due to a low balance. Other reasons are when the exit is unloading the TunnelCommunity or when we've sent more than 50 packets to the outside world without a response. I guess the latter is also a possibility. Of course, it's best not to guess, so using reason field sound like a good idea. Currently, the reason always seems to be 0.

I realize there are almost always multiple circuits available, but switching from one circuit to the next is still going to result in a dip in speed. From what I've experienced the speed almost always goes back to 0. Balancing the load over the existing circuits seems difficult since most of the speed is often coming from a few connections.

[ichorid]

A user reported on our forum:

I was using 7.4.4 for win10. I’ve experienced a weird error these days.
At first, all of my downloads couldn’t connect any peers at all. I tried to change settings and all of that. But it didn’t work. So I tried reinstalling it. I didn’t have the luck.
So I tried 7.5.0-rc5. Now it seems that the downloads found their peers back, even though they don’t really connect with them nor download anything. But the weirdest thing happened. When I put anything to “zero hoops,” it cannot find a single seed or peer at all. Usually, without anonymity, I could download things much faster. But now anonymity mode doesn’t download things, while non-anonymity mode gives me literally nothing, not even a peer.

Currently, download got much smoother. But still, I have trouble with seeding. Once a file finishes downloading, all the seeds and peers disappear. So Tribler doesn’t seed at all after finishing it. (Of course, my setting’s at unlimited seeding.)

About the non-anonymous download, I just added a torrent, but it doesn’t connect to anything. Funny thing is when I change it into anonymous download, it connects seeds/peers and starts the download.

This is very new. Before, I used non-anonymous download because I didn’t like the speed of anonymous mode. But now the non-anonymous mode doesn’t do anything.

[egbertbouman]

@ichorid We're only seeding through e2e circuits, meaning that you can only upload to other Tribler users. Chances are that there are simply no other Tribler users downloading the torrent. So, I'm not surprised about the problems with seeding.

I've never seen a download that only works if hops>0. Not sure what's happening here.

[synctext]

Bug triggered again, now during "disk checking"!

Tribler 7.4.4 did not have this, 7.5rc5 introduces new behavior that triggers this. Not a Mac only issue, also reported by others on Linux Mate and @Rik44444 on Windows 10.

This is the last big issue we need to resolve before we can finally declare things stable and release 7.5 of Tribler. Tribler RC5 stuck on disk checking with 3 concurrent other swarms active (but not actively downloading, no IO at all, just dead swarms, stuck for _weeks_ at same download percentage). This was not simply disk checking, I deleted a file underneath Tribler. Then starting a disk check to ensure it is in sync with 0% and 100% downloaded files. Worked smoothly before on RC5, but now it triggered some sort of deadlock:

Tribler still used resources and blocked smooth VLC playback. It did not want to shutdown and got stuck (e.g. stuck while being stuck):

This started a cmdline fight with Tribler that ended with a laptop reboot. Obviously, this type of Tribler bugs drives our users away permanently. This is the reason why I'm keen on resolving this, at any cost. The kill -9 18344 did not help, it turned Tribler into a zombie :zombie:

(btw closing #5307, this is now main issue)

[ichorid]

https://github.com/arvidn/libtorrent/issues/4661 looks like our case

[ichorid]

"set_alert_notify may deadlock when called more than once"

we refactored a lot of Libtorrent-related stuff during 7.5. Another detail is that we refactored Libtorrent wrapper after moving to asyncio. That explains why we only started to experience the problem later.

@egbertbouman , could you please remember if you changed stuff related to alerts/thread during the refactoring?

[egbertbouman]

@ichorid The libtorrent wrapper does everything on the same thread. If it's a threading issue it's more likely because we're calling it from somewhere we shouldn't (i.e., not the asyncio thread).

The basics of how we get the alerts from libtorrent and how we process them are all the same.

BTW, note that we are not actually using set_alert_notify, instead we use pop_alerts to get the alerts from libtorrent.

[ichorid]

Well, that was a good attempt... Not our case.
At least we now know not to use set_alert_notify.

[ichorid]

@synctext did you use external media to store the files that got stuck? Something like a USB flash drive or a slow external HDD?

[arvidn]

ruling out set_alert_notify(), I think there are two separate symptoms left:

1. download rate dropping to zero for some time, and later recovers.
2. The whole process freezes and is unkillable

Case 1: This could have lots of different causes. The disk throughput being saturated could definitely be one of them, but also dropping peers (for whatever reason). I think a long term approach to debugging issues like this would be to have a feature where libtorrent stats counters can be enabled and recorded into a log file (i.e. post_session_stats). Those counters could be saved in a binary format to save space, but the default alert::message() function will print them in text format, which can be parsed by tools/parse_session_stats.py (in the libtorrent repo). It would record the size of the disk write queue for instance, as well as the number of bytes being written to disk.

Case 2: I'm pretty confident that this symptom always must be caused by one or more threads being "stuck" in system calls that cannot be interrupted, or in modes where they cannot be interrupted. I would expect one such case would be a write() call to disk, on a system that are under heavy memory pressure and cannot easily allocate another dirty page, and maybe has to do a lot of paging activity to find one. Normally you would expect just the disk thread to get stuck though, but there may be non-obvious dependencies that cause other threads to wait for the disk somehow. Or under such condition of the system any paging activity might cause all threads to get stuck in a page fault.

I think the most reasonable way to resolve issues like this would be to sample the process when this happens, which requires debug symbols, or at least some extent of debug symbols to resolve some of the function names. This is problematic for end-users to do, since tools for this aren't easy to come by (Mac OS and BSD has sample and I think windows task manager can sample stack traces from the context menu).

[ichorid]

@arvidn , thank you very much for the clarification. :clap:

[ichorid]

So, I tried to download some torrents on a slow USB stick (non-anonymous). There were 5 popular, highly seeded torrents. The first two I added started immediately, but the speed was very low, like 0.5-15 kb/s. But the remaining 3 torrents were stuck in "Checking" for about 5 minutes. After that, they started too, with the same low speed. This is totally reproducible. I don't know what "Checking" status means in this case.
After a couple more minutes the speed for every download will jump up to hundreds of kb/s and for some to even 2 mb/s. Then after a minute, it will again drop to a bytes per second.

@arvidn, is it normal?

[ichorid]

@Rik44444 , @aaguilarjimenez , could you please indicate what kind of media you used while experiencing the bug? Did you download directly to an external USB stick or something like that?

[arvidn]

I'm not sure what "checking" means either. libtorrent has two checking modes. Checking resume data and checking files.

Since it sounds like you didn't have these files already, it probably means checking resume data. That name is a bit misleading since it does things even when you don't have resume data.

It will stat() every file in the torrent at the specified save directory, to see if any file is there. It will also do various kinds of sanity checking of resume data, if it was provided.

If you have a torrent with a lot of files to be stat()ed on a slow drive, I suppose that could take a long time. 5 minutes sounds very long though. It normally takes a fraction of a second. However, if any files were found. it would transition into file-checking mode, where it actually has to read all data from the files and check their hashes.

Whether it's normal or not, I don't know. It probably depends on what the bottleneck is.

[synctext]

yes, relatively slow external USB.
plus: this was a fault when data file checking..

[ichorid]

@synctext , we've seen exactly the same problem last year with your laptop using a slow external USB flash drive. I was able to reproduce it today by using a slow external drive. Checking was basically stuck. Also, as pointed out by @arvidn, "Checking" at 0% means libtorrent is trying to stat() the files at the disk in question. If the disk is very busy with i/o, it will probably block.

Was it a USB Flash drive or an HDD? what model (controller, etc.)? what filesystem does it use? Did you try to use it simultaneously with some other process accessing it, e.g. watching Tribler VLC streaming from it?

[ichorid]

@synctext , also, could it be that your GigaChannel database was on the same USB drive? Was Tribler processing/downloading some channels at that moment (especially, big ones)?

[synctext]

with 7.4.4 this checking never gave issues, plus no 0kbps issues with healthy big swarms. no idea on Channel parsing activity. This should be inside Tribler RC6 debug panel then please, channel inserts in last seconds.

[synctext]

btw channel.db is inside .Tribler dir on fast SSD, not on slower USB used for bulk swarm storage.

Reproduced, coool!

[ichorid]

Reliably reproduced on Windows 10 with both 7.4.4 and 7.5. Note that DHT checking works!

Downloads are stuck for the first few minutes after adding them, then resume.

[ichorid]

I suspect this is not one, but several problems resulting in slightly different, albeit very similar effects.
The first one has something to do with DHT - peers connecting.
The second one is about libtorrent getting stuck due to slow disk access.

[arvidn]

Is the USB stick formatted with FAT by any chance? i.e. not supporting sparse files?

[synctext]

yes! Dos format, Linux and Mac compatible. But again, it used to work fine.

[arvidn]

is the difference libtorrent-1.1.x and libtorrent-1.2.x?

[arvidn]

I ran a test downloading a large file into a usb stick on linux using client_test (a pretty thin wrapper around libtorrent).

Here area few observations:

• I can reproduce the stall (where the debugger is even stuck stopping the process, supporting the thesis that it's blocked in a long-running system call).

• While running the download, I don't see any stalls, just when I stop the download. My interpretation of this is that Linux fills-in the non-sparse file lazily. i.e. writing the last byte in a large file doesn't itself block while filling the file with zeroes, but it's filled in when the file is closed. This has also been my experience on MacOS on HFS+.

• when disk is busy allocating the file, it's very easy to also lock up the foreground thread by accessing the disk, even for a very small file, can block. in client_test the foreground thread saves resume data files (which are very small), but still causes the user interface to lock up.

In the past, libtorrent used to have a dedicated thread just to close files (here), specifically for this reason. It doesn't anymore though, and maybe it was a mistake to remove that. Although, this was removed such time long ago that I find it unlikely this is what's affecting you.

A few ways I can think of to mitigate this would be to:

• increase the file pool size. This would (presumably) cause files to be closed less often. And if a non-sparse file is closed after it has been fully "filled-in", it's cheap.

• increase the number of disk I/O threads, which would allow more threads to be blocked in closing files, while still making progress in other threads.

It seems this ticket is mostly about windows, and I don't feel confident assuming windows has the same behavior as I've experienced on Linux and Mac OS, but this might at least help with ideas of what's going on.

[ichorid]

@arvidn , thank you very much for your insights! This thread now seems to be about multiple issues that manifest differently on different platforms, but any of them results in 0kb/s downloads.

• The Mac problem reported by @synctext seems to be caused by the sparse file / slow USB disk.
• The Windows problem is different though. I'll try to get you some Libtorrent stats ASAP.

[ichorid]

Latest 7.5-rc5, Win10, Libtorrent version 1.2.1.
Run Tribler, add 3 highly popular torrents by infohashes. Names resolved fine. Then torrents got stuck at "Waiting for metainfo" and remain like that for half an hour.
Here are the Libtorrent session stats. Note that there are several Channels torrents in the background, already downloaded and seeded, zero connections.

Libtrorrent stats

"dht.dht_allocated_observers" : 0,
"dht.dht_announce_peer_in" : 2,
"dht.dht_announce_peer_out" : 16,
"dht.dht_bytes_in" : 112105,
"dht.dht_bytes_out" : 163770,
"dht.dht_find_node_in" : 10,
"dht.dht_find_node_out" : 0,
"dht.dht_get_in" : 0,
"dht.dht_get_out" : 0,
"dht.dht_get_peers_in" : 76,
"dht.dht_get_peers_out" : 1291,
"dht.dht_immutable_data" : 0,
"dht.dht_invalid_announce" : 0,
"dht.dht_invalid_find_node" : 0,
"dht.dht_invalid_get" : 0,
"dht.dht_invalid_get_peers" : 0,
"dht.dht_invalid_put" : 0,
"dht.dht_invalid_sample_infohashes" : 0,
"dht.dht_messages_in" : 485,
"dht.dht_messages_in_dropped" : 64,
"dht.dht_messages_out" : 1401,
"dht.dht_messages_out_dropped" : 0,
"dht.dht_mutable_data" : 0,
"dht.dht_node_cache" : 74,
"dht.dht_nodes" : 186,
"dht.dht_peers" : 2,
"dht.dht_ping_in" : 0,
"dht.dht_ping_out" : 6,
"dht.dht_put_in" : 0,
"dht.dht_put_out" : 0,
"dht.dht_sample_infohashes_in" : 0,
"dht.dht_sample_infohashes_out" : 0,
"dht.dht_torrents" : 2,
"disk.arc_mfu_ghost_size" : 0,
"disk.arc_mfu_size" : 0,
"disk.arc_mru_ghost_size" : 0,
"disk.arc_mru_size" : 489,
"disk.arc_volatile_size" : 0,
"disk.arc_write_size" : 0,
"disk.blocked_disk_jobs" : 0,
"disk.disk_blocks_in_use" : 1955,
"disk.disk_hash_time" : 80606,
"disk.disk_job_time" : 122801,
"disk.disk_read_time" : 0,
"disk.disk_write_time" : 42195,
"disk.num_blocks_cache_hits" : 0,
"disk.num_blocks_hashed" : 1955,
"disk.num_blocks_read" : 0,
"disk.num_blocks_written" : 1955,
"disk.num_fenced_check_fastresume" : 0,
"disk.num_fenced_clear_piece" : 0,
"disk.num_fenced_delete_files" : 0,
"disk.num_fenced_file_priority" : 0,
"disk.num_fenced_flush_hashed" : 0,
"disk.num_fenced_flush_piece" : 0,
"disk.num_fenced_flush_storage" : 0,
"disk.num_fenced_hash" : 0,
"disk.num_fenced_load_torrent" : 0,
"disk.num_fenced_move_storage" : 0,
"disk.num_fenced_read" : 0,
"disk.num_fenced_release_files" : 0,
"disk.num_fenced_rename_file" : 0,
"disk.num_fenced_save_resume_data" : 0,
"disk.num_fenced_stop_torrent" : 0,
"disk.num_fenced_tick_storage" : 0,
"disk.num_fenced_trim_cache" : 0,
"disk.num_fenced_write" : 0,
"disk.num_jobs" : 0,
"disk.num_read_back" : 0,
"disk.num_read_jobs" : 0,
"disk.num_read_ops" : 0,
"disk.num_running_disk_jobs" : 0,
"disk.num_running_threads" : 0,
"disk.num_write_jobs" : 0,
"disk.num_write_ops" : 489,
"disk.num_writing_threads" : 0,
"disk.pinned_blocks" : 0,
"disk.queued_disk_jobs" : 0,
"disk.queued_write_bytes" : 0,
"disk.read_cache_blocks" : 1955,
"disk.request_latency" : 0,
"disk.write_cache_blocks" : 0,
"net.has_incoming_connections" : 1,
"net.limiter_down_bytes" : 0,
"net.limiter_down_queue" : 0,
"net.limiter_up_bytes" : 0,
"net.limiter_up_queue" : 0,
"net.on_accept_counter" : 3,
"net.on_disk_counter" : 531,
"net.on_disk_queue_counter" : 0,
"net.on_lsd_counter" : 0,
"net.on_lsd_peer_counter" : 11451,
"net.on_read_counter" : 3402,
"net.on_tick_counter" : 528,
"net.on_udp_counter" : 13243,
"net.on_write_counter" : 10356,
"net.recv_bytes" : 34188365,
"net.recv_failed_bytes" : 0,
"net.recv_ip_overhead_bytes" : 1438800,
"net.recv_payload_bytes" : 34110239,
"net.recv_redundant_bytes" : 2081941,
"net.recv_tracker_bytes" : 0,
"net.sent_bytes" : 423562,
"net.sent_ip_overhead_bytes" : 1492448,
"net.sent_payload_bytes" : 0,
"net.sent_tracker_bytes" : 0,
"peer.aborted_peers" : 0,
"peer.addrinuse_peers" : 0,
"peer.banned_for_hash_failure" : 0,
"peer.boost_connection_attempts" : 66,
"peer.broken_pipe_peers" : 0,
"peer.buffer_peers" : 0,
"peer.cancelled_piece_requests" : 0,
"peer.choked_piece_requests" : 0,
"peer.connaborted_peers" : 0,
"peer.connection_attempt_loops" : 23011,
"peer.connection_attempts" : 626,
"peer.connect_timeouts" : 321,
"peer.connrefused_peers" : 4,
"peer.connreset_peers" : 19,
"peer.disconnected_peers" : 687,
"peer.eof_peers" : 33,
"peer.error_encrypted_peers" : 0,
"peer.error_incoming_peers" : 0,
"peer.error_outgoing_peers" : 41,
"peer.error_peers" : 0,
"peer.error_rc4_peers" : 0,
"peer.error_tcp_peers" : 40,
"peer.error_utp_peers" : 1,
"peer.incoming_connections" : 1,
"peer.invalid_arg_peers" : 0,
"peer.invalid_piece_requests" : 0,
"peer.max_piece_requests" : 0,
"peer.missed_connection_attempts" : 0,
"peer.no_access_peers" : 0,
"peer.no_memory_peers" : 0,
"peer.no_peer_connection_attempts" : 3373,
"peer.notconnected_peers" : 0,
"peer.num_banned_peers" : 0,
"peer.num_http_proxy_peers" : 0,
"peer.num_i2p_peers" : 0,
"peer.num_peers_connected" : 6,
"peer.num_peers_down_disk" : 0,
"peer.num_peers_down_interested" : 0,
"peer.num_peers_down_requests" : 55,
"peer.num_peers_down_unchoked" : 0,
"peer.num_peers_end_game" : 0,
"peer.num_peers_half_open" : 0,
"peer.num_peers_up_disk" : 0,
"peer.num_peers_up_interested" : 0,
"peer.num_peers_up_requests" : 0,
"peer.num_peers_up_unchoked" : 0,
"peer.num_peers_up_unchoked_all" : 0,
"peer.num_peers_up_unchoked_optimistic" : 0,
"peer.num_socks5_peers" : 0,
"peer.num_ssl_http_proxy_peers" : 0,
"peer.num_ssl_peers" : 0,
"peer.num_ssl_socks5_peers" : 0,
"peer.num_ssl_utp_peers" : 0,
"peer.num_tcp_peers" : 6,
"peer.num_utp_peers" : 0
"peer.perm_peers" : 0,
"peer.piece_rejects" : 0,
"peer.piece_requests" : 0,
"peer.timeout_peers" : 0,
"peer.too_many_peers" : 0,
"peer.transport_timeout_peers" : 301,
"peer.uninteresting_peers" : 14,
"peer.unreachable_peers" : 0,
"picker.end_game_piece_picks" : 0,
"picker.hash_fail_piece_picks" : 0,
"picker.incoming_piece_picks" : 610,
"picker.incoming_redundant_piece_picks" : 95,
"picker.interesting_piece_picks" : 132,
"picker.piece_picker_busy_loops" : 336,
"picker.piece_picker_partial_loops" : 9,
"picker.piece_picker_rand_loops" : 0,
"picker.piece_picker_rand_start_loops" : 329,
"picker.piece_picker_rare_loops" : 52,
"picker.piece_picker_reverse_rare_loops" : 0,
"picker.piece_picker_sequential_loops" : 0,
"picker.piece_picker_suggest_loops" : 0,
"picker.reject_piece_picks" : 0,
"picker.snubbed_piece_picks" : 0,
"picker.unchoke_piece_picks" : 77,
"ses.non_filter_torrents" : 9,
"ses.num_checking_torrents" : 0,
"ses.num_downloading_torrents" : 3,
"ses.num_error_torrents" : 0,
"ses.num_have_pieces" : 502,
"ses.num_incoming_allowed_fast" : 0,
"ses.num_incoming_bitfield" : 0,
"ses.num_incoming_cancel" : 0,
"ses.num_incoming_choke" : 5,
"ses.num_incoming_dht_port" : 75,
"ses.num_incoming_extended" : 190,
"ses.num_incoming_ext_handshake" : 101,
"ses.num_incoming_have" : 0,
"ses.num_incoming_have_all" : 0,
"ses.num_incoming_have_none" : 0,
"ses.num_incoming_interested" : 0,
"ses.num_incoming_metadata" : 9,
"ses.num_incoming_not_interested" : 0,
"ses.num_incoming_pex" : 72,
"ses.num_incoming_piece" : 2065,
"ses.num_incoming_reject" : 0,
"ses.num_incoming_request" : 0,
"ses.num_incoming_suggest" : 0,
"ses.num_incoming_unchoke" : 144,
"ses.num_outgoing_allowed_fast" : 0,
"ses.num_outgoing_bitfield" : 126,
"ses.num_outgoing_cancel" : 347,
"ses.num_outgoing_choke" : 19,
"ses.num_outgoing_dht_port" : 89,
"ses.num_outgoing_extended" : 174,
"ses.num_outgoing_ext_handshake" : 101,
"ses.num_outgoing_have" : 30394,
"ses.num_outgoing_have_all" : 14,
"ses.num_outgoing_have_none" : 31,
"ses.num_outgoing_interested" : 78,
"ses.num_outgoing_metadata" : 17,
"ses.num_outgoing_not_interested" : 78,
"ses.num_outgoing_pex" : 79,
"ses.num_outgoing_piece" : 0,
"ses.num_outgoing_reject" : 0,
"ses.num_outgoing_request" : 2130,
"ses.num_outgoing_suggest" : 0,
"ses.num_outgoing_unchoke" : 42,
"ses.num_outstanding_accept" : 1,
"ses.num_piece_failed" : 0,
"ses.num_piece_passed" : 502,
"ses.num_queued_download_torrents" : 0,
"ses.num_queued_seeding_torrents" : 0,
"ses.num_seeding_torrents" : 6,
"ses.num_stopped_torrents" : 0,
"ses.num_total_pieces_added" : 502,
"ses.num_unchoke_slots" : 8,
"ses.num_upload_only_torrents" : 0,
"ses.torrent_evicted_counter" : 0,
"ses.waste_piece_cancelled" : 0,
"ses.waste_piece_closing" : 282123,
"ses.waste_piece_end_game" : 1261568,
"ses.waste_piece_seed" : 0,
"ses.waste_piece_timed_out" : 16384,
"ses.waste_piece_unknown" : 521866,
"sock_bufs.socket_recv_size10" : 828,
"sock_bufs.socket_recv_size11" : 379,
"sock_bufs.socket_recv_size12" : 249,
"sock_bufs.socket_recv_size13" : 214,
"sock_bufs.socket_recv_size14" : 395,
"sock_bufs.socket_recv_size15" : 449,
"sock_bufs.socket_recv_size16" : 20,
"sock_bufs.socket_recv_size17" : 0,
"sock_bufs.socket_recv_size18" : 0,
"sock_bufs.socket_recv_size19" : 0,
"sock_bufs.socket_recv_size20" : 0,
"sock_bufs.socket_recv_size3" : 244,
"sock_bufs.socket_recv_size4" : 36,
"sock_bufs.socket_recv_size5" : 46,
"sock_bufs.socket_recv_size6" : 199,
"sock_bufs.socket_recv_size7" : 126,
"sock_bufs.socket_recv_size8" : 155,
"sock_bufs.socket_recv_size9" : 84,
"sock_bufs.socket_send_size10" : 0,
"sock_bufs.socket_send_size11" : 0,
"sock_bufs.socket_send_size12" : 0,
"sock_bufs.socket_send_size13" : 0,
"sock_bufs.socket_send_size14" : 0,
"sock_bufs.socket_send_size15" : 0,
"sock_bufs.socket_send_size16" : 0,
"sock_bufs.socket_send_size17" : 0,
"sock_bufs.socket_send_size18" : 0,
"sock_bufs.socket_send_size19" : 0,
"sock_bufs.socket_send_size20" : 0,
"sock_bufs.socket_send_size3" : 5934,
"sock_bufs.socket_send_size4" : 1253,
"sock_bufs.socket_send_size5" : 1294,
"sock_bufs.socket_send_size6" : 1100,
"sock_bufs.socket_send_size7" : 529,
"sock_bufs.socket_send_size8" : 168,
"sock_bufs.socket_send_size9" : 78,
"utp.num_utp_close_wait" : 0,
"utp.num_utp_connected" : 0,
"utp.num_utp_deleted" : 0,
"utp.num_utp_fin_sent" : 0,
"utp.num_utp_idle" : 0,
"utp.num_utp_syn_sent" : 0,
"utp.utp_fast_retransmit" : 0,
"utp.utp_invalid_pkts_in" : 0,
"utp.utp_packet_loss" : 0,
"utp.utp_packet_resend" : 114,
"utp.utp_packets_in" : 33719,
"utp.utp_packets_out" : 21163,
"utp.utp_payload_pkts_in" : 26065,
"utp.utp_payload_pkts_out" : 7652,
"utp.utp_redundant_pkts_in" : 96,
"utp.utp_samples_above_target" : 94,
"utp.utp_samples_below_target" : 7443,
"utp.utp_timeout" : 403,

Libtrorrent settings

"active_checking" : 1,
"active_dht_limit" : 88,
"active_downloads" : 3,
"active_limit" : 500,
"active_loaded_limit" : 0,
"active_lsd_limit" : 60,
"active_seeds" : 5,
"active_tracker_limit" : 1600,
"aio_max" : 300,
"aio_threads" : 4,
"alert_mask" : 1,
"alert_queue_size" : 1000,
"allowed_enc_level" : 3,
"allowed_fast_set_size" : 5,
"allow_i2p_mixed" : false,
"allow_multiple_connections_per_ip" : 0,
"allow_partial_disk_writes" : true,
"always_send_user_agent" : false,
"announce_crypto_support" : true,
"announce_double_nat" : false,
"announce_ip" : "",
"announce_to_all_tiers" : false,
"announce_to_all_trackers" : false,
"anonymous_mode" : false,
"apply_ip_filter_to_trackers" : true,
"auto_manage_interval" : 30,
"auto_manage_prefer_seeds" : false,
"auto_manage_startup" : 60,
"auto_scrape_interval" : 1800,
"auto_scrape_min_interval" : 300,
"auto_sequential" : true,
"ban_web_seeds" : true,
"broadcast_lsd" : true,
"cache_buffer_chunk_size" : 0,
"cache_expiry" : 300,
"cache_size" : 2048,
"cache_size_volatile" : 256,
"checking_mem_usage" : 1024,
"choking_algorithm" : 0,
"close_file_interval" : 120,
"close_redundant_connections" : true,
"coalesce_reads" : true,
"coalesce_writes" : true,
"connections_limit" : 200,
"connection_speed" : 30,
"connections_slack" : 10,
"connect_seed_every_n_download" : 10,
"contiguous_recv_buffer" : true,
"decrease_est_reciprocation_rate" : 3,
"default_cache_min_age" : 1,
"default_est_reciprocation_rate" : 16000,
"dht_announce_interval" : 900,
"dht_bootstrap_nodes" : "dht.libtorrent.org:25401",
"dht_upload_rate_limit" : 4000,
"disable_hash_checks" : false,
"disk_io_read_mode" : 0,
"disk_io_write_mode" : 0,
"dont_count_slow_torrents" : true,
"dont_flush_write_cache" : false,
"download_rate_limit" : 0,
"enable_dht" : false,
"enable_incoming_tcp" : true,
"enable_incoming_utp" : true,
"enable_ip_notifier" : true,
"enable_lsd" : false,
"enable_natpmp" : false,
"enable_outgoing_tcp" : true,
"enable_outgoing_utp" : true,
"enable_upnp" : false,
"file_checks_delay_per_block" : 0,
"file_pool_size" : 40,
"force_proxy" : false,
"guided_read_cache" : false,
"half_open_limit" : 0,
"handshake_client_version" : "Tribler/7.5.0-rc5-14-g7b166f0d7/...",
"handshake_timeout" : 10,
"hashing_threads" : 1,
"i2p_hostname" : "",
"i2p_port" : 0,
"ignore_limits_on_local_network" : true,
"ignore_resume_timestamps" : false,
"inactive_down_rate" : 2048,
"inactive_up_rate" : 2048,
"inactivity_timeout" : 600,
"incoming_starts_queued_torrents" : false,
"increase_est_reciprocation_rate" : 20,
"in_enc_policy" : 1,
"initial_picker_threshold" : 4,
"lazy_bitfields" : false,
"listen_interfaces" : "0.0.0.0:15670",
"listen_queue_size" : 5,
"listen_system_port_fallback" : true,
"local_download_rate_limit" : 0,
"local_service_announce_interval" : 300,
"local_upload_rate_limit" : 0,
"lock_disk_cache" : false,
"lock_files" : false,
"low_prio_disk" : true,
"max_allowed_in_request_queue" : 500,
"max_failcount" : 3,
"max_http_recv_buffer_size" : 835584,
"max_metadata_size" : 31457280,
"max_out_request_queue" : 500,
"max_paused_peerlist_size" : 1000,
"max_peerlist_size" : 3000,
"max_peer_recv_buffer_size" : 2097152,
"max_pex_peers" : 50,
"max_queued_disk_bytes" : 1048576,
"max_rejects" : 50,
"max_retry_port_bind" : 10,
"max_suggest_pieces" : 16,
"max_web_seed_connections" : 3,
"min_announce_interval" : 300,
"min_reconnect_time" : 60,
"mixed_mode_algorithm" : 1,
"mmap_cache" : "",
"network_threads" : 0,
"no_atime_storage" : true,
"no_connect_privileged_ports" : false,
"no_recheck_incomplete_resume" : false,
"num_optimistic_unchoke_slots" : 0,
"num_outgoing_ports" : 1,
"num_want" : 200,
"optimistic_disk_retry" : 600,
"optimistic_unchoke_interval" : 30,
"out_enc_policy" : 1,
"outgoing_interfaces" : "",
"outgoing_port" : 0,
"peer_connect_timeout" : 15,
"peer_fingerprint" : "...",
"peer_timeout" : 120,
"peer_tos" : 32,
"peer_turnover" : 4,
"peer_turnover_cutoff" : 90,
"peer_turnover_interval" : 300,
"piece_timeout" : 20,
"predictive_piece_announce" : 0,
"prefer_rc4" : true,
"prefer_udp_trackers" : true,
"prioritize_partial_pieces" : false,
"proxy_hostname" : "",
"proxy_hostnames" : true,
"proxy_password" : "",
"proxy_peer_connections" : true,
"proxy_port" : 0,
"proxy_tracker_connections" : true,
"proxy_type" : 0,
"proxy_username" : "",
"rate_limit_ip_overhead" : true,
"rate_limit_utp" : true,
"read_cache_line_size" : 32,
"recv_socket_buffer_size" : 0,
"report_redundant_bytes" : true,
"report_true_downloaded" : false,
"report_web_seed_downloads" : true,
"request_queue_time" : 3,
"request_timeout" : 60,
"resolver_cache_timeout" : 1200,
"seed_choking_algorithm" : 0,
"seeding_outgoing_connections" : true,
"seeding_piece_quota" : 20,
"seed_time_limit" : 86400,
"seed_time_ratio_limit" : 700,
"send_buffer_low_watermark" : 10240,
"send_buffer_watermark" : 512000,
"send_buffer_watermark_factor" : 50,
"send_redundant_have" : true,
"send_socket_buffer_size" : 0,
"share_mode_target" : 3,
"share_ratio_limit" : 200,
"smooth_connects" : true,
"ssl_listen" : 0,
"stop_tracker_timeout" : 5,
"strict_end_game_mode" : true,
"strict_super_seeding" : false,
"suggest_mode" : 0,
"support_merkle_torrents" : true,
"support_share_mode" : true,
"tick_interval" : 500,
"torrent_connect_boost" : 30,
"tracker_backoff" : 250,
"tracker_completion_timeout" : 30,
"tracker_maximum_response_length" : 1048576,
"tracker_receive_timeout" : 10,
"udp_tracker_token_expiry" : 60,
"unchoke_interval" : 15,
"unchoke_slots_limit" : 8,
"upload_rate_limit" : 0,
"upnp_ignore_nonrouters" : false,
"urlseed_max_request_bytes" : 16777216,
"urlseed_pipeline_size" : 5,
"urlseed_timeout" : 20,
"urlseed_wait_retry" : 30,
"use_dht_as_fallback" : false,
"use_disk_cache_pool" : false,
"use_disk_read_ahead" : true,
"use_parole_mode" : true,
"user_agent" : "...",
"use_read_cache" : true,
"use_write_cache" : true,
"utp_connect_timeout" : 3000,
"utp_cwnd_reduce_timer" : 100,
"utp_delayed_ack" : 0,
"utp_fin_resends" : 2,
"utp_gain_factor" : 3000,
"utp_loss_multiplier" : 50,
"utp_min_timeout" : 500,
"utp_num_resends" : 3
"utp_syn_resends" : 2,
"utp_target_delay" : 100,
"volatile_read_cache" : false,
"web_seed_name_lookup_retry" : 1800,
"whole_pieces_threshold" : 20,
"write_cache_line_size" : 16,

@arvidn , can you make something out of these stats?

[ichorid]

Also, I noticed that I cannot reproduce this bug on my PC unless I have another instance of Tribler running on my seedbox in the same subnet at my home, behind the same NAT.
Tribler running on the seedbox -> the bug triggers sometimes on the PC.
Tribler not running on the seedox -> the bug does not trigger on the PC.

@synctext , could it be that another instance of Tribler or another torrent client was running in your home network when you witnessed the freeze?

[arvidn]

those counters suggest that the DHT was properly bootstrapped and connected to the network. They also suggested that there were peers connected, and no peers failing with an error (which I would have expected if there were some issue with the ut_metadata extension, that downloads the .torrent from peers). It's not obvious what's going on. Enabling logging would probably help.

[ichorid]

@arvidn , is it possible to enable Libtorrent logging from Python bindings?

[arvidn]

yes, set the alert_mask setting to include the peer_log_notification flag (documented here)

[ichorid]

BTW, I've checked Libtorrent versions used in our latest releases:

| | MacOS | Win64 |
|-----------------|-------|-------|
| Tribler 7.4.4 | 1.2.2 | 1.2.1 |
| Tribler 7.5-rc5 | 1.2.2 | 1.2.1 |

[ichorid]

:skull: Can't reproduce it anymore :skull:
Dozens of restarts, everything runs perfectly on the same PC where yesterday it was triggered every second run :dizzy_face:

I suspect it is only triggered by a very specific race condition. In that case, using stable, deterministic environments (like VMs and app tester) will not suffice.
To catch it for good, we'll probably have to produce a specialized "debug" release with enabled debug symbols, full logging and a watchdog that will automatically send the last 5 minutes of logs and some kind of Libtorrent stack trace to the Reporter server.

[ichorid]

Accidentally reproduced on Ubuntu at home (Libtorrent 1.2.2):

[ichorid]

You know what's funny? When I restarted Tribler, only the OpenSUSE torrent was downloading. Ubuntu was in a "stopped" state. :thinking:

[egbertbouman]

@ichorid Not sure why a download would be "stopped" directly after adding it. Are you sure that you didn't try to stop the download while it was still waiting for the metainfo?

I just did some testing, and it could be that the problem with the download being stuck in "Waiting for metadata" is because we're not receiving any peers from the DHT. To test this I added a call to force_dht_announce at the bottom of Download.on_add_torrent_alert, and the download seems to start a lot faster. Could possibly be due to the fact we just did a DHT request when we opened the download dialog.

[ichorid]

@egbertbouman , I'm sure I did not press the "stop" button before closing Tribler. Also, I had disabled the download dialog through the settings menu beforehand to reduce the amount of clicking...

[ichorid]

Another detail: when just adding a download, for a brief moment it will show "1(0)" or "30(0)" peers before showing 0 and getting stuck permanently.

[egbertbouman]

I just tried to see if disabling the download dialog also fixes the problem I'm having, but it doesn't. If I don't use force_dht_announce I consistently get a delay of a few minutes (using 0 hops).

[ichorid]

One of the downloads got unstuck after a few minutes. Though the download sees only a single peer and is thus very slow. The torrent is a healthy one, it got thousands of peers (I use it regularly for testing).

@arvidn , what could make Libtorrent ignore other peers and only use one?

Here are some session stats (for this run I disabled Libtorrent logging, unfortunately):

Libtorrent stats

"dht.dht_allocated_observers" : 1
"dht.dht_announce_peer_in" : 36,
"dht.dht_announce_peer_out" : 8,
"dht.dht_bytes_in" : 338130,
"dht.dht_bytes_out" : 652219,
"dht.dht_find_node_in" : 196,
"dht.dht_find_node_out" : 0,
"dht.dht_get_in" : 0,
"dht.dht_get_out" : 0,
"dht.dht_get_peers_in" : 1630,
"dht.dht_get_peers_out" : 718,
"dht.dht_immutable_data" : 0,
"dht.dht_invalid_announce" : 0,
"dht.dht_invalid_find_node" : 0,
"dht.dht_invalid_get" : 0,
"dht.dht_invalid_get_peers" : 0,
"dht.dht_invalid_put" : 0,
"dht.dht_invalid_sample_infohashes" : 0,
"dht.dht_messages_in" : 2371,
"dht.dht_messages_in_dropped" : 2,
"dht.dht_messages_out" : 2644,
"dht.dht_messages_out_dropped" : 0,
"dht.dht_mutable_data" : 0,
"dht.dht_node_cache" : 119,
"dht.dht_nodes" : 191,
"dht.dht_peers" : 36,
"dht.dht_ping_in" : 14,
"dht.dht_ping_out" : 21,
"dht.dht_put_in" : 0,
"dht.dht_put_out" : 0,
"dht.dht_sample_infohashes_in" : 0,
"dht.dht_sample_infohashes_out" : 0,
"dht.dht_torrents" : 18,
"disk.arc_mfu_ghost_size" : 0,
"disk.arc_mfu_size" : 0,
"disk.arc_mru_ghost_size" : 32,
"disk.arc_mru_size" : 62,
"disk.arc_volatile_size" : 0,
"disk.arc_write_size" : 1,
"disk.blocked_disk_jobs" : 0,
"disk.disk_blocks_in_use" : 1993,
"disk.disk_hash_time" : 198127,
"disk.disk_job_time" : 267741,
"disk.disk_read_time" : 0,
"disk.disk_write_time" : 69614,
"disk.num_blocks_cache_hits" : 0,
"disk.num_blocks_hashed" : 3817,
"disk.num_blocks_read" : 0,
"disk.num_blocks_written" : 3808,
"disk.num_fenced_check_fastresume" : 0,
"disk.num_fenced_clear_piece" : 0,
"disk.num_fenced_delete_files" : 0,
"disk.num_fenced_file_priority" : 0,
"disk.num_fenced_flush_hashed" : 0,
"disk.num_fenced_flush_piece" : 0,
"disk.num_fenced_flush_storage" : 0,
"disk.num_fenced_hash" : 0,
"disk.num_fenced_load_torrent" : 0,
"disk.num_fenced_move_storage" : 0,
"disk.num_fenced_read" : 0,
"disk.num_fenced_release_files" : 0,
"disk.num_fenced_rename_file" : 0,
"disk.num_fenced_save_resume_data" : 0,
"disk.num_fenced_stop_torrent" : 0,
"disk.num_fenced_tick_storage" : 0,
"disk.num_fenced_trim_cache" : 0,
"disk.num_fenced_write" : 0,
"disk.num_jobs" : 9,
"disk.num_read_back" : 0,
"disk.num_read_jobs" : 0,
"disk.num_read_ops" : 0,
"disk.num_running_disk_jobs" : 0,
"disk.num_running_threads" : 3,
"disk.num_write_jobs" : 9,
"disk.num_write_ops" : 238,
"disk.num_writing_threads" : 0,
"disk.pinned_blocks" : 0,
"disk.queued_disk_jobs" : 0,
"disk.queued_write_bytes" : 147456,
"disk.read_cache_blocks" : 1984,
"disk.request_latency" : 0,
"disk.write_cache_blocks" : 9,
"net.has_incoming_connections" : 1,
"net.limiter_down_bytes" : 0,
"net.limiter_down_queue" : 0,
"net.limiter_up_bytes" : 0,
"net.limiter_up_queue" : 0,
"net.on_accept_counter" : 210,
"net.on_disk_counter" : 4073,
"net.on_disk_queue_counter" : 0,
"net.on_lsd_counter" : 32,
"net.on_lsd_peer_counter" : 48478,
"net.on_read_counter" : 42775,
"net.on_tick_counter" : 2043,
"net.on_udp_counter" : 4143,
"net.on_write_counter" : 4318,
"net.recv_bytes" : 62712526,
"net.recv_failed_bytes" : 0,
"net.recv_ip_overhead_bytes" : 2072188,
"net.recv_payload_bytes" : 62552396,
"net.recv_redundant_bytes" : 0,
"net.recv_tracker_bytes" : 0,
"net.sent_bytes" : 125703,
"net.sent_ip_overhead_bytes" : 2091252,
"net.sent_payload_bytes" : 0,
"net.sent_tracker_bytes" : 0,
"peer.aborted_peers" : 0,
"peer.addrinuse_peers" : 0,
"peer.banned_for_hash_failure" : 0,
"peer.boost_connection_attempts" : 90,
"peer.broken_pipe_peers" : 0,
"peer.buffer_peers" : 0,
"peer.cancelled_piece_requests" : 0,
"peer.choked_piece_requests" : 0,
"peer.connaborted_peers" : 0,
"peer.connection_attempt_loops" : 24696,
"peer.connection_attempts" : 159,
"peer.connect_timeouts" : 102,
"peer.connrefused_peers" : 3,
"peer.connreset_peers" : 17,
"peer.disconnected_peers" : 704,
"peer.eof_peers" : 110,
"peer.error_encrypted_peers" : 0,
"peer.error_incoming_peers" : 322,
"peer.error_outgoing_peers" : 27,
"peer.error_peers" : 0,
"peer.error_rc4_peers" : 0,
"peer.error_tcp_peers" : 198,
"peer.error_utp_peers" : 151,
"peer.incoming_connections" : 458,
"peer.invalid_arg_peers" : 0,
"peer.invalid_piece_requests" : 0,
"peer.max_piece_requests" : 0,
"peer.missed_connection_attempts" : 0,
"peer.no_access_peers" : 0,
"peer.no_memory_peers" : 0,
"peer.no_peer_connection_attempts" : 6969,
"peer.notconnected_peers" : 0,
"peer.num_banned_peers" : 9,
"peer.num_http_proxy_peers" : 0,
"peer.num_i2p_peers" : 0,
"peer.num_peers_connected" : 3,
"peer.num_peers_down_disk" : 0,
"peer.num_peers_down_interested" : 1,
"peer.num_peers_down_requests" : 1,
"peer.num_peers_down_unchoked" : 1,
"peer.num_peers_end_game" : 0,
"peer.num_peers_half_open" : 0,
"peer.num_peers_up_disk" : 0,
"peer.num_peers_up_interested" : 0,
"peer.num_peers_up_requests" : 0,
"peer.num_peers_up_unchoked" : 0,
"peer.num_peers_up_unchoked_all" : 0,
"peer.num_peers_up_unchoked_optimistic" : 0,
"peer.num_socks5_peers" : 0,
"peer.num_ssl_http_proxy_peers" : 0,
"peer.num_ssl_peers" : 0,
"peer.num_ssl_socks5_peers" : 0,
"peer.num_ssl_utp_peers" : 0,
"peer.num_tcp_peers" : 2,
"peer.num_utp_peers" : 1,
"peer.perm_peers" : 0,
"peer.piece_rejects" : 0,
"peer.piece_requests" : 0,
"peer.timeout_peers" : 0,
"peer.too_many_peers" : 0,
"peer.transport_timeout_peers" : 89,
"peer.uninteresting_peers" : 19,
"peer.unreachable_peers" : 0,
"picker.end_game_piece_picks" : 0,
"picker.hash_fail_piece_picks" : 0,
"picker.incoming_piece_picks" : 35,
"picker.incoming_redundant_piece_picks" : 0,
"picker.interesting_piece_picks" : 1,
"picker.piece_picker_busy_loops" : 0,
"picker.piece_picker_partial_loops" : 13,
"picker.piece_picker_rand_loops" : 128,
"picker.piece_picker_rand_start_loops" : 3087,
"picker.piece_picker_rare_loops" : 19,
"picker.piece_picker_reverse_rare_loops" : 0,
"picker.piece_picker_sequential_loops" : 0,
"picker.piece_picker_suggest_loops" : 0,
"picker.reject_piece_picks" : 0,
"picker.snubbed_piece_picks" : 0,
"picker.unchoke_piece_picks" : 0,
"ses.non_filter_torrents" : 13,
"ses.num_checking_torrents" : 0,
"ses.num_downloading_torrents" : 3,
"ses.num_error_torrents" : 0,
"ses.num_have_pieces" : 205,
"ses.num_incoming_allowed_fast" : 0,
"ses.num_incoming_bitfield" : 3,
"ses.num_incoming_cancel" : 0,
"ses.num_incoming_choke" : 0,
"ses.num_incoming_dht_port" : 1,
"ses.num_incoming_extended" : 425,
"ses.num_incoming_ext_handshake" : 116,
"ses.num_incoming_have" : 0,
"ses.num_incoming_have_all" : 0,
"ses.num_incoming_have_none" : 0,
"ses.num_incoming_interested" : 0,
"ses.num_incoming_metadata" : 106,
"ses.num_incoming_not_interested" : 2,
"ses.num_incoming_pex" : 100,
"ses.num_incoming_piece" : 3817,
"ses.num_incoming_reject" : 0,
"ses.num_incoming_request" : 0,
"ses.num_incoming_suggest" : 0,
"ses.num_incoming_unchoke" : 1,
"ses.num_outgoing_allowed_fast" : 0,
"ses.num_outgoing_bitfield" : 2,
"ses.num_outgoing_cancel" : 10,
"ses.num_outgoing_choke" : 3,
"ses.num_outgoing_dht_port" : 15,
"ses.num_outgoing_extended" : 312,
"ses.num_outgoing_ext_handshake" : 129,
"ses.num_outgoing_have" : 119,
"ses.num_outgoing_have_all" : 19,
"ses.num_outgoing_have_none" : 1,
"ses.num_outgoing_interested" : 1,
"ses.num_outgoing_metadata" : 213,
"ses.num_outgoing_not_interested" : 0,
"ses.num_outgoing_pex" : 98,
"ses.num_outgoing_piece" : 0,
"ses.num_outgoing_reject" : 0,
"ses.num_outgoing_request" : 3857,
"ses.num_outgoing_suggest" : 0,
"ses.num_outgoing_unchoke" : 21,
"ses.num_outstanding_accept" : 1,
"ses.num_piece_failed" : 0,
"ses.num_piece_passed" : 205,
"ses.num_queued_download_torrents" : 0,
"ses.num_queued_seeding_torrents" : 0,
"ses.num_seeding_torrents" : 8,
"ses.num_stopped_torrents" : 0,
"ses.num_total_pieces_added" : 3261,
"ses.num_unchoke_slots" : 8,
"ses.num_upload_only_torrents" : 2,
"ses.torrent_evicted_counter" : 0,
"ses.waste_piece_cancelled" : 0,
"ses.waste_piece_closing" : 0,
"ses.waste_piece_end_game" : 0,
"ses.waste_piece_seed" : 0,
"ses.waste_piece_timed_out" : 0,
"ses.waste_piece_unknown" : 0,
"sock_bufs.socket_recv_size10" : 38528,
"sock_bufs.socket_recv_size11" : 2508,
"sock_bufs.socket_recv_size12" : 58,
"sock_bufs.socket_recv_size13" : 16,
"sock_bufs.socket_recv_size14" : 22,
"sock_bufs.socket_recv_size15" : 3,
"sock_bufs.socket_recv_size16" : 0,
"sock_bufs.socket_recv_size17" : 0,
"sock_bufs.socket_recv_size18" : 0,
"sock_bufs.socket_recv_size19" : 0,
"sock_bufs.socket_recv_size20" : 0,
"sock_bufs.socket_recv_size3" : 115,
"sock_bufs.socket_recv_size4" : 79,
"sock_bufs.socket_recv_size5" : 53,
"sock_bufs.socket_recv_size6" : 688,
"sock_bufs.socket_recv_size7" : 171,
"sock_bufs.socket_recv_size8" : 161,
"sock_bufs.socket_recv_size9" : 341,
"sock_bufs.socket_send_size10" : 0,
"sock_bufs.socket_send_size11" : 0,
"sock_bufs.socket_send_size12" : 0,
"sock_bufs.socket_send_size13" : 0,
"sock_bufs.socket_send_size14" : 0,
"sock_bufs.socket_send_size15" : 0,
"sock_bufs.socket_send_size16" : 0,
"sock_bufs.socket_send_size17" : 0,
"sock_bufs.socket_send_size18" : 0,
"sock_bufs.socket_send_size19" : 0,
"sock_bufs.socket_send_size20" : 0,
"sock_bufs.socket_send_size3" : 217,
"sock_bufs.socket_send_size4" : 3478,
"sock_bufs.socket_send_size5" : 218,
"sock_bufs.socket_send_size6" : 235,
"sock_bufs.socket_send_size7" : 24,
"sock_bufs.socket_send_size8" : 133,
"sock_bufs.socket_send_size9" : 13,
"utp.num_utp_close_wait" : 0,
"utp.num_utp_connected" : 1,
"utp.num_utp_deleted" : 0,
"utp.num_utp_fin_sent" : 0,
"utp.num_utp_idle" : 0,
"utp.num_utp_syn_sent" : 0,
"utp.utp_fast_retransmit" : 0,
"utp.utp_invalid_pkts_in" : 0,
"utp.utp_packet_loss" : 0,
"utp.utp_packet_resend" : 14,
"utp.utp_packets_in" : 1393,
"utp.utp_packets_out" : 1494,
"utp.utp_payload_pkts_in" : 541,
"utp.utp_payload_pkts_out" : 373,
"utp.utp_redundant_pkts_in" : 108,
"utp.utp_samples_above_target" : 0,
"utp.utp_samples_below_target" : 334,
"utp.utp_timeout" : 291,

EDIT:
while I was typing this, another peer was added to the download:

EDIT2:
while watchin the thing download I noticed something suspicious: all the clients that were connectied were either Libtorrent based, or 0% completed, no speed, no client-identifier string. After the download stopped, the list of peers looked like this:

Also, while downloading, I started a virtual machine (bridged) with another Tribler instance and started the same download. It started normally, lots of peers, etc. The 1st Tribler instance was immediately able to see the 2nd one and started to leech from it full-speed.

EDIT3:
After a few hours the peers list still looks strange:

Some more Libtorrent stats after an hour of seeding stuck:

Libtorrent stats

"dht.dht_allocated_observers" : 3,
"dht.dht_announce_peer_in" : 313,
"dht.dht_announce_peer_out" : 8,
"dht.dht_bytes_in" : 1542646,
"dht.dht_bytes_out" : 3191438,
"dht.dht_find_node_in" : 1885,
"dht.dht_find_node_out" : 0,
"dht.dht_get_in" : 0,
"dht.dht_get_out" : 0,
"dht.dht_get_peers_in" : 7058,
"dht.dht_get_peers_out" : 2563,
"dht.dht_immutable_data" : 0,
"dht.dht_invalid_announce" : 0,
"dht.dht_invalid_find_node" : 0,
"dht.dht_invalid_get" : 0,
"dht.dht_invalid_get_peers" : 0,
"dht.dht_invalid_put" : 0,
"dht.dht_invalid_sample_infohashes" : 0,
"dht.dht_messages_in" : 12387,
"dht.dht_messages_in_dropped" : 1299,
"dht.dht_messages_out" : 12449,
"dht.dht_messages_out_dropped" : 0,
"dht.dht_mutable_data" : 0,
"dht.dht_node_cache" : 175,
"dht.dht_nodes" : 339,
"dht.dht_peers" : 76,
"dht.dht_ping_in" : 135,
"dht.dht_ping_out" : 291,
"dht.dht_put_in" : 0,
"dht.dht_put_out" : 0,
"dht.dht_sample_infohashes_in" : 74,
"dht.dht_sample_infohashes_out" : 0,
"dht.dht_torrents" : 29,
"disk.arc_mfu_ghost_size" : 0,
"disk.arc_mfu_size" : 0,
"disk.arc_mru_ghost_size" : 32,
"disk.arc_mru_size" : 73,
"disk.arc_volatile_size" : 0,
"disk.arc_write_size" : 0,
"disk.blocked_disk_jobs" : 0,
"disk.disk_blocks_in_use" : 2002,
"disk.disk_hash_time" : 5091226,
"disk.disk_job_time" : 6919958,
"disk.disk_read_time" : 44892,
"disk.disk_write_time" : 1783840,
"disk.num_blocks_cache_hits" : 5206,
"disk.num_blocks_hashed" : 101600,
"disk.num_blocks_read" : 5681,
"disk.num_blocks_written" : 101600,
"disk.num_fenced_check_fastresume" : 0,
"disk.num_fenced_clear_piece" : 0,
"disk.num_fenced_delete_files" : 0,
"disk.num_fenced_file_priority" : 0,
"disk.num_fenced_flush_hashed" : 0,
"disk.num_fenced_flush_piece" : 0,
"disk.num_fenced_flush_storage" : 0,
"disk.num_fenced_hash" : 0,
"disk.num_fenced_load_torrent" : 0,
"disk.num_fenced_move_storage" : 0,
"disk.num_fenced_read" : 0,
"disk.num_fenced_release_files" : 0,
"disk.num_fenced_rename_file" : 0,
"disk.num_fenced_save_resume_data" : 0,
"disk.num_fenced_stop_torrent" : 0,
"disk.num_fenced_tick_storage" : 0,
"disk.num_fenced_trim_cache" : 0,
"disk.num_fenced_write" : 0,
"disk.num_jobs" : 0,
"disk.num_read_back" : 0,
"disk.num_read_jobs" : 0,
"disk.num_read_ops" : 188,
"disk.num_running_disk_jobs" : 0,
"disk.num_running_threads" : 0,
"disk.num_write_jobs" : 0,
"disk.num_write_ops" : 6327,
"disk.num_writing_threads" : 0,
"disk.pinned_blocks" : 0,
"disk.queued_disk_jobs" : 0,
"disk.queued_write_bytes" : 0,
"disk.read_cache_blocks" : 2002,
"disk.request_latency" : 0,
"disk.write_cache_blocks" : 0,
"net.has_incoming_connections" : 1,
"net.limiter_down_bytes" : 0,
"net.limiter_down_queue" : 0,
"net.limiter_up_bytes" : 0,
"net.limiter_up_queue" : 0,
"net.on_accept_counter" : 864,
"net.on_disk_counter" : 106829,
"net.on_disk_queue_counter" : 0,
"net.on_lsd_counter" : 255,
"net.on_lsd_peer_counter" : 279858,
"net.on_read_counter" : 1078629,
"net.on_tick_counter" : 12463,
"net.on_udp_counter" : 799217,
"net.on_write_counter" : 110058,
"net.recv_bytes" : 1668814134,
"net.recv_failed_bytes" : 0,
"net.recv_ip_overhead_bytes" : 54007476,
"net.recv_payload_bytes" : 1667116196,
"net.recv_redundant_bytes" : 2501796,
"net.recv_tracker_bytes" : 0,
"net.sent_bytes" : 90148238,
"net.sent_ip_overhead_bytes" : 54073112,
"net.sent_payload_bytes" : 87838382,
"net.sent_tracker_bytes" : 0,
"peer.aborted_peers" : 0,
"peer.addrinuse_peers" : 0,
"peer.banned_for_hash_failure" : 0,
"peer.boost_connection_attempts" : 303,
"peer.broken_pipe_peers" : 0,
"peer.buffer_peers" : 0,
"peer.cancelled_piece_requests" : 0,
"peer.choked_piece_requests" : 0,
"peer.connaborted_peers" : 0,
"peer.connection_attempt_loops" : 225746,
"peer.connection_attempts" : 1068,
"peer.connect_timeouts" : 513,
"peer.connrefused_peers" : 12,
"peer.connreset_peers" : 103,
"peer.disconnected_peers" : 3151,
"peer.eof_peers" : 623,
"peer.error_encrypted_peers" : 0,
"peer.error_incoming_peers" : 1295,
"peer.error_outgoing_peers" : 77,
"peer.error_peers" : 0,
"peer.error_rc4_peers" : 0,
"peer.error_tcp_peers" : 699,
"peer.error_utp_peers" : 673,
"peer.incoming_connections" : 1796,
"peer.invalid_arg_peers" : 0,
"peer.invalid_piece_requests" : 0,
"peer.max_piece_requests" : 0,
"peer.missed_connection_attempts" : 0,
"peer.no_access_peers" : 0,
"peer.no_memory_peers" : 0,
"peer.no_peer_connection_attempts" : 40704,
"peer.notconnected_peers" : 0,
"peer.num_banned_peers" : 62,
"peer.num_http_proxy_peers" : 0,
"peer.num_i2p_peers" : 0,
"peer.num_peers_connected" : 17,
"peer.num_peers_down_disk" : 0,
"peer.num_peers_down_interested" : 0,
"peer.num_peers_down_requests" : 24,
"peer.num_peers_down_unchoked" : 0,
"peer.num_peers_end_game" : 0,
"peer.num_peers_half_open" : 0,
"peer.num_peers_up_disk" : 0,
"peer.num_peers_up_interested" : 0,
"peer.num_peers_up_requests" : 2,
"peer.num_peers_up_unchoked" : 0,
"peer.num_peers_up_unchoked_all" : 0,
"peer.num_peers_up_unchoked_optimistic" : 0,
"peer.num_socks5_peers" : 0,
"peer.num_ssl_http_proxy_peers" : 0,
"peer.num_ssl_peers" : 0,
"peer.num_ssl_socks5_peers" : 0,
"peer.num_ssl_utp_peers" : 0,
"peer.num_tcp_peers" : 17,
"peer.num_utp_peers" : 0,
"peer.perm_peers" : 0,
"peer.piece_rejects" : 0,
"peer.piece_requests" : 5800,
"peer.timeout_peers" : 0,
"peer.too_many_peers" : 0,
"peer.transport_timeout_peers" : 346,
"peer.uninteresting_peers" : 86,
"peer.unreachable_peers" : 0,
"picker.end_game_piece_picks" : 0,
"picker.hash_fail_piece_picks" : 0,
"picker.incoming_piece_picks" : 1128,
"picker.incoming_redundant_piece_picks" : 66,
"picker.interesting_piece_picks" : 14,
"picker.piece_picker_busy_loops" : 297,
"picker.piece_picker_partial_loops" : 151,
"picker.piece_picker_rand_loops" : 128,
"picker.piece_picker_rand_start_loops" : 3087,
"picker.piece_picker_rare_loops" : 118811,
"picker.piece_picker_reverse_rare_loops" : 0,
"picker.piece_picker_sequential_loops" : 0,
"picker.piece_picker_suggest_loops" : 80,
"picker.reject_piece_picks" : 4,
"picker.snubbed_piece_picks" : 0,
"picker.unchoke_piece_picks" : 28,
"ses.non_filter_torrents" : 13,
"ses.num_checking_torrents" : 0,
"ses.num_downloading_torrents" : 2,
"ses.num_error_torrents" : 0,
"ses.num_have_pieces" : 3261,
"ses.num_incoming_allowed_fast" : 0,
"ses.num_incoming_bitfield" : 12,
"ses.num_incoming_cancel" : 0,
"ses.num_incoming_choke" : 7,
"ses.num_incoming_dht_port" : 25,
"ses.num_incoming_extended" : 1654,
"ses.num_incoming_ext_handshake" : 475,
"ses.num_incoming_have" : 998,
"ses.num_incoming_have_all" : 0,
"ses.num_incoming_have_none" : 0,
"ses.num_incoming_interested" : 2,
"ses.num_incoming_metadata" : 430,
"ses.num_incoming_not_interested" : 2,
"ses.num_incoming_pex" : 319,
"ses.num_incoming_piece" : 101744,
"ses.num_incoming_reject" : 0,
"ses.num_incoming_request" : 5800,
"ses.num_incoming_suggest" : 0,
"ses.num_incoming_unchoke" : 47,
"ses.num_outgoing_allowed_fast" : 5,
"ses.num_outgoing_bitfield" : 56,
"ses.num_outgoing_cancel" : 30,
"ses.num_outgoing_choke" : 26,
"ses.num_outgoing_dht_port" : 42,
"ses.num_outgoing_extended" : 1179,
"ses.num_outgoing_ext_handshake" : 508,
"ses.num_outgoing_have" : 13095,
"ses.num_outgoing_have_all" : 38,
"ses.num_outgoing_have_none" : 1,
"ses.num_outgoing_interested" : 28,
"ses.num_outgoing_metadata" : 860,
"ses.num_outgoing_not_interested" : 26,
"ses.num_outgoing_pex" : 289,
"ses.num_outgoing_piece" : 5530,
"ses.num_outgoing_reject" : 0,
"ses.num_outgoing_request" : 102027,
"ses.num_outgoing_suggest" : 0,
"ses.num_outgoing_unchoke" : 67,
"ses.num_outstanding_accept" : 1,
"ses.num_piece_failed" : 0,
"ses.num_piece_passed" : 3261,
"ses.num_queued_download_torrents" : 0,
"ses.num_queued_seeding_torrents" : 0,
"ses.num_seeding_torrents" : 8,
"ses.num_stopped_torrents" : 0,
"ses.num_total_pieces_added" : 3261,
"ses.num_unchoke_slots" : 8,
"ses.num_upload_only_torrents" : 3,
"ses.torrent_evicted_counter" : 0,
"ses.waste_piece_cancelled" : 0,
"ses.waste_piece_closing" : 142500,
"ses.waste_piece_end_game" : 1032192,
"ses.waste_piece_seed" : 0,
"ses.waste_piece_timed_out" : 16384,
"ses.waste_piece_unknown" : 1310720,
"sock_bufs.socket_recv_size10" : 1017017,
"sock_bufs.socket_recv_size11" : 38973,
"sock_bufs.socket_recv_size12" : 1974,
"sock_bufs.socket_recv_size13" : 452,
"sock_bufs.socket_recv_size14" : 286,
"sock_bufs.socket_recv_size15" : 120,
"sock_bufs.socket_recv_size16" : 94,
"sock_bufs.socket_recv_size17" : 100,
"sock_bufs.socket_recv_size18" : 36,
"sock_bufs.socket_recv_size19" : 17,
"sock_bufs.socket_recv_size20" : 1,
"sock_bufs.socket_recv_size3" : 1105,
"sock_bufs.socket_recv_size4" : 505,
"sock_bufs.socket_recv_size5" : 493,
"sock_bufs.socket_recv_size6" : 3224,
"sock_bufs.socket_recv_size7" : 1184,
"sock_bufs.socket_recv_size8" : 1269,
"sock_bufs.socket_recv_size9" : 12412,
"sock_bufs.socket_send_size10" : 641,
"sock_bufs.socket_send_size11" : 95,
"sock_bufs.socket_send_size12" : 88,
"sock_bufs.socket_send_size13" : 187,
"sock_bufs.socket_send_size14" : 620,
"sock_bufs.socket_send_size15" : 302,
"sock_bufs.socket_send_size16" : 357,
"sock_bufs.socket_send_size17" : 115,
"sock_bufs.socket_send_size18" : 15,
"sock_bufs.socket_send_size19" : 0,
"sock_bufs.socket_send_size20" : 0,
"sock_bufs.socket_send_size3" : 15091
"sock_bufs.socket_send_size4" : 85871,
"sock_bufs.socket_send_size5" : 3335,
"sock_bufs.socket_send_size6" : 1682,
"sock_bufs.socket_send_size7" : 623,
"sock_bufs.socket_send_size8" : 834,
"sock_bufs.socket_send_size9" : 202,
"utp.num_utp_close_wait" : 0,
"utp.num_utp_connected" : 0,
"utp.num_utp_deleted" : 0,
"utp.num_utp_fin_sent" : 0,
"utp.num_utp_idle" : 0,
"utp.num_utp_syn_sent" : 0,
"utp.utp_fast_retransmit" : 2327,
"utp.utp_invalid_pkts_in" : 0,
"utp.utp_packet_loss" : 548,
"utp.utp_packet_resend" : 2601,
"utp.utp_packets_in" : 817018,
"utp.utp_packets_out" : 854578,
"utp.utp_payload_pkts_in" : 809009,
"utp.utp_payload_pkts_out" : 70920,
"utp.utp_redundant_pkts_in" : 555,
"utp.utp_samples_above_target" : 82,
"utp.utp_samples_below_target" : 12907,
"utp.utp_timeout" : 1055,

uTP stats look strange to me :thinking:

[ichorid]

I started a Wireshark session capturing the exchange of packets between the stuck Tribler instance and the external world.
One of the uTP sessions captured:

@arvidn , is it normal for Libtorrent to regularly send to other peers Timestamp Difference of ff ff f3 db microseconds? If it could help, I can send you the whole capture.

Another conversation. Does it look normal?

[ichorid]

Changed anonymity to 1 hop on one of the downloads, it started to download:

The list of peers looks normal too.

So, the problem is either local to Libtorrent session, or have something to do with NAT traversal.

[ichorid]

Kept Tribler running overnight, all downloads finished, newly added torrents download fine. :man_shrugging:

Stats after the night:

Libtorrent stats

"dht.dht_allocated_observers" : 397,
"dht.dht_announce_peer_in" : 4497,
"dht.dht_announce_peer_out" : 2152,
"dht.dht_bytes_in" : 21490288,
"dht.dht_bytes_out" : 47431209,
"dht.dht_find_node_in" : 37467,
"dht.dht_find_node_out" : 0,
"dht.dht_get_in" : 0,
"dht.dht_get_out" : 0,
"dht.dht_get_peers_in" : 87688,
"dht.dht_get_peers_out" : 51610,
"dht.dht_immutable_data" : 0,
"dht.dht_invalid_announce" : 76,
"dht.dht_invalid_find_node" : 0,
"dht.dht_invalid_get" : 0,
"dht.dht_invalid_get_peers" : 10,
"dht.dht_invalid_put" : 0,
"dht.dht_invalid_sample_infohashes" : 0,
"dht.dht_messages_in" : 178853,
"dht.dht_messages_in_dropped" : 12798,
"dht.dht_messages_out" : 200013,
"dht.dht_messages_out_dropped" : 5,
"dht.dht_mutable_data" : 0,
"dht.dht_node_cache" : 177,
"dht.dht_nodes" : 383,
"dht.dht_peers" : 140,
"dht.dht_ping_in" : 8122,
"dht.dht_ping_out" : 6127,
"dht.dht_put_in" : 0,
"dht.dht_put_out" : 0,
"dht.dht_sample_infohashes_in" : 1504,
"dht.dht_sample_infohashes_out" : 0,
"dht.dht_torrents" : 81,
"disk.arc_mfu_ghost_size" : 0,
"disk.arc_mfu_size" : 0,
"disk.arc_mru_ghost_size" : 0,
"disk.arc_mru_size" : 0,
"disk.arc_volatile_size" : 0,
"disk.arc_write_size" : 0,
"disk.blocked_disk_jobs" : 0,
"disk.disk_blocks_in_use" : 0,
"disk.disk_hash_time" : 20561734,
"disk.disk_job_time" : 31731884,
"disk.disk_read_time" : 1089913,
"disk.disk_write_time" : 10080237,
"disk.num_blocks_cache_hits" : 9027,
"disk.num_blocks_hashed" : 419476,
"disk.num_blocks_read" : 17408,
"disk.num_blocks_written" : 424939,
"disk.num_fenced_check_fastresume" : 0,
"disk.num_fenced_clear_piece" : 0,
"disk.num_fenced_delete_files" : 0,
"disk.num_fenced_file_priority" : 0,
"disk.num_fenced_flush_hashed" : 0,
"disk.num_fenced_flush_piece" : 0,
"disk.num_fenced_flush_storage" : 0,
"disk.num_fenced_hash" : 0,
"disk.num_fenced_load_torrent" : 0,
"disk.num_fenced_move_storage" : 0,
"disk.num_fenced_read" : 0,
"disk.num_fenced_release_files" : 0,
"disk.num_fenced_rename_file" : 0,
"disk.num_fenced_save_resume_data" : 0,
"disk.num_fenced_stop_torrent" : 0,
"disk.num_fenced_tick_storage" : 0,
"disk.num_fenced_trim_cache" : 0,
"disk.num_fenced_write" : 0,
"disk.num_jobs" : 0,
"disk.num_read_back" : 1784,
"disk.num_read_jobs" : 0,
"disk.num_read_ops" : 2337,
"disk.num_running_disk_jobs" : 0,
"disk.num_running_threads" : 4,
"disk.num_write_jobs" : 0,
"disk.num_write_ops" : 26451,
"disk.num_writing_threads" : 0,
"disk.pinned_blocks" : 0,
"disk.queued_disk_jobs" : 0,
"disk.queued_write_bytes" : 0,
"disk.read_cache_blocks" : 0,
"disk.request_latency" : 0,
"disk.write_cache_blocks" : 0,
"net.has_incoming_connections" : 1,
"net.limiter_down_bytes" : 0,
"net.limiter_down_queue" : 0,
"net.limiter_up_bytes" : 0,
"net.limiter_up_queue" : 0,
"net.on_accept_counter" : 13490,
"net.on_disk_counter" : 415445,
"net.on_disk_queue_counter" : 0,
"net.on_lsd_counter" : 889,
"net.on_lsd_peer_counter" : 286780,
"net.on_read_counter" : 3829398,
"net.on_tick_counter" : 99580,
"net.on_udp_counter" : 3672116,
"net.on_write_counter" : 757311,
"net.recv_bytes" : 6986940034,
"net.recv_failed_bytes" : 524288,
"net.recv_ip_overhead_bytes" : 253428724,
"net.recv_payload_bytes" : 6976265288,
"net.recv_redundant_bytes" : 14366795,
"net.recv_tracker_bytes" : 1706,
"net.sent_bytes" : 176973443,
"net.sent_ip_overhead_bytes" : 254552384,
"net.sent_payload_bytes" : 156297511,
"net.sent_tracker_bytes" : 1645,
"peer.aborted_peers" : 0,
"peer.addrinuse_peers" : 0,
"peer.banned_for_hash_failure" : 0,
"peer.boost_connection_attempts" : 1377,
"peer.broken_pipe_peers" : 1,
"peer.buffer_peers" : 0,
"peer.cancelled_piece_requests" : 181,
"peer.choked_piece_requests" : 6,
"peer.connaborted_peers" : 0,
"peer.connection_attempt_loops" : 19488928,
"peer.connection_attempts" : 11658,
"peer.connect_timeouts" : 7414,
"peer.connrefused_peers" : 601,
"peer.connreset_peers" : 435,
"peer.disconnected_peers" : 46090,
"peer.eof_peers" : 2934,
"peer.error_encrypted_peers" : 0,
"peer.error_incoming_peers" : 20870,
"peer.error_outgoing_peers" : 3174,
"peer.error_peers" : 29,
"peer.error_rc4_peers" : 0,
"peer.error_tcp_peers" : 10301,
"peer.error_utp_peers" : 13743,
"peer.incoming_connections" : 33073,
"peer.invalid_arg_peers" : 0,
"peer.invalid_piece_requests" : 0,
"peer.max_piece_requests" : 0,
"peer.missed_connection_attempts" : 0,
"peer.no_access_peers" : 0,
"peer.no_memory_peers" : 0,
"peer.no_peer_connection_attempts" : 246114,
"peer.notconnected_peers" : 0,
"peer.num_banned_peers" : 63,
"peer.num_http_proxy_peers" : 0,
"peer.num_i2p_peers" : 0,
"peer.num_peers_connected" : 6,
"peer.num_peers_down_disk" : 0,
"peer.num_peers_down_interested" : 0,
"peer.num_peers_down_requests" : 771,
"peer.num_peers_down_unchoked" : 0,
"peer.num_peers_end_game" : 0,
"peer.num_peers_half_open" : 15,
"peer.num_peers_up_disk" : 0,
"peer.num_peers_up_interested" : 0,
"peer.num_peers_up_requests" : 22,
"peer.num_peers_up_unchoked" : 0,
"peer.num_peers_up_unchoked_all" : 0,
"peer.num_peers_up_unchoked_optimistic" : 0,
"peer.num_socks5_peers" : 0,
"peer.num_ssl_http_proxy_peers" : 0,
"peer.num_ssl_peers" : 0,
"peer.num_ssl_socks5_peers" : 0,
"peer.num_ssl_utp_peers" : 0,
"peer.num_tcp_peers" : 16,
"peer.num_utp_peers" : 12,
"peer.perm_peers" : 0,
"peer.piece_rejects" : 187,
"peer.piece_requests" : 10453,
"peer.timeout_peers" : 17,
"peer.too_many_peers" : 1,
"peer.transport_timeout_peers" : 7408,
"peer.uninteresting_peers" : 10677,
"peer.unreachable_peers" : 87,
"picker.end_game_piece_picks" : 0,
"picker.hash_fail_piece_picks" : 0,
"picker.incoming_piece_picks" : 19526,
"picker.incoming_redundant_piece_picks" : 216,
"picker.interesting_piece_picks" : 5416,
"picker.piece_picker_busy_loops" : 7796,
"picker.piece_picker_partial_loops" : 19115,
"picker.piece_picker_rand_loops" : 4320,
"picker.piece_picker_rand_start_loops" : 911150,
"picker.piece_picker_rare_loops" : 4952547,
"picker.piece_picker_reverse_rare_loops" : 1120,
"picker.piece_picker_sequential_loops" : 0,
"picker.piece_picker_suggest_loops" : 10503,
"picker.reject_piece_picks" : 65,
"picker.snubbed_piece_picks" : 0,
"picker.unchoke_piece_picks" : 759
"ses.non_filter_torrents" : 30,
"ses.num_checking_torrents" : 0,
"ses.num_downloading_torrents" : 0,
"ses.num_error_torrents" : 0,
"ses.num_have_pieces" : 20888,
"ses.num_incoming_allowed_fast" : 0,
"ses.num_incoming_bitfield" : 1077,
"ses.num_incoming_cancel" : 516,
"ses.num_incoming_choke" : 63,
"ses.num_incoming_dht_port" : 1020,
"ses.num_incoming_extended" : 14661,
"ses.num_incoming_ext_handshake" : 11756,
"ses.num_incoming_have" : 34668,
"ses.num_incoming_have_all" : 0,
"ses.num_incoming_have_none" : 0,
"ses.num_incoming_interested" : 97,
"ses.num_incoming_metadata" : 757,
"ses.num_incoming_not_interested" : 24,
"ses.num_incoming_pex" : 1041,
"ses.num_incoming_piece" : 425464,
"ses.num_incoming_reject" : 0,
"ses.num_incoming_request" : 10453,
"ses.num_incoming_suggest" : 0,
"ses.num_incoming_unchoke" : 1129,
"ses.num_outgoing_allowed_fast" : 52,
"ses.num_outgoing_bitfield" : 2232,
"ses.num_outgoing_cancel" : 1960,
"ses.num_outgoing_choke" : 2773,
"ses.num_outgoing_dht_port" : 9001,
"ses.num_outgoing_extended" : 3184,
"ses.num_outgoing_ext_handshake" : 12282,
"ses.num_outgoing_have" : 355185,
"ses.num_outgoing_have_all" : 10362,
"ses.num_outgoing_have_none" : 316,
"ses.num_outgoing_interested" : 969,
"ses.num_outgoing_metadata" : 1376,
"ses.num_outgoing_not_interested" : 78,
"ses.num_outgoing_pex" : 1533,
"ses.num_outgoing_piece" : 10203,
"ses.num_outgoing_reject" : 84,
"ses.num_outgoing_request" : 479234,
"ses.num_outgoing_suggest" : 0,
"ses.num_outgoing_unchoke" : 11030,
"ses.num_outstanding_accept" : 1,
"ses.num_piece_failed" : 1,
"ses.num_piece_passed" : 20888,
"ses.num_queued_download_torrents" : 0,
"ses.num_queued_seeding_torrents" : 0,
"ses.num_seeding_torrents" : 10,
"ses.num_stopped_torrents" : 0,
"ses.num_total_pieces_added" : 76258,
"ses.num_unchoke_slots" : 8,
"ses.num_upload_only_torrents" : 20,
"ses.torrent_evicted_counter" : 0,
"ses.waste_piece_cancelled" : 0,
"ses.waste_piece_closing" : 5699659,
"ses.waste_piece_end_game" : 2949120,
"ses.waste_piece_seed" : 0,
"ses.waste_piece_timed_out" : 1458176,
"ses.waste_piece_unknown" : 4259840,
"sock_bufs.socket_recv_size10" : 2773534,
"sock_bufs.socket_recv_size11" : 460429,
"sock_bufs.socket_recv_size12" : 144090,
"sock_bufs.socket_recv_size13" : 18952,
"sock_bufs.socket_recv_size14" : 5022,
"sock_bufs.socket_recv_size15" : 1166,
"sock_bufs.socket_recv_size16" : 649,
"sock_bufs.socket_recv_size17" : 468,
"sock_bufs.socket_recv_size18" : 349,
"sock_bufs.socket_recv_size19" : 237,
"sock_bufs.socket_recv_size20" : 55,
"sock_bufs.socket_recv_size3" : 6250,
"sock_bufs.socket_recv_size4" : 4928,
"sock_bufs.socket_recv_size5" : 4866,
"sock_bufs.socket_recv_size6" : 54941,
"sock_bufs.socket_recv_size7" : 19743,
"sock_bufs.socket_recv_size8" : 16254,
"sock_bufs.socket_recv_size9" : 350545,
"sock_bufs.socket_send_size10" : 8354,
"sock_bufs.socket_send_size11" : 1921,
"sock_bufs.socket_send_size12" : 1701,
"sock_bufs.socket_send_size13" : 1070,
"sock_bufs.socket_send_size14" : 1956,
"sock_bufs.socket_send_size15" : 508,
"sock_bufs.socket_send_size16" : 388,
"sock_bufs.socket_send_size17" : 121,
"sock_bufs.socket_send_size18" : 17,
"sock_bufs.socket_send_size19" : 0,
"sock_bufs.socket_send_size20" : 0,
"sock_bufs.socket_send_size3" : 347212,
"sock_bufs.socket_send_size4" : 284679,
"sock_bufs.socket_send_size5" : 59510,
"sock_bufs.socket_send_size6" : 10424,
"sock_bufs.socket_send_size7" : 8527,
"sock_bufs.socket_send_size8" : 25444,
"sock_bufs.socket_send_size9" : 5479,
"utp.num_utp_close_wait" : 3,
"utp.num_utp_connected" : 6,
"utp.num_utp_deleted" : 1,
"utp.num_utp_fin_sent" : 3,
"utp.num_utp_idle" : 0,
"utp.num_utp_syn_sent" : 5,
"utp.utp_fast_retransmit" : 3362,
"utp.utp_invalid_pkts_in" : 41,
"utp.utp_packet_loss" : 1286,
"utp.utp_packet_resend" : 6158,
"utp.utp_packets_in" : 6172832,
"utp.utp_packets_out" : 3968989,
"utp.utp_payload_pkts_in" : 5985767,
"utp.utp_payload_pkts_out" : 214153,
"utp.utp_redundant_pkts_in" : 54781,
"utp.utp_samples_above_target" : 907,
"utp.utp_samples_below_target" : 139177,
"utp.utp_timeout" : 24793,

[arvidn]

is it normal for Libtorrent to regularly send to other peers Timestamp Difference of ff ff f3 db microseconds?

Yes, the timestamp difference is the difference between the sender's and the receiver's clocks. They aren't synchronized so the difference is mostly a non-sensical value. However, it's very useful to monitor changes over time. The assumption in uTP's congestion control is that the clocks won't drift too much, so the change in this diff represents changes in buffering along the network path.

Regarding the libtorrent stats, some of those numbers are "counters", meaning they are cumulative and monotonic. Some of them are "gauges" meaning they are instantaneous snapshots of the current state (say, the number of uTP connections in a certain state, right now). The counters are mostly useful when collecting multiple samples and comparing them over time.

[ichorid]

@arvidn , would you be able to figure out what's happening if I send you a Wireshark capture of Tribler stuck trying to download the torrents? Also, what could have caused the behaviour on the screenshots above, namely Tribler connecting only to the 0% nameless clients?

[arvidn]

I could give it a shot. It’s all direct peer connections, not encrypted nor over a proxy, right?

[arvidn]

I wrote this tool a while back which might be useful: https://github.com/arvidn/bittorrent-trace

[ichorid]

@arvidn , I appliet your bittorrent-trace utility to the exchange file of the stuck Tribler instance.
Aside from other peers requesting metainfo for test torrents I used to run previously, there a dir with the relevant (ubuntu) infohash.

Aside from a single exchange, all captures looked like this:

>> 1591212017.149 HANDSHAKE
>> 1591212017.149 RESERVED 0000000000180005
>> 1591212017.149 INFO-HASH ee55335f2acde309fa645fab11c04750d7e45fa1
>> 1591212017.149 PEER-ID 0920dc71b767d3bfe956e469b5a144b712079088 [. .q.g...V.i..D.....]
<< 1591212017.624 FIN
>> 1591212017.624 FIN

The single non-trivial exchange was:

Exchange

>> 1591212149.120 HANDSHAKE
>> 1591212149.120 RESERVED 0000000000180005
>> 1591212149.120 INFO-HASH ee55335f2acde309fa645fab11c04750d7e45fa1
>> 1591212149.120 PEER-ID 0920dc71b767d3bfe956e469b5a144b712079088 [. .q.g...V.i..D.....]
<< 1591212149.248 HANDSHAKE
<< 1591212149.248 RESERVED 0000000000100005
<< 1591212149.248 INFO-HASH ee55335f2acde309fa645fab11c04750d7e45fa1
<< 1591212149.248 PEER-ID 2d4254376135532d5db24d457b03e331caaa59eb [-BT7a5S-].ME{..1..Y.]
>> 1591212149.248 EXTENSION-HANDSHAKE {
'complete_ago': 480,
'm': { 'lt_donthave': 7, 'share_mode': 8, 'upload_only': 3, 'ut_holepunch': 4, 'ut_metadata': 2, 'ut_pex': 1 },
'metadata_size': 63600,
'reqq': 500,
'upload_only': 1,
'v': 'Tribler/7.5.0-GIT/0920dc71b767d3bfe956e469b5a144b712079088',
'yourip': '%\x06\xff\x06'
}
>> 1591212149.248 HAVE-ALL
>> 1591212149.248 UNCHOKE
<< 1591212149.370 EXTENSION-HANDSHAKE {
'e': 0,
'ipv4': '%\x06\xff\x06',
'complete_ago': 2,
'm': { 'upload_only': 3, 'lt_donthave': 7, 'ut_holepunch': 4, 'ut_metadata': 2, 'ut_pex': 1, 'ut_comment': 6 },
'metadata_size': 63600,
'p': 15857,
'reqq': 255,
'v': 'BitTorrent 7.10.5',
'yp': 39177,
'yourip': 'ST\x04\xd9'
}
<< 1591212149.370 BITFIELD 11111111111110111111111111111111111111111111111111101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111011111111111111111111111111111111111111111111111111101111011111111111111111111111111111111111110111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111011111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111110111111111111111101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111101111111111111111111111111111111111111111111111111111111111111110111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111011111111111111111111111111111100111111111111110
<< 1591212149.370 HAVE 1945
<< 1591212149.370 HAVE 2433
<< 1591212149.370 HAVE 3128
<< 1591212149.370 HAVE 1308
<< 1591212149.370 HAVE 1256
<< 1591212149.370 HAVE 51
<< 1591212149.370 HAVE 1313
<< 1591212149.370 HAVE 1357
<< 1591212149.370 HAVE 1234
<< 1591212149.370 HAVE 2608
<< 1591212149.370 HAVE 3031
<< 1591212149.370 HAVE 13
<< 1591212149.370 HAVE 2967
<< 1591212149.370 HAVE 2416
<< 1591212149.370 HAVE 1724
<< 1591212149.370 HAVE 3159
<< 1591212149.370 HAVE 3160
<< 1591212149.370 HAVE 1750
<< 1591212149.370 HAVE 2029
<< 1591212149.370 HAVE 2148
<< 1591212149.370 HAVE 676
<< 1591212149.370 HAVE 1351
<< 1591212149.370 HAVE 2380
<< 1591212149.370 HAVE 142
>> 1591212149.370 FIN
<< 1591212149.372 FIN

[arvidn]

In the non-trivial exchange, you send a "HAVE-ALL" message. Then you get a "lazy bitfield", where it turns out the peer is a seed as well, and the connection is closed.

There's also a 'upload_only': 1, in the handshake, suggesting you aren't interested in downloading anything. If you're not a seed, you can end up in upload-only mode in case a disk write operation fails with ENOSPACE. i.e. if you run out of space, the torrent will be switched into "upload-only" mode. So, it will keep uploading but won't download any more.

In this case the torrent is not paused not set in an error state, but there should be a file_error_alert.

I take it you're not a seed, is that right? Is it possible the torrent was started in seed-mode, and nothing has caused it to check any piece yet, so it keeps thinking it's a seed? I can't think of any other reason why a HAVE-ALL message would be sent.

seed-mode would also explain upload_only in the handshake too.

[ichorid]

@arvidn , the captured exchange was from the moment when the ubuntu torrent was already downloaded (although very slow), but the two remaining downloads were still stuck. So, upload only is fine.

What's suspicious, though, is that there are no attempts to get metainfo for the remaining two downloads from DHT. Do you protocol parser catches DHT connection attempts?

[arvidn]

It doesn't analyze DHT packets at all. But any actual attempt to establish a TCP or uTP connection to a peer should be picked up

[ichorid]

I've compared a healthy capture vs the stuck one. One thing is for sure: when stuck, Tribler sends no DHT requests for the torrents that are stuck in "downloading metadata" state. Instead, it sends DHT requests for some other infohashes. I tried looking up those infohashes, but DHT can't find them.

However, while looking at those infohashes I noticed something strange. There are streaks of infohash requests that all start with the same few bits. Here are the screenshots:

These were all going to another instance of Tribler running in the same local network (my seedbox). Though, there too were some DHT requests going to external servers with the same prefix, so it is not specific to local network Tribler->Tribler DHT activity.
The infohashes queried look like this:

03d0f1213f07db9ae14f4933b9cb33528db94513
03d0f294815d38d14487762cb2ebea87ca9843c4
03d0f61269d972c2e27dee834431d82193815e01
03d0f2fbfeacb50e8be80d232a8e56026db8cab0
03d0f5ee78afc9fecad396af3e047758a9e878dd
03d0f1d087595241e85755a0f6932e2fe229d973
03d0f54737d9d932bde8af0f380b65dc96b3dca3
03d0f3f87902892fabecdc7b5388e02d7ee65847

@arvidn , I'm no specialist in DHTs, but to me, it looks very suspicious. It looks more like DHT response than DHT request.

[ichorid]

Ah, I see from the source code! Libtorrent uses DHT obfuscation, it will only start using the real DHT address when it gets closer to the target. So this is not a bug, but a feature :grin:

[ichorid]

Still, this leaves us with a problem: the capture contained no queries for infohashes of the stuck torrents. 03d0f does not correlate with the beginning of any of the stuck torrents' infohashes.

@arvidn , I still can't understand, why it searches for the same prefix as the sender (our own) id?

[arvidn]

Still, this leaves us with a problem: the capture contained no queries for infohashes of the stuck torrents. 03d0f does not correlate with the beginning of any of the stuck torrents' infohashes.

Right, assuming your capture is longer than 15 minutes (which is the default DHT announce interval) there should have been at least one DHT lookup for the info-hash.

There are a few reasons a torrent isn't announcing to the DHT. It can be detected whether it is by looking at torrent_status::announcing_to_dht (docs)

Queuing logic may disable announcing to DHT (docs)

@arvidn , I still can't understand, why it searches for the same prefix as the sender (our own) id?

That's part of normal DHT routing table maintanence, to make sure it discovers new DHT nodes that are close to its own ID.

[ichorid]

My capture was only 3 minutes long, which makes it useless for analysis purposes...

Queuing logic may disable announcing to DHT

We don't use the "automanage" feature in Tribler. Does DHT-limiting queuing logic still applies in this case?

[arvidn]

no, I'm pretty sure if the auto_managed flag is not set, the DHT would never be disabled automatically.

There's still a manual option to disable it (docs) (docs)

[ichorid]

Well, I'll try to reproduce it once again (though it depends on pure chance :four_leaf_clover: ). When I do, I'll do a long packet capture.

[ichorid]

Just reproduced it again!

To semi-reliably reproduce it, one must start Tribler without any subscribed channels (or with 1-2 channels), subscribe to top 10-20 channels, and then, while the channels are downloading, start trying downloading other highly seeded torrents by infohash. In my case, the 1st Ubuntu torrent started fine, so I removed it and tried the second one. The second got stuck as the last time.

I'll do a long capture of UDP packets to look at DHT activity.

[arvidn]

I think dumping torrent_status might be useful as well

[ichorid]

I managed to reproduce it semi-reliably. When the problem arises, it affects all the torrents I try to download. In a normal session, the added torrent will find a lot of peers almost immediately (10-15 seconds max). In a bugged session, the torrent is stuck for 3-6 minutes in "waiting for metadata". After it downloads the metadata, it will connect no more than 1-2 peers and proceed to leech from them. This can continue for 2-10 minutes. After that, the torrent almost instantly finds a lot of peers and leeches very fast as normal. Adding other torrents during the same run results in the same scenario, no matter the torrent.

I started to print torrent_status as suggested. Here is a sample from the moment when the torrent is still stuck waiting for metadata:

Stuck waiting for metadata

{'next_announce': datetime.timedelta(0)
'state': libtorrent.states.downloading_metadata
'errc': <libtorrent.error_code object at 0x7f4870200710>
'error_file': -1
'save_path': '/home/vader/Downloads/TriblerDownloads'
'name': 'ubuntu-16.04.6-desktop-i386.iso'
'torrent_file': <libtorrent.torrent_info object at 0x7f4870331090>
'current_tracker': ''
'total_download': 0
'total_upload': 0
'total_payload_download': 0
'total_payload_upload': 0
'total_failed_bytes': 0
'total_redundant_bytes': 0
'total_done': 0
'total_wanted_done': 0
'total_wanted': 0
'all_time_upload': 0
'all_time_download': 0
'added_time': 1591449605
'last_seen_complete': 0
'storage_mode': libtorrent.storage_mode_t.storage_mode_sparse
'progress': 0.0
'progress_ppm': 0
'queue_position': 4
'download_rate': 0
'upload_rate': 0
'download_payload_rate': 0
'upload_payload_rate': 0
'num_seeds': 0
'num_peers': 0
'num_complete': -1
'num_incomplete': -1
'list_seeds': 0
'list_peers': 0
'connect_candidates': 0
'num_pieces': 0
'distributed_full_copies': 0
'distributed_fraction': 0
'distributed_copies': 0.0
'block_size': 0
'num_uploads': 0
'num_connections': 0
'uploads_limit': -1
'connections_limit': -1
'up_bandwidth_queue': 0
'down_bandwidth_queue': 0
'seed_rank': 0
'need_save_resume': True
'is_seeding': False
'is_finished': False
'has_metadata': False
'has_incoming': False
'moving_storage': False
'announcing_to_trackers': True
'announcing_to_lsd': True
'announcing_to_dht': True
'info_hash': <libtorrent.sha1_hash object at 0x7f4870350710>
'last_upload': None
'last_download': None
'active_duration': datetime.timedelta(seconds=21)
'finished_duration': datetime.timedelta(0)
'seeding_duration': datetime.timedelta(0)
'flags': 0}

And here is the one from the moment where it already leeches from 2 peers:

2 peers

{'next_announce': datetime.timedelta(0)
'state': libtorrent.states.downloading
'errc': <libtorrent.error_code object at 0x7f4870312990>
'error_file': -1
'save_path': '/home/vader/Downloads/TriblerDownloads'
'name': 'ubuntu-16.04.6-desktop-i386.iso'
'torrent_file': <libtorrent.torrent_info object at 0x7f4883ee6330>
'current_tracker': ''
'total_download': 50623154
'total_upload': 60620
'total_payload_download': 50516674
'total_payload_upload': 0
'total_failed_bytes': 0
'total_redundant_bytes': 15244
'total_done': 50495488
'total_wanted_done': 50495488
'total_wanted': 1677721600
'all_time_upload': 0
'all_time_download': 49797507
'added_time': 1591449605
'last_seen_complete': 1591449716
'storage_mode': libtorrent.storage_mode_t.storage_mode_sparse
'progress': 0.030097000300884247
'progress_ppm': 30097
'queue_position': 0
'download_rate': 1858086
'upload_rate': 57972
'download_payload_rate': 1800824
'upload_payload_rate': 0
'num_seeds': 1
'num_peers': 1
'num_complete': -1
'num_incomplete': -1
'list_seeds': 3
'list_peers': 3
'connect_candidates': 1
'num_pieces': 96
'distributed_full_copies': 1
'distributed_fraction': 30
'distributed_copies': 1.0299999713897705
'block_size': 16384
'num_uploads': 0
'num_connections': 2
'uploads_limit': -1
'connections_limit': -1
'up_bandwidth_queue': 0
'down_bandwidth_queue': 0
'seed_rank': 0
'need_save_resume': True
'is_seeding': False
'is_finished': False
'has_metadata': True
'has_incoming': True
'moving_storage': False
'announcing_to_trackers': True
'announcing_to_lsd': True
'announcing_to_dht': True
'info_hash': <libtorrent.sha1_hash object at 0x7f48701f62b0>
'last_upload': None
'last_download': datetime.datetime(2020 6 6 15 21 56)
'active_duration': datetime.timedelta(seconds=110)
'finished_duration': datetime.timedelta(0)
'seeding_duration': datetime.timedelta(0)
'flags': 0}

Note there is "queue_position": 4 for the stuck state. We do not use torrent automanagement, but the same session runs a dozen of background DHT checks for Channel torrents and there are two dozens of tiny Channel torrents already downloaded and seeded.

@arvidn , does Libtorrent uses some kind of queueing even in case automanagement is not used.
We do not touch the auto_managed flag at all.

[ichorid]

Libtorrent uses automanagement by default :face_with_head_bandage:

In [1]: import libtorrent as lt                                                                                                                                                                                    

In [2]: lt.add_torrent_params_flags_t.flag_auto_managed & lt.add_torrent_params_flags_t.default_flags                                                                                                              
Out[2]: 32

And we never touch that. @egbertbouman , do we disable automanage explicitly?

EDIT:
I figured out we construct atp flags ourselves and pass theme to async_add_torrent. If we do not add a flag for automanagement, the torrent should start without one, right?

Why the queue:4 then?

[ichorid]

I added a bunch of torrents simultaneously and printed queue_position and flags for them.
flags is 0 everywhere. However, queue_position is -1 for those already seeding and 1 and more for the others.

Either setting auto_managed flag does not work through Python, or Libtorrent assigns queue_position even if the torrent is not managed (and that would be very confusing).
@arvidn ?

[ichorid]

Having read a little bit through Libtorrent source I can say that it indeed uses queue_position internally when ordering/prioritising connections even when there are no auto-managed torrents. If there is some kind of internal limit for DHT sessions and/or external peer connections or some rare condition that can result in a bunch of torrents being constantly scheduled to the front of the queue,
that would explain the problem. One thing that could be related is that we download a lot of small (~ 1kb size) torrents in the same session (Channels subsystem torrents). That could trigger some kind of "endgame" mode that will force the things to get priority over the recently added torrents.

[arvidn]

yeah, queue position is always assigned, regardless of whether it's auto managed or not. it's possible that the dht_limit would affect torrents that don't have the auto manged flag set (but it seems like it shouldn't). Stil though, the torrent_status you posted suggests that the DHT is still enabled for the torrent, so it might be some other issue, where it's not announced to the DHT for some reason.

[ichorid]

I noticed that stuck torrents are announced to DHT after about 300 seconds. auto_scrape_min_interval is exactly 300 seconds.

[ichorid]

If a torrent is not auto-managed, how often is it announced to DHT? I mean, if I add a torrent by infohash, what's the schedule of DHT checks for it? Does adding a non-auto-managed torrent interfere in some way with DHT scrapes schedule of other non-auto-managed torrents?

[arvidn]

The convention is to announce a torrent to the DHT every 15 minutes.
The auto-managed mechanism only turns things on and off. It doesn't affect the DHT announce frequency.

[ichorid]

It seems it has something to do with C-level async stuff. I can semi-reliably trigger it by adding 3-4 torrents in a couple of seconds just after starting Tribler (with Channels torrents restoring in the same session). One of the added torrents will be almost guaranteed to become stuck in "downloading metadata" for 5-??? minutes.

However, if I change the actual command that Tribler uses to add torrents from async_add_torrent to the plain add_torrent, I can't reproduce the problem.

@arvidn , could it be that the logic behind prioritize_dht can't handle bursts of dozens of asynchronously added torrents?

[arvidn]

One reason I can think of this would happen is that if you add the torrents while the DHT is still being bootstrapped, it's possible that the DHT announces for the torrents will fail, because the routing table is empty, or virtually empty.

There's (currently) no logic to detect whether a DHT announce fails and retry again soon. The only re-announce mechanism is the periodic one, every 15 minutes. So, if you wait 15 minutes, do the stuck torrents get unstuck?

[ichorid]

So, if you wait 15 minutes, do the stuck torrents get unstuck?

Yes, they do. Sometimes it happens after 10 minutes, sometimes it takes more than an hour (i.e. after adding 3 torrents, one torrent can get unstuck in 15 minutes, the remaining two can be still stuck for hours. ). Waiting for hours happens rarely, though.

[ichorid]

Yep, it definitely only happens when using async_add_torrent. The torrents get stuck for a few minutes, then slowly get unstuck.

[ichorid]

When using add_torrent directly though, sometimes a very interesting thing happens: Tribler downloads endpoint becomes completely stuck, all downloads in the "waiting for metadata" state. The console shows that the usual requests to it do not trigger anything. Then, there come HTTP timeouts... Wireshark capture shows normal uTP activity though, for existing torrents.
After 5-10 minutes, everything becomes unstuck. Tribler instantly shows all downloads as having proper metadata, just started downloading.

@arvidn , is there something that could block in add_torrent for several minutes, though does not affect already existing (seeding) torrents?

[arvidn]

does the call itself, to add_torrent() block during this time? (it would be surprising if it would block for that long, it would suggest that something fishy is going on with the main network thread in libtorrent). It's only supposed to block until the main thread has received the request, added the torrent and produced a torrent_handle that's then returned. So, the call should take longer than async_add_torrent().

On the libtorrent side, the exact same thing happens in both cases, the only difference is that the non-async version waits on the client side, blocking the calling thread.

If you see a difference in behavior between the two, I would think it's something triggered by timing.

Does this problem seem to be caused by torrents not announcing to the DHT? (or at least not announcing in a timely manner).

Does Tribler change any of the dht_ settings?

In order to understand more of what's going on, could you try changing the dht_announce_interval setting to something very low, to make torrents announce to the DHT more frequently?

By default it's set to (15 * 60) seconds.

This is the function that's called when it's time to announce another torrent to the DHT.

It tries to stagger the DHT announce of all torrents evenly distributed across the 15 minutes, by setting up a timer to fire every (15m / num_torrents).

int delay = std::max(m_settings.get_int(settings_pack::dht_announce_interval)
    / std::max(int(m_torrents.size()), 1), 1);

There's a risk that if this is called when there's only 1 torrent, the timer is set up for 15 minutes, then if you add more torrents, maybe the delay won't be recomputed for another 15 minutes (I don't know that this is the case, but it seems like a risk).

The next torrent to announce to the DHT is determined by an iterator m_next_dht_torrent, which rotates over all torrents.

[ichorid]

Using add_torrent nonetheless results in stuck torrents, although with smaller probability.
For instance, I added 9 highly popular torrents. 6 of them proceeded from "waiting for metadata" to "downloading" almost immediately.
3 got stuck (lets call them A,B,C).
Then, I waited for a couple of minutes just to be sure. Then I stopped the 6 downloading torrents.
The 3 ABC stuck torrents remained stuck.
Then I waited for another couple of minutes.
Then I stopped one of the stuck torrents (A), and started it right away.
It got unstuck immediately.
The 2 remaining stuck torrents (B and C) were still stuck.
After the A finished downloading, B got unstuck and started to download.
After B finished downloading, C remains stuck for more than 40 minutes...

EDIT:
C was stuck for a good reason: there are no peers. Checked with another client.

[arvidn]

getting unstuck when you stop and start is consistent with the first DHT announce failing. stopping and starting will trigger another DHT announce right away.

Starting immediately as another torrent finishes suggest that there might be some auto-managed aspect, that it was paused and got unpaused.

the torrent_status you posted earlier suggests that the torrent has not found any peers, anywhere:

'list_seeds': 0
'list_peers': 0
'connect_candidates': 0

[ichorid]

does the call itself, to add_torrent() block during this time?
I tried to simulate the blocking with main thread sleep for both adding and reporting torrents. It didn't resemble the behaviour I described above at all. So, if there was a problem, it was more akin to missing handles or something like that. A mystery, indeed! :ghost: :man_shrugging: :ghost:

Tribler does not alter any dht_ setting of Libtorrent.

To sum it up, for now, the problem seems to be that adding a bunch of torrents in a short period of time results in some torrents being stuck in "waiting for metadata" for 300-600 seconds. Stopping any of the other torrents seems not to affect the stuck torrent. While restarting the stuck torrent sometimes can make it unstuck.

Another trial: I disabled the network connection and started a bunch of torrents, then closed Tribler.
Then I enabled the network connection back and opened Tribler. Out of the 7 added torrents only a single one started, the others got stuck in such a bad way, that even stopping-starting them did not help. Then I restarted Tribler again and voila, every torrent got started as normal.
I tried to reproduce the same trick with network connectivity, a couple of times, but everything worked fine.

As you say, the problem is highly timing-dependent.

[arvidn]

you can see which DHT announces are in-flight by calling torrent_handle::post_dht_stats(). It will post a dht_stats_alert which has active_requests and routing_table fields. It's not the full table, just counters for number of nodes per bucket.

The active_requests will show both get_peer lookups as part of announcing torrents, as well as bootstrap when starting up, and other get_peer lookups as part of normal routing table maintenance.

[ichorid]

I'll try to get more DHT stats using this calls later. Meanwhile, I traced the faulty DHT exchange by hand.
The pattern is as follows:
Libtorrent asks a DHT peer for some non-stuck infohash (N), the peer responds with a proper DHT answer packet.
After 2-15 seconds Libtorrent asks the same peer for the stuck infohash (S). This time, the peer remains silent.

This happened 8 times during the first 32 seconds of the Libtorrent session.

I waited for a few minutes, restarted the stuck infohash (S) and it was able to instantly get the necessary DHT responses from other peers (e.g. peers not including those first 9 peers that became silent).

It looks like we're hitting into some kind of DHT requests rate-limiting mechanism employed by other BitTorrent clients. :bricks:

I got a full capture saved, BTW.

[ichorid]

@arvidn , is it possible to wait upon a Libtorrent start until you get a certain number of peers? If the problem is really about DHT flooding control, the easiest solution for us would be to just wait a few seconds until we get enough peers.

[arvidn]

there is an alert for when DHT bootstrapping completes. It might be a good idea to wait for that before starting any torrent.
Maybe the simplest solution would be to pause the session and then resume it once bootstrapping completes.

[arvidn]

http://libtorrent.org/reference-Alerts.html#dht_bootstrap_alert

[ichorid]

I merged the fix for the DHT flood problem.

@arvidn , thank you very much for your help! Hope you got something out of this too.

[synctext]

Is it time almost for RC6 or more @egbertbouman stuff coming?

[ichorid]

We're waiting for Egbert. His stuff is important. He will probably finish today or tomorrow.

[egbertbouman]

@synctext When https://github.com/Tribler/tribler/pull/5357 is merged we should be good to go. More stuff is still coming, but that will have to wait until after RC6.