Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Can't seed from behind a SOCKS proxy via uTP #6512

Open
ichorid opened this issue Oct 3, 2021 · 32 comments
Open

Can't seed from behind a SOCKS proxy via uTP #6512

ichorid opened this issue Oct 3, 2021 · 32 comments
Milestone

Comments

@ichorid
Copy link
Contributor

ichorid commented Oct 3, 2021

Libtorrent 1.2.14.0

This was first discovered in Tribler hidden seeding test issue, where two Libtorrent sessions are started and connected via SOCKS5 UDP associate protocols via uTP. I managed to capture the log:

uTP log
[000000000000] 0x7f150000ce60: initializing MTU to: 1005 [548, 1462]
[000000000065] 0x7f150000ce60: send_syn seq_nr:24134 id:13379 target:238.97.87.177:1024
[000000000168] 0x7f150000ce60: state:SYN_SENT
[000000006519] 0x7f1518012c40: initializing MTU to: 1005 [548, 1462]
[000000006556] 0x7f1518012c40: their_delay::add_sample:6434 prev_base:0 new_base:6434
[000000006560] 0x7f1518012c40: incoming packet reply_micro:6434 base_change:0
[000000006564] 0x7f1518012c40: updating timeout to: now + 3000
[000000006568] 0x7f1518012c40: incoming packet seq_nr:24134 ack_nr:0 type:ST_SYN id:13379 size:0 timestampdiff:0 timestamp:2151945736 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000000006579] 0x7f1518012c40: received ST_SYN state:CONNECTED seq_nr:2247 ack_nr:24134
[000000006582] 0x7f1518012c40: defer ack
[000000006590] 0x7f1518012c40: utp_stream destructed
[000000006593] 0x7f1518012c40: destroy state:CONNECTED (close-reason: 0)
[000000006636] 0x7f1518012c40: sending packet seq_nr:2247 ack_nr:24134 type:ST_FIN id:13379 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2151952298 time_diff:6434 mtu_probe:0 extension:0
[000000006729] 0x7f1518012c40: state:FIN_SENT
[000000006735] 0x7f1518012c40: detach()
[000000006766] 0x7f1518012c40: sending packet seq_nr:2247 ack_nr:24134 type:ST_STATE id:13379 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2151952441 time_diff:6434 mtu_probe:0 extension:0
[000000013791] 0x7f150000ce60: their_delay::add_sample:7168 prev_base:0 new_base:7168
[000000013803] 0x7f150000ce60: incoming packet reply_micro:7168 base_change:0
[000000013810] 0x7f150000ce60: updating timeout to: now + 500
[000000013820] 0x7f150000ce60: acked packet 24134 (0 bytes) (rtt:13)
[000000013828] 0x7f150000ce60: incoming packet seq_nr:2247 ack_nr:24134 type:ST_FIN id:13379 size:0 timestampdiff:6434 timestamp:2151952298 our ack_nr:0 our seq_nr:24135 our acked_seq_nr:24134 our state:SYN_SENT
[000000013836] 0x7f150000ce60: state:CONNECTED
[000000013838] 0x7f150000ce60: calling connect handler
[000000013845] 0x7f150000ce60: calling connect handler ec:Success shutdown:0
[000000013885] 0x7f150000ce60: skipping send (no payload and no force) seq_nr:24135 ack_nr:2246 id:13380 target:238.97.87.177:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000000013893] 0x7f150000ce60: defer ack
[000000013895] 0x7f150000ce60: subscribe drained
[000000013900] 0x7f150000ce60: incoming stream consumed
[000000013915] 0x7f150000ce60: sending packet seq_nr:24135 ack_nr:2246 type:ST_FIN id:13380 target:238.97.87.177:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2151959593 time_diff:7168 mtu_probe:0 extension:0
[000000013990] 0x7f150000ce60: state:FIN_SENT
[000000014020] 0x7f150000ce60: sending packet seq_nr:24135 ack_nr:2246 type:ST_STATE id:13380 target:238.97.87.177:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2151959696 time_diff:7168 mtu_probe:0 extension:0
[000000022617] 0x7f1518012c40: their_delay::add_sample:8702 prev_base:6434 new_base:6434
[000000022628] 0x7f1518012c40: incoming packet reply_micro:8702 base_change:0
[000000022636] 0x7f1518012c40: updating timeout to: now + 500
[000000022641] 0x7f1518012c40: incoming packet seq_nr:24135 ack_nr:2246 type:ST_FIN id:13380 size:0 timestampdiff:7168 timestamp:2151959593 our ack_nr:24134 our seq_nr:2247 our acked_seq_nr:2246 our state:FIN_SENT
[000000022649] 0x7f1518012c40: FIN received in order
[000000022674] 0x7f1518012c40: sending packet seq_nr:2247 ack_nr:24135 type:ST_STATE id:13379 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2151968343 time_diff:8702 mtu_probe:0 extension:0
[000000025080] 0x7f1518012c40: their_delay::add_sample:11063 prev_base:6434 new_base:6434
[000000025092] 0x7f1518012c40: incoming packet reply_micro:11063 base_change:0
[000000025173] 0x7f1518012c40: updating timeout to: now + 500
[000000025178] 0x7f1518012c40: incoming packet seq_nr:24135 ack_nr:2246 type:ST_STATE id:13380 size:0 timestampdiff:7168 timestamp:2151959696 our ack_nr:24135 our seq_nr:2247 our acked_seq_nr:2246 our state:FIN_SENT
[000000045777] 0x7f150000ce60: add_read_buffer 104 bytes
[000000045786] 0x7f150000ce60: new read handler. 0 bytes in buffer
[000000045795] 0x7f150000ce60: add_write_buffer 283 bytes
[000000045800] 0x7f150000ce60: new write handler. 283 bytes to write
[000000045817] 0x7f150000ce60: sending packet seq_nr:24135 ack_nr:2246 type:ST_DATA id:13380 target:238.97.87.177:1024 size:303 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2151991492 time_diff:7168 mtu_probe:0 extension:0
[000000045861] 0x7f150000ce60: calling write handler written:283
[000000045864] 0x7f150000ce60: calling write handler written:283 ec:Success shutdown:0
[000000045925] 0x7f150000ce60: their_delay::add_sample:39166 prev_base:7168 new_base:7168
[000000045928] 0x7f150000ce60: incoming packet reply_micro:39166 base_change:0
[000000045931] 0x7f150000ce60: updating timeout to: now + 500
[000000045934] 0x7f150000ce60: incoming packet seq_nr:2247 ack_nr:24134 type:ST_STATE id:13379 size:0 timestampdiff:6434 timestamp:2151952441 our ack_nr:2246 our seq_nr:24136 our acked_seq_nr:24134 our state:FIN_SENT
[000000045947] 0x7f150000ce60: their_delay::add_sample:23288 prev_base:7168 new_base:7168
[000000045948] 0x7f150000ce60: incoming packet reply_micro:23288 base_change:0
[000000045950] 0x7f150000ce60: updating timeout to: now + 500
[000000045955] 0x7f150000ce60: acked packet 24135 (283 bytes) (rtt:0)
[000000045959] 0x7f150000ce60: incoming packet seq_nr:2247 ack_nr:24135 type:ST_STATE id:13379 size:0 timestampdiff:8702 timestamp:2151968343 our ack_nr:2246 our seq_nr:24136 our acked_seq_nr:24135 our state:FIN_SENT
[000000049485] 0x7f1518012c40: their_delay::add_sample:3674 prev_base:6434 new_base:3674
[000000049493] 0x7f1518012c40: incoming packet reply_micro:3674 base_change:-2760
[000000049496] 0x7f1518012c40: ERROR: incoming packet type: ST_DATA seq_nr:24135 eof_seq_nr:24135 (ignored)
[000000486809] 0x7f1518012c40: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000499903] 0x7f150000ce60: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000000987212] 0x7f1518012c40: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000987229] 0x7f1518012c40: timeout num-timeouts: 0 max-resends: 3 confirmed: 0  acked-seq-num: 2246 mtu-seq: 0
[000000987236] 0x7f1518012c40: resetting cwnd:1005
[000000987239] 0x7f1518012c40: slow_start -> 1
[000000987247] 0x7f1518012c40: state:ERROR error:End of file
[000001000235] 0x7f150000ce60: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000001000254] 0x7f150000ce60: timeout num-timeouts: 0 max-resends: 3 confirmed: 1  acked-seq-num: 24135 mtu-seq: 0
[000001000260] 0x7f150000ce60: resetting cwnd:1005
[000001000263] 0x7f150000ce60: slow_start -> 1
[000001000272] 0x7f150000ce60: state:ERROR error:End of file
[000001000277] 0x7f150000ce60: calling read handler read:0 ec:End of file shutdown:1
[000001000288] 0x7f150000ce60: detach()
[000001000291] 0x7f150000ce60: state:DELETE
[000001487591] 0x7f1518012c40: should_delete() = true
[000001487606] 0x7f1518012c40: destroying utp socket state
[000001500623] 0x7f150000ce60: should_delete() = true
[000001500638] 0x7f150000ce60: destroying utp socket state
[000002001188] 0x7f150000ce60: initializing MTU to: 1005 [548, 1462]
[000002001216] 0x7f150000ce60: send_syn seq_nr:44045 id:11949 target:238.97.87.177:1024
[000002001296] 0x7f150000ce60: state:SYN_SENT
[000002005491] 0x7f1518012c40: initializing MTU to: 1005 [548, 1462]
[000002005505] 0x7f1518012c40: their_delay::add_sample:4262 prev_base:0 new_base:4262
[000002005508] 0x7f1518012c40: incoming packet reply_micro:4262 base_change:0
[000002005510] 0x7f1518012c40: updating timeout to: now + 3000
[000002005513] 0x7f1518012c40: incoming packet seq_nr:44045 ack_nr:0 type:ST_SYN id:11949 size:0 timestampdiff:0 timestamp:2153946891 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000002005582] 0x7f1518012c40: received ST_SYN state:CONNECTED seq_nr:11464 ack_nr:44045
[000002005586] 0x7f1518012c40: defer ack
[000002005593] 0x7f1518012c40: utp_stream destructed
[000002005595] 0x7f1518012c40: destroy state:CONNECTED (close-reason: 0)
[000002005617] 0x7f1518012c40: sending packet seq_nr:11464 ack_nr:44045 type:ST_FIN id:11949 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2153951288 time_diff:4262 mtu_probe:0 extension:0
[000002005703] 0x7f1518012c40: state:FIN_SENT
[000002005712] 0x7f1518012c40: detach()
[000002005748] 0x7f1518012c40: sending packet seq_nr:11464 ack_nr:44045 type:ST_STATE id:11949 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2153951420 time_diff:4262 mtu_probe:0 extension:0
[000002007537] 0x7f150000ce60: their_delay::add_sample:1932 prev_base:0 new_base:1932
[000002007539] 0x7f150000ce60: incoming packet reply_micro:1932 base_change:0
[000002007541] 0x7f150000ce60: updating timeout to: now + 500
[000002007542] 0x7f150000ce60: acked packet 44045 (0 bytes) (rtt:6)
[000002007544] 0x7f150000ce60: incoming packet seq_nr:11464 ack_nr:44045 type:ST_FIN id:11949 size:0 timestampdiff:4262 timestamp:2153951288 our ack_nr:0 our seq_nr:44046 our acked_seq_nr:44045 our state:SYN_SENT
[000002007545] 0x7f150000ce60: state:CONNECTED
[000002007546] 0x7f150000ce60: calling connect handler
[000002007547] 0x7f150000ce60: calling connect handler ec:Success shutdown:0
[000002007552] 0x7f150000ce60: skipping send (no payload and no force) seq_nr:44046 ack_nr:11463 id:11950 target:238.97.87.177:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000002007554] 0x7f150000ce60: defer ack
[000002007555] 0x7f150000ce60: subscribe drained
[000002007555] 0x7f150000ce60: incoming stream consumed
[000002007558] 0x7f150000ce60: sending packet seq_nr:44046 ack_nr:11463 type:ST_FIN id:11950 target:238.97.87.177:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2153953242 time_diff:1932 mtu_probe:0 extension:0
[000002007575] 0x7f150000ce60: state:FIN_SENT
[000002007580] 0x7f150000ce60: sending packet seq_nr:44046 ack_nr:11463 type:ST_STATE id:11950 target:238.97.87.177:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2153953264 time_diff:1932 mtu_probe:0 extension:0
[000002007610] 0x7f150000ce60: add_read_buffer 104 bytes
[000002007613] 0x7f150000ce60: new read handler. 0 bytes in buffer
[000002007616] 0x7f150000ce60: add_write_buffer 68 bytes
[000002007617] 0x7f150000ce60: new write handler. 68 bytes to write
[000002007621] 0x7f150000ce60: sending packet seq_nr:44046 ack_nr:11463 type:ST_DATA id:11950 target:238.97.87.177:1024 size:88 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2153953304 time_diff:1932 mtu_probe:0 extension:0
[000002007630] 0x7f150000ce60: calling write handler written:68
[000002007631] 0x7f150000ce60: calling write handler written:68 ec:Success shutdown:0
[000002008686] 0x7f150000ce60: their_delay::add_sample:2949 prev_base:1932 new_base:1932
[000002008689] 0x7f150000ce60: incoming packet reply_micro:2949 base_change:0
[000002008691] 0x7f150000ce60: updating timeout to: now + 500
[000002008692] 0x7f150000ce60: incoming packet seq_nr:11464 ack_nr:44045 type:ST_STATE id:11949 size:0 timestampdiff:4262 timestamp:2153951420 our ack_nr:11463 our seq_nr:44047 our acked_seq_nr:44045 our state:FIN_SENT
[000002010330] 0x7f1518012c40: their_delay::add_sample:2772 prev_base:4262 new_base:2772
[000002010332] 0x7f1518012c40: incoming packet reply_micro:2772 base_change:-1490
[000002010334] 0x7f1518012c40: updating timeout to: now + 500
[000002010335] 0x7f1518012c40: incoming packet seq_nr:44046 ack_nr:11463 type:ST_FIN id:11950 size:0 timestampdiff:1932 timestamp:2153953242 our ack_nr:44045 our seq_nr:11464 our acked_seq_nr:11463 our state:FIN_SENT
[000002010350] 0x7f1518012c40: FIN received in order
[000002010356] 0x7f1518012c40: sending packet seq_nr:11464 ack_nr:44046 type:ST_STATE id:11949 target:219.166.218.76:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2153956037 time_diff:2772 mtu_probe:0 extension:0
[000002010966] 0x7f1518012c40: their_delay::add_sample:3386 prev_base:2772 new_base:2772
[000002010968] 0x7f1518012c40: incoming packet reply_micro:3386 base_change:0
[000002010969] 0x7f1518012c40: updating timeout to: now + 500
[000002010970] 0x7f1518012c40: incoming packet seq_nr:44046 ack_nr:11463 type:ST_STATE id:11950 size:0 timestampdiff:1932 timestamp:2153953264 our ack_nr:44046 our seq_nr:11464 our acked_seq_nr:11463 our state:FIN_SENT
[000002011716] 0x7f1518012c40: their_delay::add_sample:4096 prev_base:2772 new_base:2772
[000002011718] 0x7f1518012c40: incoming packet reply_micro:4096 base_change:0
[000002011719] 0x7f1518012c40: ERROR: incoming packet type: ST_DATA seq_nr:44046 eof_seq_nr:44046 (ignored)
[000002012270] 0x7f150000ce60: their_delay::add_sample:1917 prev_base:1932 new_base:1917
[000002012272] 0x7f150000ce60: incoming packet reply_micro:1917 base_change:-15
[000002012274] 0x7f150000ce60: updating timeout to: now + 500
[000002012275] 0x7f150000ce60: acked packet 44046 (68 bytes) (rtt:4)
[000002012277] 0x7f150000ce60: incoming packet seq_nr:11464 ack_nr:44046 type:ST_STATE id:11949 size:0 timestampdiff:2772 timestamp:2153956037 our ack_nr:11463 our seq_nr:44047 our acked_seq_nr:44046 our state:FIN_SENT
[000002488098] 0x7f1518012c40: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000002501345] 0x7f150000ce60: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000002988448] 0x7f1518012c40: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000002988466] 0x7f1518012c40: timeout num-timeouts: 0 max-resends: 3 confirmed: 0  acked-seq-num: 11463 mtu-seq: 0
[000002988473] 0x7f1518012c40: resetting cwnd:1005
[000002988476] 0x7f1518012c40: slow_start -> 1
[000002988484] 0x7f1518012c40: state:ERROR error:End of file
[000003001466] 0x7f150000ce60: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000003001483] 0x7f150000ce60: timeout num-timeouts: 0 max-resends: 3 confirmed: 1  acked-seq-num: 44046 mtu-seq: 0
[000003001490] 0x7f150000ce60: resetting cwnd:1005
[000003001493] 0x7f150000ce60: slow_start -> 1
[000003001502] 0x7f150000ce60: state:ERROR error:End of file
[000003001506] 0x7f150000ce60: calling read handler read:0 ec:End of file shutdown:1
[000003001518] 0x7f150000ce60: detach()
[000003001521] 0x7f150000ce60: state:DELETE
[000003488485] 0x7f1518012c40: should_delete() = true
[000003488488] 0x7f1518012c40: destroying utp socket state
[000003501495] 0x7f150000ce60: should_delete() = true
[000003501497] 0x7f150000ce60: destroying utp socket state

The log is for two Libtorrent sessions exchanging uTP data locally through Tribler SOCKS5 connections on both sides. This is 100% reproducible, although it will be hard to reproduce outside of Tribler (e.g. via some random SOCKS server), because of all the dynamic port assignments, etc. Also, there seem to be almost to SOCKS5 servers that support UDP association.

The interesting part of the log is:

...
[000000006579] 0x7f1518012c40: received ST_SYN state:CONNECTED seq_nr:2247 ack_nr:24134
[000000006582] 0x7f1518012c40: defer ack
[000000006590] 0x7f1518012c40: utp_stream destructed
[000000006593] 0x7f1518012c40: destroy state:CONNECTED (close-reason: 0)
...
[000000049496] 0x7f1518012c40: ERROR: incoming packet type: ST_DATA seq_nr:24135 eof_seq_nr:24135 (ignored)

Seems like the seeder acknowledges the connection and then immediately destroys the uTP stream object for some mysterious reason 💥

@ichorid
Copy link
Contributor Author

ichorid commented Oct 4, 2021

Seems related to #6001

@ichorid
Copy link
Contributor Author

ichorid commented Oct 4, 2021

@arvidn ?

@arvidn
Copy link
Owner

arvidn commented Oct 5, 2021

make sure you have settings_pack::proxy_peer_connections enabled.
You may want to try enabling session_log too. http://libtorrent.org/reference-Alerts.html#alert_category_t to see if there's any reason given to closing the connection.

My suspicion is that it has to do with the validation of incoming network interfaces. When listening on a specific interface, but receiving an incoming connection over another interface, that connection is closed because it didn't match the listen interface.

a proxy is roughly treated as its own interface and it's configured to not allow incoming connections.

Could you try this patch?

diff --git a/src/session_impl.cpp b/src/session_impl.cpp
index 6d24443f9..98a148086 100644
--- a/src/session_impl.cpp
+++ b/src/session_impl.cpp
@@ -1912,7 +1912,7 @@ namespace {
                                ? int(random(63000) + 2000)
                                : m_listen_interfaces.front().port;
                        listen_endpoint_t ep(address_v4::any(), port, {}
-                               , transport::plaintext, listen_socket_t::proxy);
+                               , transport::plaintext, listen_socket_t::proxy | listen_socket_t::accept_incoming);
                        eps.emplace_back(ep);
                }
                else

@ichorid
Copy link
Contributor Author

ichorid commented Oct 5, 2021

proxy_peer_connections is constantly enabled in Tribler for anonymized Libtorrent sessions, I've checked that. Here is the Libtorrent session log:

update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:6881 on device "lo"
closing listen socket for 192.168.178.206:6881 on device "eno1"
closing listen socket for [::1]:6881 on device "lo"
closing listen socket for [fe80::501f:b7d:58b5:d47b%eno1]:6881 on device "eno1"
attempting to open listen socket to: 0.0.0.0:6881 on device:  no-incoming proxy 
failed to bind udp socket to: 0.0.0.0:6881 on device:  : [system] (98) Address already in use (retries: 10)
 listening on: 0.0.0.0 TCP port: 6882 UDP port: 6882
>>> SET_TOS [ udp (0.0.0.0 6882) tos: 20 e: Success ]
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881

This is the log for the leecher. The seeder's log looks the same. The suspicious line is:

attempting to open listen socket to: 0.0.0.0:6881 on device:  no-incoming proxy 

@ichorid
Copy link
Contributor Author

ichorid commented Oct 5, 2021

I applied the patch you provided.
The session log changed a bit:

date listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:6882 on device "lo"
closing listen socket for 192.168.178.206:6882 on device "eno1"
closing listen socket for [::1]:6881 on device "lo"
closing listen socket for [fe80::501f:b7d:58b5:d47b%eno1]:6881 on device "eno1"
attempting to open listen socket to: 0.0.0.0:6881 on device:  accept-incoming proxy 
failed to bind listen socket to: 0.0.0.0:6881 on device:  : [system] (98) Address already in use (retries: 10)
 listening on: 0.0.0.0 TCP port: 6882 UDP port: 6882
>>> SET_TOS [ tcp (0.0.0.0 6882) tos: 20 e: Success ]
>>> SET_TOS [ udp (0.0.0.0 6882) tos: 20 e: Success ]
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
attempting to open listen socket to: 0.0.0.0:6881 on device:  accept-incoming proxy 

The uTP log did not change much:

uTP log
[000000000000] 0x7f87640073e0: initializing MTU to: 1005 [548, 1462]
[000000000059] 0x7f87640073e0: send_syn seq_nr:14200 id:46348 target:107.68.22.122:1024
[000000000158] 0x7f87640073e0: state:SYN_SENT
[000000005879] 0x7f877c0150d0: initializing MTU to: 1005 [548, 1462]
[000000005883] 0x7f877c0150d0: their_delay::add_sample:5809 prev_base:0 new_base:5809
[000000005883] 0x7f877c0150d0: incoming packet reply_micro:5809 base_change:0
[000000005884] 0x7f877c0150d0: updating timeout to: now + 3000
[000000005885] 0x7f877c0150d0: incoming packet seq_nr:14200 ack_nr:0 type:ST_SYN id:46348 size:0 timestampdiff:0 timestamp:3626084900 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000000005887] 0x7f877c0150d0: received ST_SYN state:CONNECTED seq_nr:48247 ack_nr:14200
[000000005888] 0x7f877c0150d0: defer ack
[000000005889] 0x7f877c0150d0: utp_stream destructed
[000000005890] 0x7f877c0150d0: destroy state:CONNECTED (close-reason: 0)
[000000005898] 0x7f877c0150d0: sending packet seq_nr:48247 ack_nr:14200 type:ST_FIN id:46348 target:19.48.110.134:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:3626090747 time_diff:5809 mtu_probe:0 extension:0
[000000005917] 0x7f877c0150d0: state:FIN_SENT
[000000005919] 0x7f877c0150d0: detach()
[000000005927] 0x7f877c0150d0: sending packet seq_nr:48247 ack_nr:14200 type:ST_STATE id:46348 target:19.48.110.134:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:3626090780 time_diff:5809 mtu_probe:0 extension:0
[000000007296] 0x7f87640073e0: their_delay::add_sample:1403 prev_base:0 new_base:1403
[000000007299] 0x7f87640073e0: incoming packet reply_micro:1403 base_change:0
[000000007300] 0x7f87640073e0: updating timeout to: now + 500
[000000007302] 0x7f87640073e0: acked packet 14200 (0 bytes) (rtt:7)
[000000007303] 0x7f87640073e0: incoming packet seq_nr:48247 ack_nr:14200 type:ST_FIN id:46348 size:0 timestampdiff:5809 timestamp:3626090747 our ack_nr:0 our seq_nr:14201 our acked_seq_nr:14200 our state:SYN_SENT
[000000007305] 0x7f87640073e0: state:CONNECTED
[000000007305] 0x7f87640073e0: calling connect handler
[000000007307] 0x7f87640073e0: calling connect handler ec:Success shutdown:0
[000000007315] 0x7f87640073e0: skipping send (no payload and no force) seq_nr:14201 ack_nr:48246 id:46349 target:107.68.22.122:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000000007317] 0x7f87640073e0: defer ack
[000000007317] 0x7f87640073e0: subscribe drained
[000000007318] 0x7f87640073e0: incoming stream consumed
[000000007322] 0x7f87640073e0: sending packet seq_nr:14201 ack_nr:48246 type:ST_FIN id:46349 target:107.68.22.122:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3626092176 time_diff:1403 mtu_probe:0 extension:0
[000000007336] 0x7f87640073e0: state:FIN_SENT
[000000007362] 0x7f87640073e0: sending packet seq_nr:14201 ack_nr:48246 type:ST_STATE id:46349 target:107.68.22.122:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3626092195 time_diff:1403 mtu_probe:0 extension:0
[000000008986] 0x7f877c0150d0: their_delay::add_sample:1664 prev_base:5809 new_base:1664
[000000008988] 0x7f877c0150d0: incoming packet reply_micro:1664 base_change:-4145
[000000008990] 0x7f877c0150d0: updating timeout to: now + 500
[000000008991] 0x7f877c0150d0: incoming packet seq_nr:14201 ack_nr:48246 type:ST_FIN id:46349 size:0 timestampdiff:1403 timestamp:3626092176 our ack_nr:14200 our seq_nr:48247 our acked_seq_nr:48246 our state:FIN_SENT
[000000008993] 0x7f877c0150d0: FIN received in order
[000000009000] 0x7f877c0150d0: sending packet seq_nr:48247 ack_nr:14201 type:ST_STATE id:46348 target:19.48.110.134:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3626093851 time_diff:1664 mtu_probe:0 extension:0
[000000009450] 0x7f877c0150d0: their_delay::add_sample:2109 prev_base:1664 new_base:1664
[000000009452] 0x7f877c0150d0: incoming packet reply_micro:2109 base_change:0
[000000009476] 0x7f877c0150d0: updating timeout to: now + 500
[000000009477] 0x7f877c0150d0: incoming packet seq_nr:14201 ack_nr:48246 type:ST_STATE id:46349 size:0 timestampdiff:1403 timestamp:3626092195 our ack_nr:14201 our seq_nr:48247 our acked_seq_nr:48246 our state:FIN_SENT
[000000014157] 0x7f87640073e0: add_read_buffer 104 bytes
[000000014160] 0x7f87640073e0: new read handler. 0 bytes in buffer
[000000014164] 0x7f87640073e0: add_write_buffer 486 bytes
[000000014165] 0x7f87640073e0: new write handler. 486 bytes to write
[000000014170] 0x7f87640073e0: sending packet seq_nr:14201 ack_nr:48246 type:ST_DATA id:46349 target:107.68.22.122:1024 size:506 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3626099023 time_diff:1403 mtu_probe:0 extension:0
[000000014184] 0x7f87640073e0: calling write handler written:486
[000000014185] 0x7f87640073e0: calling write handler written:486 ec:Success shutdown:0
[000000014205] 0x7f87640073e0: their_delay::add_sample:8280 prev_base:1403 new_base:1403
[000000014206] 0x7f87640073e0: incoming packet reply_micro:8280 base_change:0
[000000014207] 0x7f87640073e0: updating timeout to: now + 500
[000000014208] 0x7f87640073e0: incoming packet seq_nr:48247 ack_nr:14200 type:ST_STATE id:46348 size:0 timestampdiff:5809 timestamp:3626090780 our ack_nr:48246 our seq_nr:14202 our acked_seq_nr:14200 our state:FIN_SENT
[000000014212] 0x7f87640073e0: their_delay::add_sample:5216 prev_base:1403 new_base:1403
[000000014212] 0x7f87640073e0: incoming packet reply_micro:5216 base_change:0
[000000014213] 0x7f87640073e0: updating timeout to: now + 500
[000000014214] 0x7f87640073e0: acked packet 14201 (486 bytes) (rtt:0)
[000000014216] 0x7f87640073e0: incoming packet seq_nr:48247 ack_nr:14201 type:ST_STATE id:46348 size:0 timestampdiff:1664 timestamp:3626093851 our ack_nr:48246 our seq_nr:14202 our acked_seq_nr:14201 our state:FIN_SENT
[000000015211] 0x7f877c0150d0: their_delay::add_sample:1042 prev_base:1664 new_base:1042
[000000015213] 0x7f877c0150d0: incoming packet reply_micro:1042 base_change:-622
[000000015214] 0x7f877c0150d0: ERROR: incoming packet type: ST_DATA seq_nr:14201 eof_seq_nr:14201 (ignored)
[000000474951] 0x7f877c0150d0: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000499813] 0x7f87640073e0: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000000975071] 0x7f877c0150d0: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000975089] 0x7f877c0150d0: timeout num-timeouts: 0 max-resends: 3 confirmed: 0  acked-seq-num: 48246 mtu-seq: 0
[000000975096] 0x7f877c0150d0: resetting cwnd:1005
[000000975098] 0x7f877c0150d0: slow_start -> 1
[000000975106] 0x7f877c0150d0: state:ERROR error:End of file
[000000999929] 0x7f87640073e0: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000000999947] 0x7f87640073e0: timeout num-timeouts: 0 max-resends: 3 confirmed: 1  acked-seq-num: 14201 mtu-seq: 0
[000000999953] 0x7f87640073e0: resetting cwnd:1005
[000000999956] 0x7f87640073e0: slow_start -> 1
[000000999965] 0x7f87640073e0: state:ERROR error:End of file
[000000999969] 0x7f87640073e0: calling read handler read:0 ec:End of file shutdown:1
[000000999980] 0x7f87640073e0: detach()
[000000999983] 0x7f87640073e0: state:DELETE
[000001475344] 0x7f877c0150d0: should_delete() = true
[000001475358] 0x7f877c0150d0: destroying utp socket state
[000001500017] 0x7f87640073e0: should_delete() = true
[000001500034] 0x7f87640073e0: destroying utp socket state
[000002000373] 0x7f87640073e0: initializing MTU to: 1005 [548, 1462]
[000002000410] 0x7f87640073e0: send_syn seq_nr:24296 id:61656 target:107.68.22.122:1024
[000002000512] 0x7f87640073e0: state:SYN_SENT
[000002006219] 0x7f877c0150d0: initializing MTU to: 1005 [548, 1462]
[000002006237] 0x7f877c0150d0: their_delay::add_sample:5800 prev_base:0 new_base:5800
[000002006242] 0x7f877c0150d0: incoming packet reply_micro:5800 base_change:0
[000002006246] 0x7f877c0150d0: updating timeout to: now + 3000
[000002006250] 0x7f877c0150d0: incoming packet seq_nr:24296 ack_nr:0 type:ST_SYN id:61656 size:0 timestampdiff:0 timestamp:3628085250 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000002006348] 0x7f877c0150d0: received ST_SYN state:CONNECTED seq_nr:23941 ack_nr:24296
[000002006358] 0x7f877c0150d0: defer ack
[000002006369] 0x7f877c0150d0: utp_stream destructed
[000002006373] 0x7f877c0150d0: destroy state:CONNECTED (close-reason: 0)
[000002006411] 0x7f877c0150d0: sending packet seq_nr:23941 ack_nr:24296 type:ST_FIN id:61656 target:19.48.110.134:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:3628091243 time_diff:5800 mtu_probe:0 extension:0
[000002006495] 0x7f877c0150d0: state:FIN_SENT
[000002006501] 0x7f877c0150d0: detach()
[000002006539] 0x7f877c0150d0: sending packet seq_nr:23941 ack_nr:24296 type:ST_STATE id:61656 target:19.48.110.134:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:3628091383 time_diff:5800 mtu_probe:0 extension:0
[000002012937] 0x7f87640073e0: their_delay::add_sample:6540 prev_base:0 new_base:6540
[000002012949] 0x7f87640073e0: incoming packet reply_micro:6540 base_change:0
[000002012956] 0x7f87640073e0: updating timeout to: now + 500
[000002012966] 0x7f87640073e0: acked packet 24296 (0 bytes) (rtt:12)
[000002012973] 0x7f87640073e0: incoming packet seq_nr:23941 ack_nr:24296 type:ST_FIN id:61656 size:0 timestampdiff:5800 timestamp:3628091243 our ack_nr:0 our seq_nr:24297 our acked_seq_nr:24296 our state:SYN_SENT
[000002012982] 0x7f87640073e0: state:CONNECTED
[000002012984] 0x7f87640073e0: calling connect handler
[000002012992] 0x7f87640073e0: calling connect handler ec:Success shutdown:0
[000002013013] 0x7f87640073e0: skipping send (no payload and no force) seq_nr:24297 ack_nr:23940 id:61657 target:107.68.22.122:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000002013022] 0x7f87640073e0: defer ack
[000002013024] 0x7f87640073e0: subscribe drained
[000002013029] 0x7f87640073e0: incoming stream consumed
[000002013046] 0x7f87640073e0: sending packet seq_nr:24297 ack_nr:23940 type:ST_FIN id:61657 target:107.68.22.122:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3628097894 time_diff:6540 mtu_probe:0 extension:0
[000002013114] 0x7f87640073e0: state:FIN_SENT
[000002013147] 0x7f87640073e0: sending packet seq_nr:24297 ack_nr:23940 type:ST_STATE id:61657 target:107.68.22.122:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3628097991 time_diff:6540 mtu_probe:0 extension:0
[000002013327] 0x7f87640073e0: add_read_buffer 104 bytes
[000002013342] 0x7f87640073e0: new read handler. 0 bytes in buffer
[000002013355] 0x7f87640073e0: add_write_buffer 68 bytes
[000002013363] 0x7f87640073e0: new write handler. 68 bytes to write
[000002013386] 0x7f87640073e0: sending packet seq_nr:24297 ack_nr:23940 type:ST_DATA id:61657 target:107.68.22.122:1024 size:88 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:3628098228 time_diff:6540 mtu_probe:0 extension:0
[000002013442] 0x7f87640073e0: calling write handler written:68
[000002013447] 0x7f87640073e0: calling write handler written:68 ec:Success shutdown:0
[000002015285] 0x7f87640073e0: their_delay::add_sample:8752 prev_base:6540 new_base:6540
[000002015297] 0x7f87640073e0: incoming packet reply_micro:8752 base_change:0
[000002015304] 0x7f87640073e0: updating timeout to: now + 500
[000002015308] 0x7f87640073e0: incoming packet seq_nr:23941 ack_nr:24296 type:ST_STATE id:61656 size:0 timestampdiff:5800 timestamp:3628091383 our ack_nr:23940 our seq_nr:24298 our acked_seq_nr:24296 our state:FIN_SENT
[000002022864] 0x7f877c0150d0: their_delay::add_sample:9819 prev_base:5800 new_base:5800
[000002022876] 0x7f877c0150d0: incoming packet reply_micro:9819 base_change:0
[000002022885] 0x7f877c0150d0: updating timeout to: now + 500
[000002022890] 0x7f877c0150d0: incoming packet seq_nr:24297 ack_nr:23940 type:ST_FIN id:61657 size:0 timestampdiff:6540 timestamp:3628097894 our

@ichorid
Copy link
Contributor Author

ichorid commented Oct 5, 2021

Added peer logging:

Peer log: ep: 235.97.29.105:1024 type: uTP seed: 0 p: 0x7f55f80136a0 local: 0.0.0.0:0
Peer log: bt_peer_connection
Peer log: a: 235.97.29.105
Peer log: global 
Peer log: protocol: IPv4
Peer log: dst: 0.0.0.0:6882 ec: Success
Peer log: dst: 235.97.29.105:1024
Peer log: e: 0.0.0.0:6882
Peer log: quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
Session log: RECALCULATE UNCHOKE SLOTS: [ peers: 1 eligible-peers: 0 allowed-slots: 8 ]
Peer log: ep: 235.97.29.105:1024
Peer log: 
Peer log: tos: 32 e: Success
Peer log: outgoing encryption policy: enabled
Peer log: initiating encrypted handshake
Peer log: pad size: 140
Peer log: bytes: 236
Peer log: sent DH key
Peer log: max: 104 bytes
Peer log: bytes: 236
Peer log: bytes: 236 
Peer log: 236 bytes
Peer log: bytes: 0 ERROR: (asio.misc:2) End of file
Peer log: in peer_connection::on_receive_data_impl ERROR: (asio.misc:2) End of file
Peer log: op: 11 ERROR: (asio.misc:2) End of file
Peer log: 

The only peer logs are from the leecher side. The last "empty" log line is suspicious 🤔

@wrtorrent
Copy link

wrtorrent commented Oct 5, 2021

235.97.29.105:1024
port number is low?
linux had restriction somewhere on connecting (binding) to low port numbers

@userdocs
Copy link

userdocs commented Oct 5, 2021

@ichorid
Copy link
Contributor Author

ichorid commented Oct 5, 2021

@wrtorrent , thanks for suggestion, but port 1024 should be perfectly fine as 1024>1023. Also, this is not real ports and IPs, but just the ports and IPs reported by Tribler SOCKS5 server during tests. This means the Linux kernel never sees these, those exist just as numbers in packets going back and forth over the SOCKS protocol.

@ichorid
Copy link
Contributor Author

ichorid commented Oct 5, 2021

@arvidn , any ideas on how to debug this further?

@arvidn
Copy link
Owner

arvidn commented Oct 6, 2021

@ichorid the patch I suggested should affect a peers "willingness" to accept an incoming connection via SOCKS5. From the peer log you posted, it looks like you're on the peer making the connection (not accepting it). Did you still patch the other end? If not, it might still be the problem that it won't accept incoming connections from you.

@ichorid
Copy link
Contributor Author

ichorid commented Oct 6, 2021

@arvidn both ends run on the same machine, same lib, same process. I guess the second column in the log is the Libtorrent Session pointer or some kind of id. You can see there are two such pointers in the log I provided: 0x7f877c0150d0 and 0x7f87640073e0. The logs look just the same for both of them.

EDIT: sorry, the thing you were talking about is the Session log. I omitted the log for the second Session because it looked just the same. I'll provide it for the sake of completeness now.

@ichorid
Copy link
Contributor Author

ichorid commented Oct 6, 2021

Seeder session log:

update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:6881 on device "lo"
closing listen socket for 192.168.178.206:6881 on device "eno1"
closing listen socket for [::1]:6881 on device "lo"
closing listen socket for [fe80::501f:b7d:58b5:d47b%eno1]:6881 on device "eno1"
attempting to open listen socket to: 0.0.0.0:6881 on device:  accept-incoming proxy 
 listening on: 0.0.0.0 TCP port: 6881 UDP port: 6881
>>> SET_TOS [ tcp (0.0.0.0 6881) tos: 20 e: Success ] 
>>> SET_TOS [ udp (0.0.0.0 6881) tos: 20 e: Success ] 
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881

Leecher session log:

update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:6882 on device "lo"
closing listen socket for 192.168.178.206:6882 on device "eno1"
closing listen socket for [::1]:6881 on device "lo"
closing listen socket for [fe80::501f:b7d:58b5:d47b%eno1]:6881 on device "eno1"
attempting to open listen socket to: 0.0.0.0:6881 on device:  accept-incoming proxy 
failed to bind listen socket to: 0.0.0.0:6881 on device:  : [system] (98) Address already in use (retries: 10)
 listening on: 0.0.0.0 TCP port: 6882 UDP port: 6882
>>> SET_TOS [ tcp (0.0.0.0 6882) tos: 20 e: Success ]
>>> SET_TOS [ udp (0.0.0.0 6882) tos: 20 e: Success ]
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:6881,[::]:6881
parsed listen interfaces count: 2, ifaces: 0.0.0.0:6881,[::]:6881

Both sessions run on the same machine. The leecher session starts after the seeder, tries to bind to the default port 6881, fails to do so and then tries port 6882. One suspicious point is the leecher log still showing update listen interfaces pointing to port 6881:raised_eyebrow:

@ichorid
Copy link
Contributor Author

ichorid commented Oct 6, 2021

Just for the sake of it, I randomized the listen ports:
Seeder:

parsed listen interfaces count: 1, ifaces: 0.0.0.0:14275
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:14275 on device "lo"
closing listen socket for 192.168.178.206:14275 on device "eno1"
attempting to open listen socket to: 0.0.0.0:14275 on device:  accept-incoming proxy 
 listening on: 0.0.0.0 TCP port: 14275 UDP port: 14275
>>> SET_TOS [ tcp (0.0.0.0 14275) tos: 20 e: Success ] 
>>> SET_TOS [ udp (0.0.0.0 14275) tos: 20 e: Success ] 
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:14275
parsed listen interfaces count: 1, ifaces: 0.0.0.0:14275
UDP error: 0.0.0.0:0 (125) Operation canceled
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:14275
parsed listen interfaces count: 1, ifaces: 0.0.0.0:14275

Leecher:

update listen interfaces: 0.0.0.0:34800
parsed listen interfaces count: 1, ifaces: 0.0.0.0:34800
applying settings pack, reopen_listen_port=true
reopen listen sockets
closing listen socket for 127.0.0.1:34800 on device "lo"
closing listen socket for 192.168.178.206:34800 on device "eno1"
attempting to open listen socket to: 0.0.0.0:34800 on device:  accept-incoming proxy 
 listening on: 0.0.0.0 TCP port: 34800 UDP port: 34800
>>> SET_TOS [ tcp (0.0.0.0 34800) tos: 20 e: Success ]
>>> SET_TOS [ udp (0.0.0.0 34800) tos: 20 e: Success ]
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:34800
parsed listen interfaces count: 1, ifaces: 0.0.0.0:34800
UDP error: 0.0.0.0:0 (125) Operation canceled
applying settings pack, reopen_listen_port=false
update listen interfaces: 0.0.0.0:34800
parsed listen interfaces count: 1, ifaces: 0.0.0.0:34800

The uTP log seems the same 🤷

[000000000000] 0x7fd4f0004660: initializing MTU to: 1005 [548, 1462]
[000000000016] 0x7fd4f0004660: send_syn seq_nr:60235 id:2226 target:235.21.209.99:1024
[000000000063] 0x7fd4f0004660: state:SYN_SENT
[000000002627] 0x7fd508015930: initializing MTU to: 1005 [548, 1462]
[000000002635] 0x7fd508015930: their_delay::add_sample:2600 prev_base:0 new_base:2600
[000000002637] 0x7fd508015930: incoming packet reply_micro:2600 base_change:0
[000000002638] 0x7fd508015930: updating timeout to: now + 3000
[000000002639] 0x7fd508015930: incoming packet seq_nr:60235 ack_nr:0 type:ST_SYN id:2226 size:0 timestampdiff:0 timestamp:2449865397 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000000002643] 0x7fd508015930: received ST_SYN state:CONNECTED seq_nr:35475 ack_nr:60235
[000000002645] 0x7fd508015930: defer ack
[000000002648] 0x7fd508015930: utp_stream destructed
[000000002649] 0x7fd508015930: destroy state:CONNECTED (close-reason: 0)
[000000002666] 0x7fd508015930: sending packet seq_nr:35475 ack_nr:60235 type:ST_FIN id:2226 target:221.161.99.136:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2449868036 time_diff:2600 mtu_probe:0 extension:0
[000000002703] 0x7fd508015930: state:FIN_SENT
[000000002706] 0x7fd508015930: detach()
[000000002719] 0x7fd508015930: sending packet seq_nr:35475 ack_nr:60235 type:ST_STATE id:2226 target:221.161.99.136:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2449868097 time_diff:2600 mtu_probe:0 extension:0
[000000005217] 0x7fd4f0004660: their_delay::add_sample:2560 prev_base:0 new_base:2560
[000000005223] 0x7fd4f0004660: incoming packet reply_micro:2560 base_change:0
[000000005226] 0x7fd4f0004660: updating timeout to: now + 500
[000000005230] 0x7fd4f0004660: acked packet 60235 (0 bytes) (rtt:5)
[000000005233] 0x7fd4f0004660: incoming packet seq_nr:35475 ack_nr:60235 type:ST_FIN id:2226 size:0 timestampdiff:2600 timestamp:2449868036 our ack_nr:0 our seq_nr:60236 our acked_seq_nr:60235 our state:SYN_SENT
[000000005236] 0x7fd4f0004660: state:CONNECTED
[000000005237] 0x7fd4f0004660: calling connect handler
[000000005240] 0x7fd4f0004660: calling connect handler ec:Success shutdown:0
[000000005259] 0x7fd4f0004660: skipping send (no payload and no force) seq_nr:60236 ack_nr:35474 id:2227 target:235.21.209.99:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000000005263] 0x7fd4f0004660: defer ack
[000000005264] 0x7fd4f0004660: subscribe drained
[000000005266] 0x7fd4f0004660: incoming stream consumed
[000000005273] 0x7fd4f0004660: sending packet seq_nr:60236 ack_nr:35474 type:ST_FIN id:2227 target:235.21.209.99:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2449870652 time_diff:2560 mtu_probe:0 extension:0
[000000005303] 0x7fd4f0004660: state:FIN_SENT
[000000005316] 0x7fd4f0004660: sending packet seq_nr:60236 ack_nr:35474 type:ST_STATE id:2227 target:235.21.209.99:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2449870695 time_diff:2560 mtu_probe:0 extension:0
[000000008848] 0x7fd508015930: their_delay::add_sample:3575 prev_base:2600 new_base:2600
[000000008852] 0x7fd508015930: incoming packet reply_micro:3575 base_change:0
[000000008856] 0x7fd508015930: updating timeout to: now + 500
[000000008858] 0x7fd508015930: incoming packet seq_nr:60236 ack_nr:35474 type:ST_FIN id:2227 size:0 timestampdiff:2560 timestamp:2449870652 our ack_nr:60235 our seq_nr:35475 our acked_seq_nr:35474 our state:FIN_SENT
[000000008862] 0x7fd508015930: FIN received in order
[000000008872] 0x7fd508015930: sending packet seq_nr:35475 ack_nr:60236 type:ST_STATE id:2226 target:221.161.99.136:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2449874248 time_diff:3575 mtu_probe:0 extension:0
[000000009908] 0x7fd508015930: their_delay::add_sample:4593 prev_base:2600 new_base:2600
[000000009913] 0x7fd508015930: incoming packet reply_micro:4593 base_change:0
[000000009951] 0x7fd508015930: updating timeout to: now + 500
[000000009953] 0x7fd508015930: incoming packet seq_nr:60236 ack_nr:35474 type:ST_STATE id:2227 size:0 timestampdiff:2560 timestamp:2449870695 our ack_nr:60236 our seq_nr:35475 our acked_seq_nr:35474 our state:FIN_SENT
[000000019820] 0x7fd4f0004660: add_read_buffer 104 bytes
[000000019826] 0x7fd4f0004660: new read handler. 0 bytes in buffer
[000000019835] 0x7fd4f0004660: add_write_buffer 387 bytes
[000000019838] 0x7fd4f0004660: new write handler. 387 bytes to write
[000000019849] 0x7fd4f0004660: sending packet seq_nr:60236 ack_nr:35474 type:ST_DATA id:2227 target:235.21.209.99:1024 size:407 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2449885225 time_diff:2560 mtu_probe:0 extension:0
[000000019881] 0x7fd4f0004660: calling write handler written:387
[000000019884] 0x7fd4f0004660: calling write handler written:387 ec:Success shutdown:0
[000000019937] 0x7fd4f0004660: their_delay::add_sample:17221 prev_base:2560 new_base:2560
[000000019939] 0x7fd4f0004660: incoming packet reply_micro:17221 base_change:0
[000000019941] 0x7fd4f0004660: updating timeout to: now + 500
[000000019943] 0x7fd4f0004660: incoming packet seq_nr:35475 ack_nr:60235 type:ST_STATE id:2226 size:0 timestampdiff:2600 timestamp:2449868097 our ack_nr:35474 our seq_nr:60237 our acked_seq_nr:60235 our state:FIN_SENT
[000000019954] 0x7fd4f0004660: their_delay::add_sample:11087 prev_base:2560 new_base:2560
[000000019955] 0x7fd4f0004660: incoming packet reply_micro:11087 base_change:0
[000000019956] 0x7fd4f0004660: updating timeout to: now + 500
[000000019959] 0x7fd4f0004660: acked packet 60236 (387 bytes) (rtt:0)
[000000019962] 0x7fd4f0004660: incoming packet seq_nr:35475 ack_nr:60236 type:ST_STATE id:2226 size:0 timestampdiff:3575 timestamp:2449874248 our ack_nr:35474 our seq_nr:60237 our acked_seq_nr:60236 our state:FIN_SENT
[000000022293] 0x7fd508015930: their_delay::add_sample:2448 prev_base:2600 new_base:2448
[000000022299] 0x7fd508015930: incoming packet reply_micro:2448 base_change:-152
[000000022301] 0x7fd508015930: ERROR: incoming packet type: ST_DATA seq_nr:60236 eof_seq_nr:60236 (ignored)
[000000474963] 0x7fd508015930: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000500121] 0x7fd4f0004660: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000000975097] 0x7fd508015930: tick:FIN_SENT r: 0 (no handler) w: 0 (no handler)
[000000975115] 0x7fd508015930: timeout num-timeouts: 0 max-resends: 3 confirmed: 0  acked-seq-num: 35474 mtu-seq: 0
[000000975122] 0x7fd508015930: resetting cwnd:1005
[000000975125] 0x7fd508015930: slow_start -> 1
[000000975132] 0x7fd508015930: state:ERROR error:End of file
[000001000372] 0x7fd4f0004660: tick:FIN_SENT r: 0 (handler) w: 0 (no handler)
[000001000390] 0x7fd4f0004660: timeout num-timeouts: 0 max-resends: 3 confirmed: 1  acked-seq-num: 60236 mtu-seq: 0
[000001000397] 0x7fd4f0004660: resetting cwnd:1005
[000001000400] 0x7fd4f0004660: slow_start -> 1
[000001000410] 0x7fd4f0004660: state:ERROR error:End of file
[000001000414] 0x7fd4f0004660: calling read handler read:0 ec:End of file shutdown:1
[000001000426] 0x7fd4f0004660: detach()
[000001000428] 0x7fd4f0004660: state:DELETE
[000001475362] 0x7fd508015930: should_delete() = true
[000001475377] 0x7fd508015930: destroying utp socket state
[000001500499] 0x7fd4f0004660: should_delete() = true
[000001500513] 0x7fd4f0004660: destroying utp socket state
[000002001095] 0x7fd4f0004660: initializing MTU to: 1005 [548, 1462]
[000002001116] 0x7fd4f0004660: send_syn seq_nr:31991 id:28464 target:235.21.209.99:1024
[000002001220] 0x7fd4f0004660: state:SYN_SENT
[000002007090] 0x7fd508015930: initializing MTU to: 1005 [548, 1462]
[000002007108] 0x7fd508015930: their_delay::add_sample:5955 prev_base:0 new_base:5955
[000002007112] 0x7fd508015930: incoming packet reply_micro:5955 base_change:0
[000002007116] 0x7fd508015930: updating timeout to: now + 3000
[000002007119] 0x7fd508015930: incoming packet seq_nr:31991 ack_nr:0 type:ST_SYN id:28464 size:0 timestampdiff:0 timestamp:2451866494 our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000002007204] 0x7fd508015930: received ST_SYN state:CONNECTED seq_nr:175 ack_nr:31991
[000002007206] 0x7fd508015930: defer ack
[000002007208] 0x7fd508015930: utp_stream destructed
[000002007208] 0x7fd508015930: destroy state:CONNECTED (close-reason: 0)
[000002007230] 0x7fd508015930: sending packet seq_nr:175 ack_nr:31991 type:ST_FIN id:28464 target:221.161.99.136:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2451872594 time_diff:5955 mtu_probe:0 extension:0
[000002007264] 0x7fd508015930: state:FIN_SENT
[000002007265] 0x7fd508015930: detach()
[000002007287] 0x7fd508015930: sending packet seq_nr:175 ack_nr:31991 type:ST_STATE id:28464 target:221.161.99.136:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:0 in-flight:0 mtu:1005 timestamp:2451872668 time_diff:5955 mtu_probe:0 extension:0
[000002008697] 0x7fd4f0004660: their_delay::add_sample:1484 prev_base:0 new_base:1484
[000002008699] 0x7fd4f0004660: incoming packet reply_micro:1484 base_change:0
[000002008701] 0x7fd4f0004660: updating timeout to: now + 500
[000002008702] 0x7fd4f0004660: acked packet 31991 (0 bytes) (rtt:7)
[000002008704] 0x7fd4f0004660: incoming packet seq_nr:175 ack_nr:31991 type:ST_FIN id:28464 size:0 timestampdiff:5955 timestamp:2451872594 our ack_nr:0 our seq_nr:31992 our acked_seq_nr:31991 our state:SYN_SENT
[000002008705] 0x7fd4f0004660: state:CONNECTED
[000002008706] 0x7fd4f0004660: calling connect handler
[000002008707] 0x7fd4f0004660: calling connect handler ec:Success shutdown:0
[000002008712] 0x7fd4f0004660: skipping send (no payload and no force) seq_nr:31992 ack_nr:174 id:28465 target:235.21.209.99:1024 header_size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005
[000002008713] 0x7fd4f0004660: defer ack
[000002008714] 0x7fd4f0004660: subscribe drained
[000002008715] 0x7fd4f0004660: incoming stream consumed
[000002008717] 0x7fd4f0004660: sending packet seq_nr:31992 ack_nr:174 type:ST_FIN id:28465 target:235.21.209.99:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2451874099 time_diff:1484 mtu_probe:0 extension:0
[000002008730] 0x7fd4f0004660: state:FIN_SENT
[000002008735] 0x7fd4f0004660: sending packet seq_nr:31992 ack_nr:174 type:ST_STATE id:28465 target:235.21.209.99:1024 size:20 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2451874116 time_diff:1484 mtu_probe:0 extension:0
[000002008846] 0x7fd4f0004660: add_read_buffer 104 bytes
[000002008848] 0x7fd4f0004660: new read handler. 0 bytes in buffer
[000002008852] 0x7fd4f0004660: add_write_buffer 68 bytes
[000002008854] 0x7fd4f0004660: new write handler. 68 bytes to write
[000002008857] 0x7fd4f0004660: sending packet seq_nr:31992 ack_nr:174 type:ST_DATA id:28465 target:235.21.209.99:1024 size:88 error:Success send_buffer_size:0 cwnd:1500 adv_wnd:1048576 in-flight:0 mtu:1005 timestamp:2451874238 time_diff:1484 mtu_probe:0 extension:0
[000002008867] 0x7fd4f0004660: calling write handler written:68
[000002008868] 0x7fd4f0004660: calling write handler written:68 ec:Success shutdown:0
[000002009414] 0x7fd4f0004660: their_delay::add_sample:2128 prev_base:1484 new_base:1484
[000002009417] 0x7fd4f0004660: incoming packet reply_micro:2128 base_change:0
[000002009418] 0x7fd4f0004660: updating timeout to: now + 500
[000002009419] 0x7fd4f0004660: incoming packet seq_nr:175 ack_nr:31991 type:ST_STATE id:28464 size:0 timestampdiff:5955 timestamp:2451872668 our ack_nr:174 our seq_nr:31993 our acked_seq_nr:31991 our state:FIN_SENT
[000002010929] 0x7fd508015930: their_delay::add_sample:2212 prev_base:5955 new_base:2212
[000002010932] 0x7fd508015930: incoming packet reply_micro:2212 base_change:-3743
[000002010933] 0x7fd508015930: updating timeout to: now + 500
[000002010934] 0x7fd508015930: incoming packet seq_nr:31992 ack_nr:174 type:ST_FIN id:28465 size:0 timestampdiff:1484 timestamp:2451874099 our ack_nr:31991 our seq_nr:175

@ichorid
Copy link
Contributor Author

ichorid commented Oct 11, 2021

@arvidn , any ideas how to proceed with debugging this further?

@arvidn
Copy link
Owner

arvidn commented Oct 22, 2021

the best thing I can think of would be to set a breakpoint in the uTP destroy function and see where it's called from, or add more logging around calls to it (with the reason it's called).

I still have a suspicion it's related to libtorrent's logic to ensure connections are coming in (and going out) over an "approved" interface (when interfaces are specified). It's possible there are some other places where the proxy-interface is assumed not to accept incoming connections.

@egbertbouman
Copy link

egbertbouman commented Oct 22, 2021

Tribler broke after 6aad9a4. Inverting the proxy_peer_connections flag in the if-statement fixes the issue for me.

@arvidn
Copy link
Owner

arvidn commented Oct 22, 2021

Great find. I don't think it's quite as simple as to revert this. The purpose of that check is to ensure that a local listen socket isn't accepting incoming connections when peer connections are supposed to be going through the proxy. I.e. as a safety measure to prevent peers from circumventing your proxy.

I'll take a closer look at this.

@arvidn
Copy link
Owner

arvidn commented Oct 22, 2021

For example, imagine using an http proxy and enabling proxy peer connections. Any connection accepted by a local listen socket won't be going through the proxy, and shouldn't be allowed.

@egbertbouman
Copy link

I haven't looked into it too deep, but thee problem may very well be at the Tribler side. The issue with accepting incoming connections through a proxy is currently that we don't know where to send the data. In Tribler this is currently solved by sending the data to the local listen socket (https://github.com/Tribler/tribler/blob/main/src/tribler-core/tribler_core/modules/tunnel/community/community.py#L561). This would work with libtorrent 1.2.12, but stopped working after the commit I mentioned earlier.

Ideally, when libtorrent sends an UDP associate it should include the address with which to communicate in the DST.ADDR/DST.PORT fields. This would ensure that we always know what to do with incoming data. Right now, these field are empty.

@arvidn
Copy link
Owner

arvidn commented Oct 22, 2021

I see. Libtorrent (probably) expects those packets to be wrapped in the socks5 udp header.

This is all uTP, right?

@arvidn
Copy link
Owner

arvidn commented Oct 22, 2021

I agree that it would be good if libtorrent would fill in the IP and port in the UDP Associate command, but in your case, it's the same IP and port, libtorrent just doesn't treat it as coming via the proxy if it doesn't have the socks5 header.

@egbertbouman
Copy link

I see. Libtorrent (probably) expects those packets to be wrapped in the socks5 udp header.

I've looked into this and Tribler is adding a SOCKS5 header. Without the header libtorrent doesn't respond at all, and with a header it immediately sends a ST_FIN after receiving a ST_SYN. I assume the ST_FIN is sent as a result of the uTP destroy function you mentioned earlier?

This is all uTP, right?

Yes, the UDP packets are coming from another libtorrent instance. I assume it's all uTP.

I agree that it would be good if libtorrent would fill in the IP and port in the UDP Associate command, but in your case, it's the same IP and port, libtorrent just doesn't treat it as coming via the proxy if it doesn't have the socks5 header.

It looks like incoming_connection is called even when a proxy is used. When that methods performs the proxy_peer_connections check, it's not looking at the headers as far as I can tell.

@ichorid
Copy link
Contributor Author

ichorid commented Oct 22, 2021

Yay, @egbertbouman , long time no see! 😁 🎉

@arvidn arvidn added this to the 1.2.15 milestone Oct 23, 2021
@arvidn
Copy link
Owner

arvidn commented Oct 23, 2021

libtorrent is probably just assuming no proxy supports incoming connections then. this should be fixed.

@arvidn
Copy link
Owner

arvidn commented Oct 27, 2021

could you try this patch?

#6538

@ichorid
Copy link
Contributor Author

ichorid commented Oct 28, 2021

could you try this patch?

#6538

First of all, this patch is for Libtorrent 2.0. I was not able to apply it to 1.2.14. So, I tried compiling Python bindings with Libtorrent 2.0, but failed to do so with boost-build. Seems like the jamfile-based build is broken. I filed a separate issue for that.

@arvidn , could you please either:

  • prepare a 1.2.14-compatible patch for me, or
  • include bindings build fixes in the patch, or
  • point me out how to build the bindings without using the broken jamfile?

(I would prefer a 1.2.14 - based patch 😉 )

@egbertbouman
Copy link

egbertbouman commented Oct 28, 2021

I haven't tried backporting the full patch to 1.2.14, but I know from previous testing that removing the proxy check from incoming_connection fixes the issue.

@ichorid
Copy link
Contributor Author

ichorid commented Oct 28, 2021

@egbertbouman , @arvidn , indeed, removing the proxy check in 1.2.14 (session_impl::incoming_connection) fixes the issue, but only in combination with @egbertbouman 's Tribler hidden seeding test fix.

I guess we will use 1.2.12 for the time being. This issue should probably remain open until #6538 is merged.

@arvidn
Copy link
Owner

arvidn commented Nov 5, 2021

I back-ported the fix (but not the test)

@arvidn arvidn modified the milestones: 1.2.15, 1.2.16 Dec 27, 2021
@arvidn arvidn modified the milestones: 1.2.16, 1.2.17 Apr 17, 2022
@proninyaroslav
Copy link

proninyaroslav commented Apr 21, 2022

@arvidn
Maybe it's related, but I'm having problems with the HTTP proxy (it's used to bypass ISP locks), address: px1.blockme.site:23128, the download works, but the seeding doesn't work. In the log, all connections are marked as timed out. proxy_peer_connections is enabled.

Log
2022-04-20 20:36:53.204 [SESSION_LOG] update listen interfaces: 0.0.0.0:40737,[::]:40737
2022-04-20 20:36:53.204 [SESSION_LOG] parsed listen interfaces count: 2, ifaces: 0.0.0.0:40737,[::]:40737
2022-04-20 20:37:04.609 [SESSION_LOG] RECALCULATE UNCHOKE SLOTS: [ peers: 4 eligible-peers: 0 allowed-slots: 8 ]
2022-04-20 20:37:05.609 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 15 seconds
2022-04-20 20:37:05.609 [PEER_LOG] [INFO] [CONNECTION FAILED] 145.249.233.227:39945 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [SESSION_LOG] CONNECTION FAILED: 145.249.233.227:39945
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 15 seconds
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION FAILED] 92.115.97.157:12694 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [SESSION_LOG] CONNECTION FAILED: 92.115.97.157:12694
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 15 seconds
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION FAILED] 89.207.216.91:6882 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [SESSION_LOG] CONNECTION FAILED: 89.207.216.91:6882
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 15 seconds
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION FAILED] 80.250.189.177:15431 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:05.610 [SESSION_LOG] CONNECTION FAILED: 80.250.189.177:15431
2022-04-20 20:37:05.610 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:37:06.483 [TORRENT_LOG] *** update_tracker_timer: [ announce_to_all_tiers: 1 announce_to_all_trackers: 1 num_trackers: 5 ]
2022-04-20 20:37:06.483 [TORRENT_LOG] *** tracker: (0) [ep: 0.0.0.0:40737 ] "http://bt2.t-ru.org/ann" [ found: 0 i->tier: 0 tier: 2147483647 working: 1 fails: 0 limit: 0 upd: 0 ]
2022-04-20 20:37:06.483 [TORRENT_LOG] *** tracker: (1) [ep: 0.0.0.0:40737 ] "http://bt4.t-ru.org/ann" [ found: 1 i->tier: 0 tier: 0 working: 1 fails: 0 limit: 0 upd: 0 ]
2022-04-20 20:37:06.484 [TORRENT_LOG] *** tracker: (2) [ep: 0.0.0.0:40737 ] "http://bt.t-ru.org/ann" [ found: 1 i->tier: 0 tier: 0 working: 1 fails: 0 limit: 0 upd: 0 ]
2022-04-20 20:37:06.484 [TORRENT_LOG] *** tracker: (3) [ep: 0.0.0.0:40737 ] "http://bt3.t-ru.org/ann" [ found: 1 i->tier: 0 tier: 0 working: 1 fails: 0 limit: 0 upd: 0 ]
2022-04-20 20:37:06.484 [TORRENT_LOG] *** tracker: (4) [ep: 0.0.0.0:40737 ] "http://retracker.local/announce" [ found: 1 i->tier: 1 tier: 0 working: 0 fails: 1 limit: 0 upd: 0 ]
2022-04-20 20:37:06.484 [TORRENT_LOG] *** update tracker timer: next_announce < now 0 m_waiting_tracker: 1 next_announce_in: 3251
2022-04-20 20:37:06.610 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:37:06.610 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:37:06.610 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:37:06.610 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:37:46.600 [TORRENT_LOG] *** UPDATE LIST [ torrent_want_tick : 0 ]
2022-04-20 20:38:50.661 [PEER_LOG] [OUTGOING] [OUTGOING_CONNECTION] ep: 51.195.61.93:6890 type: TCP seed: 0 p: 0x7f4a4260 local: 0.0.0.0:0
2022-04-20 20:38:50.661 [PEER_LOG] [INFO] [CONSTRUCT] bt_peer_connection
2022-04-20 20:38:50.661 [TORRENT_LOG] *** UPDATE LIST [ torrent_want_tick : 1 ]
2022-04-20 20:38:50.661 [PEER_LOG] [INFO] [SET_PEER_CLASS] a: 51.195.61.93
2022-04-20 20:38:50.661 [PEER_LOG] [INFO] [CLASS] global tcp 
2022-04-20 20:38:50.661 [PEER_LOG] [OUTGOING] [OPEN] protocol: IPv4
2022-04-20 20:38:50.662 [PEER_LOG] [OUTGOING] [BIND] dst: 0.0.0.0:0 ec: Success
2022-04-20 20:38:50.662 [PEER_LOG] [OUTGOING] [ASYNC_CONNECT] dst: 51.195.61.93:6890
2022-04-20 20:38:50.662 [PEER_LOG] [INFO] [LOCAL ENDPOINT] e: 192.168.1.156:41753
2022-04-20 20:38:50.662 [PEER_LOG] [INCOMING] [CANNOT_READ] quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
2022-04-20 20:38:50.662 [SESSION_LOG] RECALCULATE UNCHOKE SLOTS: [ peers: 1 eligible-peers: 0 allowed-slots: 8 ]
2022-04-20 20:38:50.662 [PEER_LOG] [INFO] [UPDATE_INTEREST] not interesting
2022-04-20 20:38:50.713 [PEER_LOG] [INFO] [CONNECTION FAILED] 51.195.61.93:6890 ERROR: (system:111) Connection refused
2022-04-20 20:38:50.713 [SESSION_LOG] CONNECTION FAILED: 51.195.61.93:6890
2022-04-20 20:38:50.713 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (system:111) Connection refused
2022-04-20 20:38:50.713 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:38:50.713 [TORRENT_LOG] *** UPDATE LIST [ torrent_want_tick : 0 ]
2022-04-20 20:39:05.670 [PEER_LOG] [OUTGOING] [OUTGOING_CONNECTION] ep: 89.207.216.91:6882 type: TCP seed: 0 p: 0x7f4a4240 local: 0.0.0.0:0
2022-04-20 20:39:05.670 [PEER_LOG] [INFO] [CONSTRUCT] bt_peer_connection
2022-04-20 20:39:05.670 [TORRENT_LOG] *** UPDATE LIST [ torrent_want_tick : 1 ]
2022-04-20 20:39:05.670 [PEER_LOG] [INFO] [SET_PEER_CLASS] a: 89.207.216.91
2022-04-20 20:39:05.670 [PEER_LOG] [INFO] [CLASS] global tcp 
2022-04-20 20:39:05.670 [PEER_LOG] [OUTGOING] [OPEN] protocol: IPv4
2022-04-20 20:39:05.670 [PEER_LOG] [OUTGOING] [BIND] dst: 0.0.0.0:0 ec: Success
2022-04-20 20:39:05.671 [PEER_LOG] [OUTGOING] [ASYNC_CONNECT] dst: 89.207.216.91:6882
2022-04-20 20:39:05.674 [PEER_LOG] [INFO] [LOCAL ENDPOINT] e: 192.168.1.156:34085
2022-04-20 20:39:05.674 [PEER_LOG] [INCOMING] [CANNOT_READ] quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
2022-04-20 20:39:05.674 [PEER_LOG] [OUTGOING] [OUTGOING_CONNECTION] ep: 80.250.189.177:15431 type: TCP seed: 0 p: 0x7f4a4220 local: 0.0.0.0:0
2022-04-20 20:39:05.674 [PEER_LOG] [INFO] [CONSTRUCT] bt_peer_connection
2022-04-20 20:39:05.674 [PEER_LOG] [INFO] [SET_PEER_CLASS] a: 80.250.189.177
2022-04-20 20:39:05.674 [PEER_LOG] [INFO] [CLASS] global tcp 
2022-04-20 20:39:05.674 [PEER_LOG] [OUTGOING] [OPEN] protocol: IPv4
2022-04-20 20:39:05.674 [PEER_LOG] [OUTGOING] [BIND] dst: 0.0.0.0:0 ec: Success
2022-04-20 20:39:05.674 [PEER_LOG] [OUTGOING] [ASYNC_CONNECT] dst: 80.250.189.177:15431
2022-04-20 20:39:05.674 [PEER_LOG] [INFO] [LOCAL ENDPOINT] e: 192.168.1.156:43739
2022-04-20 20:39:05.675 [PEER_LOG] [INCOMING] [CANNOT_READ] quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
2022-04-20 20:39:05.675 [PEER_LOG] [OUTGOING] [OUTGOING_CONNECTION] ep: 92.115.97.157:12694 type: TCP seed: 0 p: 0x7f4a4280 local: 0.0.0.0:0
2022-04-20 20:39:05.675 [PEER_LOG] [INFO] [CONSTRUCT] bt_peer_connection
2022-04-20 20:39:05.675 [PEER_LOG] [INFO] [SET_PEER_CLASS] a: 92.115.97.157
2022-04-20 20:39:05.675 [PEER_LOG] [INFO] [CLASS] global tcp 
2022-04-20 20:39:05.675 [PEER_LOG] [OUTGOING] [OPEN] protocol: IPv4
2022-04-20 20:39:05.675 [PEER_LOG] [OUTGOING] [BIND] dst: 0.0.0.0:0 ec: Success
2022-04-20 20:39:05.675 [PEER_LOG] [OUTGOING] [ASYNC_CONNECT] dst: 92.115.97.157:12694
2022-04-20 20:39:05.675 [PEER_LOG] [INFO] [LOCAL ENDPOINT] e: 192.168.1.156:41597
2022-04-20 20:39:05.675 [PEER_LOG] [INCOMING] [CANNOT_READ] quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
2022-04-20 20:39:05.675 [PEER_LOG] [OUTGOING] [OUTGOING_CONNECTION] ep: 145.249.233.227:39945 type: TCP seed: 0 p: 0x7f4a42a0 local: 0.0.0.0:0
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [CONSTRUCT] bt_peer_connection
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [SET_PEER_CLASS] a: 145.249.233.227
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [CLASS] global tcp 
2022-04-20 20:39:05.676 [PEER_LOG] [OUTGOING] [OPEN] protocol: IPv4
2022-04-20 20:39:05.676 [PEER_LOG] [OUTGOING] [BIND] dst: 0.0.0.0:0 ec: Success
2022-04-20 20:39:05.676 [PEER_LOG] [OUTGOING] [ASYNC_CONNECT] dst: 145.249.233.227:39945
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [LOCAL ENDPOINT] e: 192.168.1.156:42455
2022-04-20 20:39:05.676 [PEER_LOG] [INCOMING] [CANNOT_READ] quota: 104  can-write-to-disk: yes queue-limit: 1048576 disconnecting: no  connecting: yes
2022-04-20 20:39:05.676 [SESSION_LOG] RECALCULATE UNCHOKE SLOTS: [ peers: 4 eligible-peers: 0 allowed-slots: 8 ]
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [UPDATE_INTEREST] not interesting
2022-04-20 20:39:05.676 [PEER_LOG] [INFO] [UPDATE_INTEREST] not interesting
2022-04-20 20:39:05.677 [PEER_LOG] [INFO] [UPDATE_INTEREST] not interesting
2022-04-20 20:39:05.677 [PEER_LOG] [INFO] [UPDATE_INTEREST] not interesting
2022-04-20 20:39:20.677 [SESSION_LOG] RECALCULATE UNCHOKE SLOTS: [ peers: 4 eligible-peers: 0 allowed-slots: 8 ]
2022-04-20 20:39:23.679 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 18 seconds
2022-04-20 20:39:23.679 [PEER_LOG] [INFO] [CONNECTION FAILED] 92.115.97.157:12694 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.679 [SESSION_LOG] CONNECTION FAILED: 92.115.97.157:12694
2022-04-20 20:39:23.679 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.679 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 18 seconds
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION FAILED] 80.250.189.177:15431 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.680 [SESSION_LOG] CONNECTION FAILED: 80.250.189.177:15431
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 18 seconds
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION FAILED] 145.249.233.227:39945 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.680 [SESSION_LOG] CONNECTION FAILED: 145.249.233.227:39945
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECT_FAILED] waited 18 seconds
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION FAILED] 89.207.216.91:6882 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.680 [SESSION_LOG] CONNECTION FAILED: 89.207.216.91:6882
2022-04-20 20:39:23.680 [PEER_LOG] [INFO] [CONNECTION_FAILED] op: 16 ERROR: (libtorrent:36) timed out
2022-04-20 20:39:23.681 [TORRENT_LOG] *** UPDATE LIST [ torrent_want_tick : 0 ]
2022-04-20 20:39:24.679 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:39:24.680 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:39:24.680 [PEER_LOG] [INFO] [CONNECTION CLOSED] 
2022-04-20 20:39:24.680 [PEER_LOG] [INFO] [CONNECTION CLOSED]

@arvidn
Copy link
Owner

arvidn commented Sep 17, 2022

There were recent improvements to the socks5 support in libtorrent to accept incoming udp packets with the source address as a domain name. as well as the bind address in the udp associate response supporting domain names.

Regarding the HTTP proxy, it's unrelated to socks. My guess is that since you can't receive incoming connection, you can't seed to peers who also can't accept incoming connections.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants