Discussion of libtorrent, a C++ bittorrent library.

Дмитрий Скрябин | 2 Aug 2012 07:39

uTP upload isn't working (python bindings)

Hello.
I have a problem: my torrent client can't upload torrents via uTP.
My test stand:
Machine 1: Debian squeeze, libtorrent 0.16.2, python 2.6. IP:88.86.211.x
Machine 2: Mac OS X, uTorrent Version 1.6.5. IP:85.12.217.x

I try to upload torrent from libtorrent to uTorrent
To select uTP, I deny TCP uploads by setting enable_tcp_incoming to false.

Short description: libtorrent got an error "Connection timed out", uTorrent got "Invalid packet length".

Here is the logs:

* uTorrent Logs:
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): Connecting: source: T
[03:05:19]  88.86.211.x:6881(Samovary by Krokoz - Select Edition VL SP1): Connecting: source: T
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.1.0.0
(0.0)]: Handshake completed
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.1.0.0
(0.0)]: Send Have 789
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.1.0.0
(0.0)]: Send Have 794
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.1.0.0
(0.0)]: Send Have 8
[03:05:19]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.1.0.0
(0.0)]: Send Have 352
[03:05:19]  88.86.211.x:6881(Samovary by Krokoz - Select Edition VL SP1): Disconnect: Connection closed
[03:05:31]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.16.2.0
(94.3)]: Send Have 950
[03:05:36]  88.86.211.x:6881 [uTP](Samovary by Krokoz - Select Edition VL SP1): [libtorrent/0.16.2.0

(Continue reading)

headers

Dmitry | 2 Aug 2012 13:54

Re: uTP upload isn't working (python bindings)

I want to add additional info from utp.log:
[000006416091] 0x7f84800e9b60: sending packet seq_nr:16090 ack_nr:61135 
type:ST_STATE id:22112 target:85.12.217.x:59696 size:20 error:Success 
send_buffer_size:0 cwnd:16408 adv_wnd:3670004 in-flight:519 mtu:16408 
timestamp:379142883 time_diff:2353805702 mtu_probe:0 ex tension:0
[000006525072] 0x7f84800e9b60: sending packet seq_nr:16090 ack_nr:61135 
type:ST_DATA id:22112 target:85.12.217.x:59696 size:25 error:Success 
send_buffer_size:0 cwnd:16408 adv_wnd:3670016 in-flight:0 mtu:16408 
timestamp:379251855 time_diff:2353804775 mtu_probe:0 extension:0
[000006635600] 0x7f84800e9b60: skipping send seq_nr:16091 ack_nr:61135
 id:22112 target:85.12.217.x:59696 header_size:20 error:Success
 send_buffer_size:0 cwnd:16408 ret:0 adv_wnd:3670016 in-flight:0 mtu:16408
[000007695912] 0x7f84800e9b60: skipping send seq_nr:16094 ack_nr:61137 
id:22112 target:85.12.217.67:59696 header_size:20 error:Success
 send_buffer_size:16374 cwnd:17879 ret:0 adv_wnd:3670016 in-flight:16388 
 mtu:16408
[000007696085] 0x7f84800e9b60: skipping send seq_nr:16094 ack_nr:61137 
id:22112 target:85.12.217.67:59696 header_size:20 error:Success
 send_buffer_size:16374 cwnd:17879 ret:0 adv_wnd:3670016 in-flight:16388 
 mtu:16408

There are many such lines in log file. In the end of logfile:

[000009461089] 0x7f84800e9b60: sending FIN seq_nr:16096 ack_nr:61139 
type:ST_FIN id:22112 target:85.12.217.x:59696 size:20 error:Success 
send_buffer_size:15319
[000010059688] 0x7f84800e9b60: re-sending packet seq_nr:16096 ack_nr:61139 
type:ST_FIN id:22112 target:85.12.217.x:59696 size:20 error:Success 
send_buffer_size:15319 cwnd:16408 adv_wnd:3668963 in-flight:0 mtu:16408 
timestamp:382786457 time_diff:2353804216

(Continue reading)

headers

Dmitriy Skryabin | 2 Aug 2012 14:16

Re: uTP upload isn't working (python bindings)

Sorry, in my previous post logs are not full. There are full log of connection between libtorrent and
uTorrent (he is long):

root <at> tc1:/opt/TCSystem/torrent-client# cat utp.log | grep 0x7f84800e9b60 | more
[000006384991] 0x7f84800e9b60: intializing MTU to: 16408 [548, 16408]
[000006385003] 0x7f84800e9b60: their_delay::add_sample:2353807524 prev_base:0 new_base:2353807524
[000006385007] 0x7f84800e9b60: incoming packet reply_micro:2353807524 base_change:0
[000006385010] 0x7f84800e9b60: updating timeout to: now + 3000
[000006385014] 0x7f84800e9b60: incoming packet seq_nr:61132 ack_nr:0 type:ST_SYN id:22112 size:0
timestampdiff:0 timestamp:2320271549 
our ack_nr:0 our seq_nr:0 our acked_seq_nr:0 our state:NONE
[000006385021] 0x7f84800e9b60: received ST_SYN state:CONNECTED seq_nr:16088 ack_nr:61132
[000006385043] 0x7f84800e9b60: sending packet seq_nr:16088 ack_nr:61132 type:ST_STATE id:22112
target:85.12.217.x:59696 size:20 error
:Success send_buffer_size:0 cwnd:16408 adv_wnd:3670016 in-flight:0 mtu:16408 timestamp:379111834
time_diff:2353807524 mtu_probe:0 exte
nsion:0
[000006385206] 0x7f84800e9b60: add_read_buffer 20 bytes
[000006385213] 0x7f84800e9b60: new read handler. 0 bytes in buffer
[000006391444] 0x7f84800e9b60: their_delay::add_sample:2353807292 prev_base:2353807524 new_base:2353807292
[000006391453] 0x7f84800e9b60: incoming packet reply_micro:2353807292 base_change:-232
[000006391456] 0x7f84800e9b60: updating timeout to: now + 500
[000006391460] 0x7f84800e9b60: incoming packet seq_nr:61133 ack_nr:16087 type:ST_DATA id:22113
size:68 timestampdiff:1941166396 timest
amp:2320278252 our ack_nr:61132 our seq_nr:16088 our acked_seq_nr:16087 our state:CONNECTED
[000006391468] 0x7f84800e9b60: setting read timeout to 100 ms from now
[000006391470] 0x7f84800e9b60: copied 20 bytes into user receive buffer
[000006391475] 0x7f84800e9b60: remove inbuf: 61133 (0)
[000006391479] 0x7f84800e9b60: calling read handler read:20
[000006391489] 0x7f84800e9b60: calling read handler read:20 ec:Success kill:0

(Continue reading)