Opened 7 years ago

Closed 7 years ago

#9239 closed defect (wontfix)

fail to make a connection because of 'upstream data before doing handshake'

Reported by: c95517 Owned by: asn
Priority: Medium Milestone:
Component: Archived/Obfsproxy Version:
Severity: Keywords:
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

on HOST A(Obfsproxy version: 0.2.2_5), which is a remote machine, the configuration as following
/usr/local/bin/obfsproxy --log-file /var/log/obfsproxy/obfsproxy.log --log-min-severity=debug obfs2 --shared-secret 24aee8abd7c8f7b6cab862331f82b27e --dest=127.0.0.1:22 server 0.0.0.0:80

on HOST B(Obfsproxy version: 0.2.2), which is a local machine, the configuration as following():
/usr/local/bin/obfsproxy --log-file /var/log/obfsproxy/obfsproxy.log --log-min-severity=debug obfs2 --shared-secret 24aee8abd7c8f7b6cab862331f82b27e socks 127.0.0.1:9999

on HOST B, make a ssh tunnel with the command:
ssh -vvv -o ProxyCommand='nc -X 4 -x 127.0.0.1:9999 %h %p' -l tunnel -i ~/.ssh/tunnel -p 80 HOSTA

if I capture packets on HOST A with the command:
tcpdump -i eth0 port 80

I will fail to build a tunnel, the log in HOST B :

2013-07-11 16:34:24,129 [DEBUG] Starting obfs2 with shared secret: 24aee8abd7c8f7b6cab862331f82b27e
2013-07-11 16:34:24,129 [DEBUG] socks_up_0x1076cef90: Received SOCKS handshake data.
2013-07-11 16:34:24,997 [DEBUG] socks_down_0x1076cef50: Received 2703 bytes:

... ... ... ...

2013-07-11 16:34:24,997 [ERROR] Unhandled Error
Traceback (most recent call last):

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/python/log.py", line 88, in callWithLogger

return callWithContext({"system": lp}, func, *args, kw)

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/python/log.py", line 73, in callWithContext

return context.call({ILogContext: newCtx}, func, *args, kw)

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/python/context.py", line 118, in callWithContext

return self.currentContext().callWithContext(ctx, func, *args, kw)

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/python/context.py", line 81, in callWithContext

return func(*args,kw)

--- <exception caught here> ---

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/internet/selectreactor.py", line 151, in _doReadOrWrite

why = getattr(selectable, method)()

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/internet/tcp.py", line 215, in doRead

return self._dataReceived(data)

File "/usr/bin/python/python27/lib/python2.7/site-packages/twisted/internet/tcp.py", line 221, in _dataReceived

rval = self.protocol.dataReceived(data)

File "/usr/bin/python/python27/lib/python2.7/site-packages/obfsproxy/network/socks.py", line 52, in dataReceived

assert(self.circuit.circuitIsReady()) # XXX Is this always true?

exceptions.AssertionError:

2013-07-11 16:34:24,998 [DEBUG] socks_down_0x1076cef50: Connection was lost ().
2013-07-11 16:34:24,998 [DEBUG] socks_down_0x1076cef50: Closing connection.

the log in HOST A:

2013-07-11 16:34:24,376 [DEBUG] conn_0xa1242cc: connectionMade (server): Setting it as upstream on our circuit.
2013-07-11 16:34:24,376 [DEBUG] circ_0xa12422c: Setting upstream connection (conn_0xa1242cc).
2013-07-11 16:34:24,377 [DEBUG] circ_0xa12422c: Circuit completed.
2013-07-11 16:34:24,859 [DEBUG] obfs2 handshake: responder queued 2703 bytes (padding_length: 2679).
2013-07-11 16:34:24,859 [DEBUG] conn_0xa12430c: Writing 2703 bytes.
2013-07-11 16:34:24,862 [DEBUG] circ_0xa12422c: upstream: Received 41 bytes.
2013-07-11 16:34:24,862 [DEBUG] Got upstream data before doing handshake. Caching.
2013-07-11 16:34:24,869 [DEBUG] conn_0xa12430c: dataReceived called without a reason.
2013-07-11 16:34:25,059 [DEBUG] conn_0xa12430c: Connection was lost (Connection was closed cleanly.).
2013-07-11 16:34:25,059 [DEBUG] conn_0xa12430c: Closing connection.
2013-07-11 16:34:25,059 [DEBUG] circ_0xa12422c: Tearing down circuit.
2013-07-11 16:34:25,059 [DEBUG] conn_0xa1242cc: Closing connection.
2013-07-11 16:34:25,060 [DEBUG] conn_0xa1242cc: Connection was lost (Connection was closed cleanly.).
2013-07-11 16:34:25,060 [INFO] Stopping factory <obfsproxy.network.network.StaticDestinationClientFactory instance at 0xa12424c>

Child Tickets

Change History (5)

comment:1 Changed 7 years ago by asn

Thanks for catching this bug. This happens because the SSH server sends data first (before the client), and the code did not expect that. Will try to fix soon.

comment:2 Changed 7 years ago by asn

Resolution: fixed
Status: newclosed

Fixed here: https://gitweb.torproject.org/pluggable-transports/obfsproxy.git/commitdiff/b1ae5afc64d9035af1d4a1b5619b7819239e6f25

Will hopefully do a release with the fix soon. You can use the git master till then.

If it doesn't fix the issue for you (or you have any questions), please reopen this ticket :)

comment:3 Changed 7 years ago by c95517

Yes, it fixed this issue. asn, Thank you.

comment:4 Changed 7 years ago by jonolumb

Resolution: fixed
Status: closedreopened

I am running version 0.2.1 and am having this problem, below are the server logs and client logs. Has a newer version been released since this fix was committed? I am using the experimental PPA... Thanks!

======= SERVER ========

2013-09-09 08:06:12,706 [WARNING] Obfsproxy (version: 0.2.1) starting up.
2013-09-09 08:06:12,706 [DEBUG] argv: ['/usr/bin/obfsproxy', '--log-min-severity=debug', 'obfs2', '--dest=127.0.0.1:22', 'server', '0.0.0.0:443']
2013-09-09 08:06:12,706 [DEBUG] args: Namespace(dest=('127.0.0.1', 22), ext_cookie_file=None, listen_addr=('0.0.0.0', 443), log_file=None, log_min_severity='debug', mode='server', name='obfs2', no_log=False, no_safe_logging=False, shared_secret=None, ss_hash_iterations=None, validation_function=<bound method type.validate_external_mode_cli of <class 'obfsproxy.transports.obfs2.Obfs2Transport'>>)
2013-09-09 08:06:12,707 [INFO] StaticDestinationServerFactory starting on 443
2013-09-09 08:06:12,707 [INFO] Starting factory <obfsproxy.network.network.StaticDestinationServerFactory instance at 0x1bd09e0>
2013-09-09 08:06:12,707 [DEBUG] fact_s_0x1bd09e0: Starting up static destination server factory.
2013-09-09 08:06:12,707 [INFO] Launched 'server' listener at '[scrubbed]:443' for transport 'obfs2'.
2013-09-09 08:06:17,414 [DEBUG] fact_s_0x1bd09e0: New connection from [scrubbed]:38864.
2013-09-09 08:06:17,414 [INFO] Starting factory <obfsproxy.network.network.StaticDestinationClientFactory instance at 0x1bd1290>
2013-09-09 08:06:17,414 [DEBUG] fact_c_0x1bd1290: Client factory started connecting.
2013-09-09 08:06:17,415 [DEBUG] conn_0x1bcfbd0: connectionMade (server): Setting it as downstream on our circuit.
2013-09-09 08:06:17,415 [DEBUG] circ_0x1bd1248: Setting downstream connection (conn_0x1bcfbd0).
2013-09-09 08:06:17,423 [DEBUG] conn_0x1bcfd10: connectionMade (server): Setting it as upstream on our circuit.
2013-09-09 08:06:17,424 [DEBUG] circ_0x1bd1248: Setting upstream connection (conn_0x1bcfd10).
2013-09-09 08:06:17,424 [DEBUG] circ_0x1bd1248: Circuit completed.
2013-09-09 08:06:17,425 [DEBUG] obfs2 handshake: responder queued 7500 bytes (padding_length: 7476).
2013-09-09 08:06:17,425 [DEBUG] conn_0x1bcfbd0: Writing 7500 bytes.
2013-09-09 08:06:17,427 [DEBUG] circ_0x1bd1248: upstream: Received 41 bytes.
2013-09-09 08:06:17,427 [DEBUG] Got upstream data before doing handshake. Caching.
2013-09-09 08:06:17,435 [DEBUG] conn_0x1bcfbd0: dataReceived called without a reason.

======= CLIENT =======

sudo obfsproxy --log-min-severity=debug obfs2 --dest=175.41.179.239:443 server 0.0.0.0:8888
2013-09-09 16:06:06,045 [WARNING] Obfsproxy (version: 0.2.1) starting up.
2013-09-09 16:06:06,045 [DEBUG] argv: ['/usr/bin/obfsproxy', '--log-min-severity=debug', 'obfs2', '--dest=175.41.179.239:443', 'server', '0.0.0.0:8888']
2013-09-09 16:06:06,045 [DEBUG] args: Namespace(dest=('175.41.179.239', 443), ext_cookie_file=None, listen_addr=('0.0.0.0', 8888), log_file=None, log_min_severity='debug', mode='server', name='obfs2', no_log=False, no_safe_logging=False, shared_secret=None, ss_hash_iterations=None, validation_function=<bound method type.validate_external_mode_cli of <class 'obfsproxy.transports.obfs2.Obfs2Transport'>>)
2013-09-09 16:06:06,046 [INFO] StaticDestinationServerFactory starting on 8888
2013-09-09 16:06:06,046 [INFO] Starting factory <obfsproxy.network.network.StaticDestinationServerFactory instance at 0x9edcf6c>
2013-09-09 16:06:06,046 [DEBUG] fact_s_0x9edcf6c: Starting up static destination server factory.
2013-09-09 16:06:06,046 [INFO] Launched 'server' listener at '[scrubbed]:8888' for transport 'obfs2'.
2013-09-09 16:06:23,093 [DEBUG] fact_s_0x9edcf6c: New connection from [scrubbed]:36395.
2013-09-09 16:06:23,094 [INFO] Starting factory <obfsproxy.network.network.StaticDestinationClientFactory instance at 0x9ed8d8c>
2013-09-09 16:06:23,094 [DEBUG] fact_c_0x9ed8d8c: Client factory started connecting.
2013-09-09 16:06:23,095 [DEBUG] conn_0x9ed888c: connectionMade (server): Setting it as downstream on our circuit.
2013-09-09 16:06:23,095 [DEBUG] circ_0x9ed8e6c: Setting downstream connection (conn_0x9ed888c).
2013-09-09 16:06:23,226 [DEBUG] conn_0x9ee062c: connectionMade (server): Setting it as upstream on our circuit.
2013-09-09 16:06:23,226 [DEBUG] circ_0x9ed8e6c: Setting upstream connection (conn_0x9ee062c).
2013-09-09 16:06:23,226 [DEBUG] circ_0x9ed8e6c: Circuit completed.
2013-09-09 16:06:23,230 [DEBUG] obfs2 handshake: responder queued 7123 bytes (padding_length: 7099).
2013-09-09 16:06:23,230 [DEBUG] conn_0x9ed888c: Writing 7123 bytes.
2013-09-09 16:06:23,241 [DEBUG] conn_0x9ed888c: dataReceived called without a reason.
2013-09-09 16:06:23,369 [DEBUG] circ_0x9ed8e6c: upstream: Received 4344 bytes.
2013-09-09 16:06:23,369 [DEBUG] Got upstream data before doing handshake. Caching.
2013-09-09 16:06:23,370 [DEBUG] circ_0x9ed8e6c: upstream: Received 7240 bytes.
2013-09-09 16:06:23,371 [DEBUG] Got upstream data before doing handshake. Caching.
2013-09-09 16:06:23,373 [DEBUG] circ_0x9ed8e6c: upstream: Received 7500 bytes.
2013-09-09 16:06:23,374 [DEBUG] Got upstream data before doing handshake. Caching.
2013-09-09 16:06:33,155 [DEBUG] conn_0x9ee062c: Connection was lost (Connection was closed cleanly.).
2013-09-09 16:06:33,155 [DEBUG] conn_0x9ee062c: Closing connection.
2013-09-09 16:06:33,156 [DEBUG] circ_0x9ed8e6c: Tearing down circuit.
2013-09-09 16:06:33,156 [DEBUG] conn_0x9ed888c: Closing connection.
2013-09-09 16:06:33,156 [INFO] Stopping factory <obfsproxy.network.network.StaticDestinationClientFactory instance at 0x9ed8d8c>
2013-09-09 16:06:33,156 [DEBUG] conn_0x9ed888c: Connection was lost (Connection was closed cleanly.).

comment:5 Changed 7 years ago by asn

Resolution: wontfix
Status: reopenedclosed

This ticket is about the old C-based obfsproxy. Closing.

Note: See TracTickets for help on using tickets.