[tor-bugs] #9239 [Obfsproxy]: fail to make a connection because of 'upstream data before doing handshake'

[Tor Bug Tracker & Wiki]

#9239: fail to make a connection because of  'upstream data before doing
handshake'
-----------------------+----------------------------------------------------
 Reporter:  c95517     |          Owner:  asn
     Type:  defect     |         Status:  new
 Priority:  normal     |      Milestone:     
Component:  Obfsproxy  |        Version:     
 Keywords:             |         Parent:     
   Points:             |   Actualpoints:     
-----------------------+----------------------------------------------------
 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>

-- 
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/9239>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online