Opened 12 years ago

Closed 12 years ago

Last modified 12 years ago

#1389 closed Bug (fixed)

bitcomet handshake with TransmissionBT failed

Reported by: shijun.wu Owned by: charles
Priority: High Milestone: 1.40
Component: libtransmission Version: 1.34
Severity: Critical Keywords: obfuscated bitcomet
Cc:

Description

I found bitcomet 1.05 handshake failed with transmissionbt 1.34, I tune the transmissionbt on debug mode, got the following things:

Port Forwarding: accept socket 9 for incoming peer connections [17:22:23.860] 192.168.1.107:1776 setting to state [awaiting handshake] (handshake.c:163) [17:22:23.861] 192.168.1.107:1776 handling canRead; state is [awaiting handshake] (handshake.c:939) [17:22:23.861] 192.168.1.107:1776 payload: need 48, got 3265 (handshake.c:555) [17:22:23.861] 192.168.1.107:1776 I think peer is sending us an encrypted handshake... (handshake.c:580) [17:22:23.861] 192.168.1.107:1776 setting to state [awaiting ya] (handshake.c:163) [17:22:23.861] 192.168.1.107:1776 handling canRead; state is [awaiting ya] (handshake.c:939) [17:22:23.861] 192.168.1.107:1776 in readYa... need 96, have 3265 (handshake.c:700) [17:22:23.881] 192.168.1.107:1776 sending B->A: Diffie Hellman Yb, PadB (handshake.c:710) [17:22:23.884] 192.168.1.107:1776 setting to state [awaiting pad a] (handshake.c:163) [17:22:23.884] 192.168.1.107:1776 handling canRead; state is [awaiting pad a] (handshake.c:939) [17:22:23.884] 192.168.1.107:1776 looking to get past pad a... & resync on hash('req',S) ... have 3169 bytes (handshake.c:730) [17:22:23.884] 192.168.1.107:1776 looking for hash('req',S) ... draining 1647 bytes (handshake.c:743) [17:22:23.884] 192.168.1.107:1776 draining one more byte (handshake.c:748) [17:22:23.884] 192.168.1.107:1776 handling canRead; state is [awaiting pad a] (handshake.c:939) [17:22:23.884] 192.168.1.107:1776 looking to get past pad a... & resync on hash('req',S) ... have 1521 bytes (handshake.c:730) [17:22:23.884] 192.168.1.107:1776 looking for hash('req',S) ... draining 808 bytes (handshake.c:743) [17:22:23.884] 192.168.1.107:1776 draining one more byte (handshake.c:748) [17:22:23.884] 192.168.1.107:1776 handling canRead; state is [awaiting pad a] (handshake.c:939) [17:22:23.884] 192.168.1.107:1776 looking to get past pad a... & resync on hash('req',S) ... have 712 bytes (handshake.c:730) [17:22:23.884] 192.168.1.107:1776 looking for hash('req',S) ... draining 408 bytes (handshake.c:743) [17:22:23.884] 192.168.1.107:1776 draining one more byte (handshake.c:748) [17:22:23.884] 192.168.1.107:1776 handling canRead; state is [awaiting pad a] (handshake.c:939) [17:22:23.884] 192.168.1.107:1776 looking to get past pad a... & resync on hash('req',S) ... have 303 bytes (handshake.c:730) [17:22:23.885] 192.168.1.107:1776 no luck so far.. draining 303 bytes (handshake.c:739) [17:22:23.904] 192.168.1.107:1776 handling canRead; state is [awaiting pad a] (handshake.c:939) [17:22:23.904] 192.168.1.107:1776 looking to get past pad a... & resync on hash('req',S) ... have 56 bytes (handshake.c:730) [17:22:23.904] 192.168.1.107:1776 looking for hash('req',S) ... draining 0 bytes (handshake.c:743) [17:22:23.904] 192.168.1.107:1776 found it... looking setting to awaiting_crypto_provide (handshake.c:753) [17:22:23.904] 192.168.1.107:1776 setting to state [awaiting crypto_provide] (handshake.c:163) [17:22:23.904] 192.168.1.107:1776 handling canRead; state is [awaiting crypto_provide] (handshake.c:939) [17:22:23.904] 192.168.1.107:1776 reading obfuscated torrent hash... (handshake.c:786) [17:22:23.905] 192.168.1.107:1776 found the torrent; it's [Azureus4.0.0.2.jar] (handshake.c:793) [17:22:23.905] 192.168.1.107:1776 crypto_provide is 2 (handshake.c:820) [17:22:23.905] 192.168.1.107:1776 padc is 0 (handshake.c:823) [17:22:23.905] 192.168.1.107:1776 setting to state [awaiting pad c] (handshake.c:163) [17:22:23.905] 192.168.1.107:1776 handling canRead; state is [awaiting pad c] (handshake.c:939) [17:22:23.905] 192.168.1.107:1776 ia_len is 0 (handshake.c:841) [17:22:23.905] 192.168.1.107:1776 setting to state [awaiting ia] (handshake.c:163) [17:22:38.913] 192.168.1.107:1776 libevent got an error what==65, errno=11 (Resource temporarily unavailable) (handshake.c:1016) [17:22:38.913] 192.168.1.107:1776 handshakeDone: aborting (handshake.c:978)

Change History (9)

comment:1 Changed 12 years ago by charles

  • Component changed from Transmission to libtransmission
  • Milestone changed from None Set to 1.40
  • Owner set to charles
  • Status changed from new to assigned

comment:2 Changed 12 years ago by charles

Looks like this is happening iff these conditions are all true:

  1. The peer intiates the connection to Transmission
  2. encryption is forced
  3. During the handshake's third blocking step, the peer's len(PadC) is 0
  4. During the handshake's third blocking step, the peer's len(IA) is 0

comment:3 Changed 12 years ago by charles

Possible fix in r6985

comment:4 Changed 12 years ago by charles

More changes made; r6987 is a more likely fix to test

comment:5 Changed 12 years ago by charles

  • Resolution set to fixed
  • Status changed from assigned to closed

Confirmed fixed in r6987. Lacrocivious and I tested [Transmission,BitComet?]x[intiating handshake,receiving handshake]x[encrypted,plaintext] and it all seems to be working just fine now.

shijun.wu: thanks for the bug report. I'm glad this got filed & fixed in time for 1.40

comment:6 Changed 12 years ago by shijun.wu

  • Resolution fixed deleted
  • Status changed from closed to reopened

Really Charles! I checked out the trunk code, and tested it's ok now, but I found another issue, looks like Transmission1.34+ transfer data with others bt client(bitcomet, bittorrent6.1.1,bitspirit...) is very slow->only 33kbps(these bt client is in our private lan network), when I use Transmission1.34 release build, it can up to 2Mbps. I tune Transmission1.34+ on debug mode, the following msg printed:

[13:12:43.249] 192.168.1.107:2173 adding 3251 bytes into io->output (peer-io.c:724) [13:12:43.249] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134) [13:12:43.250] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: wrote 3251 bytes; 13146 left in block (peer-msgs.c:1732) [13:12:43.250] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: stalled writing block... uploadMax 0, outlen 0 (peer-msgs.c:1736) [13:12:43.251] 192.168.1.107:2173 unlimited reading... (peer-io.c:142) [13:12:43.251] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134) [13:12:43.252] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: stalled writing block... uploadMax 0, outlen 0 (peer-msgs.c:1736) [13:12:43.253] 192.168.1.107:2173 didWrite... io->outputBufferSize was 4096, is now 0 (peer-io.c:175) [13:12:43.254] 192.168.1.107:2173 wrote 4096 bytes to peer... upload bytesLeft is now 0 (peer-io.c:187) [13:12:43.254] 192.168.1.107:2173 after adjusting the output buffer, its size is now 0 (peer-io.c:134) [13:12:43.368] 192.168.1.107:2173 adding 4096 bytes into io->output (peer-io.c:724) [13:12:43.368] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134) [13:12:43.369] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: wrote 4096 bytes; 9050 left in block (peer-msgs.c:1732) [13:12:43.369] 192.168.1.107:2173 unlimited reading... (peer-io.c:142) [13:12:43.369] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134) [13:12:43.369] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: stalled writing block... uploadMax 0, outlen 0 (peer-msgs.c:1736) [13:12:43.369] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: stalled writing block... uploadMax 0, outlen 0 (peer-msgs.c:1736) [13:12:43.369] 192.168.1.107:2173 unlimited reading... (peer-io.c:142) [13:12:43.369] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134) [13:12:43.369] Azureus4.0.0.2.jar - 192.168.1.107:2173 6.1.1?: stalled writing block... uploadMax 0, outlen 0 (peer-msgs.c:1736) [13:12:43.371] 192.168.1.107:2173 didWrite... io->outputBufferSize was 4096, is now 0 (peer-io.c:175) [13:12:43.371] 192.168.1.107:2173 wrote 4096 bytes to peer... upload bytesLeft is now 0 (peer-io.c:187) [13:12:43.371] 192.168.1.107:2173 after adjusting the output buffer, its size is now 0 (peer-io.c:134) [13:12:43.500] 192.168.1.107:2173 adding 4096 bytes into io->output (peer-io.c:724) [13:12:43.500] 192.168.1.107:2173 after adjusting the output buffer, its size is now 4096 (peer-io.c:134)

comment:7 Changed 12 years ago by shijun.wu

Really thanks Charles's hard work !

comment:8 Changed 12 years ago by charles

  • Resolution set to fixed
  • Status changed from reopened to closed

It was an unfortunate bug in the new bandwidth allocation code that was recently added, but has already been fixed in r6991, right after the BitComet? fixes went in. :)

comment:9 Changed 12 years ago by charles

  • Priority changed from Highest to High
Note: See TracTickets for help on using tickets.