Race condition in t.c.s.c.SSHConnection sendClose can expect remote connection before it's opened

	tommyvn reported
Trac ID	trac#7960
Type	defect
Created	2015-07-03 20:11:29Z

I'm seeing very occasional exceptions on connections to a reverse conch tunnel that connects and disconnects potentially very quickly:

2015-07-03 08:26:45+0000 [SSHForwardingClient,0,127.0.0.1] Unhandled Error
        Traceback (most recent call last):
          File "/opt/pypy-2.6.0-linux64/site-packages/ruppells/sockets/sshin.py", line 304, in start
            reactor.run()
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/base.py", line 1192, in run
            self.mainLoop()
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/base.py", line 1204, in mainLoop
            self.doIteration(t)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/epollreactor.py", line 396, in doPoll
            log.callWithLogger(selectable, _drdw, selectable, fd, event)
        --- <exception caught here> ---
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/python/log.py", line 88, in callWithLogger
            return callWithContext({"system": lp}, func, *args, **kw)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/python/log.py", line 73, in callWithContext
            return context.call({ILogContext: newCtx}, func, *args, **kw)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/posixbase.py", line 627, in _doReadOrWrite
            self._disconnectSelectable(selectable, why, inRead)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/posixbase.py", line 260, in _disconnectSelectable
            selectable.connectionLost(f)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/internet/tcp.py", line 299, in connectionLost
            protocol.connectionLost(reason)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/conch/ssh/forwarding.py", line 129, in connectionLost
            self.channel.loseConnection()
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/conch/ssh/channel.py", line 253, in loseConnection
            self.conn.sendClose(self)
          File "/opt/pypy-2.6.0-linux64/site-packages/twisted/conch/ssh/connection.py", line 510, in sendClose
            self.channelsToRemoteChannel[channel]))
        exceptions.KeyError: <ruppells.sockets.sshin.SSHListenServerForwardingChannel2 instance at 0x00007f8eb6aa02c0>

It seems that the following code can be called on a connection that doesn't yet have the remote channel:

self.transport.sendPacket(MSG_CHANNEL_CLOSE, struct.pack('>L',
                self.channelsToRemoteChannel[channel]))

I've worked around it with a sub-class that overrides the sendClose method with one that wraps that statement in a check to see if channel is indeed in self.channelsToRemoteChannel but I've not confirmed that that dict isn't getting filled in from a deferred somewhere so I might be simply masking the problem.
I've also not made a [http://sscce.org/] yet, I'll get that on here when I start work on a patch.

If no one's looked into this when I've got more time I'll follow the calls and see if the fix is that simple and send a patch.

trac-id__7960 7960
type__defect defect
reporter__tommyvn tommyvn
priority__normal normal
milestone__ 
branch__ 
branch_author__ 
status__new new
resolution__None None
component__conch conch
keywords__conch__race_condition__sendClose conch, race condition, sendClose
time__1435954289301299 1435954289301299
changetime__1547204430479041 1547204430479041
version__None None
owner__None None
cc__z3p

Start in twisted/conch/ssh/connection.py at sendClose, then follow the callers in twisted/conch/ssh/channel.py and forwarding.py. Reproduce the rapid connect/disconnect reverse Conch tunnel case and trace when channelsToRemoteChannel is populated; done means sendClose no longer raises KeyError when the remote channel has not opened.