# Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: dwayne@oscl.ca-20080416224822-99cnf7dfwr2erkd2 # target_branch: http://www.lag.net/paramiko/bzr/paramiko/ # testament_sha1: 12bd5771411c90be8c1f0cd313f0c878049beb2f # timestamp: 2008-04-16 17:19:08 -0600 # base_revision_id: robey@lag.net-20080324065154-w8p2lhawmsbynxc0 # # Begin patch === modified file 'paramiko/channel.py' --- paramiko/channel.py 2008-03-23 02:36:16 +0000 +++ paramiko/channel.py 2008-04-16 22:48:22 +0000 @@ -693,9 +693,11 @@ m.add_byte(chr(MSG_CHANNEL_DATA)) m.add_int(self.remote_chanid) m.add_string(s[:size]) - self.transport._send_user_message(m) finally: self.lock.release() + # Note: We release self.lock before calling _send_user_message. + # Otherwise, we can deadlock during re-keying. + self.transport._send_user_message(m) return size def send_stderr(self, s): @@ -729,9 +731,11 @@ m.add_int(self.remote_chanid) m.add_int(1) m.add_string(s[:size]) - self.transport._send_user_message(m) finally: self.lock.release() + # Note: We release self.lock before calling _send_user_message. + # Otherwise, we can deadlock during re-keying. + self.transport._send_user_message(m) return size def sendall(self, s): === modified file 'paramiko/sftp_client.py' --- paramiko/sftp_client.py 2008-03-23 02:36:16 +0000 +++ paramiko/sftp_client.py 2008-04-16 19:33:02 +0000 @@ -106,7 +106,11 @@ from_transport = classmethod(from_transport) def _log(self, level, msg): - super(SFTPClient, self)._log(level, "[chan " + self.sock.get_name() + "] " + msg) + if issubclass(type(msg), list): + for m in msg: + super(SFTPClient, self)._log(level, "[chan " + self.sock.get_name() + "] " + m) + else: + super(SFTPClient, self)._log(level, "[chan " + self.sock.get_name() + "] " + msg) def close(self): """ === modified file 'paramiko/sftp_server.py' --- paramiko/sftp_server.py 2008-03-23 02:36:16 +0000 +++ paramiko/sftp_server.py 2008-04-16 19:33:02 +0000 @@ -75,7 +75,11 @@ self.server = sftp_si(server, *largs, **kwargs) def _log(self, level, msg): - super(SFTPServer, self)._log(level, "[chan " + self.sock.get_name() + "] " + msg) + if issubclass(type(msg), list): + for m in msg: + super(SFTPServer, self)._log(level, "[chan " + self.sock.get_name() + "] " + m) + else: + super(SFTPServer, self)._log(level, "[chan " + self.sock.get_name() + "] " + msg) def start_subsystem(self, name, transport, channel): self.sock = channel === modified file 'tests/test_transport.py' --- tests/test_transport.py 2008-03-24 06:51:11 +0000 +++ tests/test_transport.py 2008-04-16 22:44:45 +0000 @@ -27,11 +27,14 @@ import time import threading import unittest +import random from paramiko import Transport, SecurityOptions, ServerInterface, RSAKey, DSSKey, \ SSHException, BadAuthenticationType, InteractiveQuery, ChannelException from paramiko import AUTH_FAILED, AUTH_PARTIALLY_SUCCESSFUL, AUTH_SUCCESSFUL from paramiko import OPEN_SUCCEEDED, OPEN_FAILED_ADMINISTRATIVELY_PROHIBITED +from paramiko.common import MSG_KEXINIT, MSG_CHANNEL_WINDOW_ADJUST +from paramiko.message import Message from loop import LoopSocket @@ -564,3 +567,160 @@ schan.close() chan.close() self.assertEquals(chan.send_ready(), True) + + def test_I_rekey_deadlock(self): + """ + Regression test for deadlock when in-transit messages are received after MSG_KEXINIT is sent + + Note: When this test fails, it may leak threads. + """ + + # Test for an obscure deadlocking bug that can occur if we receive + # certain messages while initiating a key exchange. + # + # The deadlock occurs as follows: + # + # In the main thread: + # 1. The user's program calls Channel.send(), which sends + # MSG_CHANNEL_DATA to the remote host. + # 2. Packetizer discovers that REKEY_BYTES has been exceeded, and + # sets the __need_rekey flag. + # + # In the Transport thread: + # 3. Packetizer notices that the __need_rekey flag is set, and raises + # NeedRekeyException. + # 4. In response to NeedRekeyException, the transport thread sends + # MSG_KEXINIT to the remote host. + # + # On the remote host (using any SSH implementation): + # 5. The MSG_CHANNEL_DATA is received, and MSG_CHANNEL_WINDOW_ADJUST is sent. + # 6. The MSG_KEXINIT is received, and a corresponding MSG_KEXINIT is sent. + # + # In the main thread: + # 7. The user's program calls Channel.send(). + # 8. Channel.send acquires Channel.lock, then calls Transport._send_user_message(). + # 9. Transport._send_user_message waits for Transport.clear_to_send + # to be set (i.e., it waits for re-keying to complete). + # Channel.lock is still held. + # + # In the Transport thread: + # 10. MSG_CHANNEL_WINDOW_ADJUST is received; Channel._window_adjust + # is called to handle it. + # 11. Channel._window_adjust tries to acquire Channel.lock, but it + # blocks because the lock is already held by the main thread. + # + # The result is that the Transport thread never processes the remote + # host's MSG_KEXINIT packet, because it becomes deadlocked while + # handling the preceding MSG_CHANNEL_WINDOW_ADJUST message. + + # We set up two separate threads for sending and receiving packets, + # while the main thread acts as a watchdog timer. If the timer + # expires, a deadlock is assumed. + + class SendThread(threading.Thread): + def __init__(self, chan, iterations, done_event): + threading.Thread.__init__(self, None, None, self.__class__.__name__) + self.setDaemon(True) + self.chan = chan + self.iterations = iterations + self.done_event = done_event + self.watchdog_event = threading.Event() + self.last = None + + def run(self): + try: + for i in xrange(1, 1+self.iterations): + if self.done_event.isSet(): + break + self.watchdog_event.set() + #print i, "SEND" + self.chan.send("x" * 2048) + finally: + self.done_event.set() + self.watchdog_event.set() + + class ReceiveThread(threading.Thread): + def __init__(self, chan, done_event): + threading.Thread.__init__(self, None, None, self.__class__.__name__) + self.setDaemon(True) + self.chan = chan + self.done_event = done_event + self.watchdog_event = threading.Event() + + def run(self): + try: + while not self.done_event.isSet(): + if self.chan.recv_ready(): + chan.recv(65536) + self.watchdog_event.set() + else: + if random.randint(0, 1): + time.sleep(random.randint(0, 500) / 1000.0) + finally: + self.done_event.set() + self.watchdog_event.set() + + self.setup_test_server() + self.ts.packetizer.REKEY_BYTES = 2048 + + chan = self.tc.open_session() + chan.exec_command('yes') + schan = self.ts.accept(1.0) + + # Monkey patch the client's Transport._handler_table so that the client + # sends MSG_CHANNEL_WINDOW_ADJUST whenever it receives an initial + # MSG_KEXINIT. This is used to simulate the effect of network latency + # on a real MSG_CHANNEL_WINDOW_ADJUST message. + self.tc._handler_table = self.tc._handler_table.copy() # copy per-class dictionary + _negotiate_keys = self.tc._handler_table[MSG_KEXINIT] + def _negotiate_keys_wrapper(self, m): + if self.local_kex_init is None: # Remote side sent KEXINIT + # Simulate in-transit MSG_CHANNEL_WINDOW_ADJUST by sending it + # before responding to the incoming MSG_KEXINIT. + m2 = Message() + m2.add_byte(chr(MSG_CHANNEL_WINDOW_ADJUST)) + m2.add_int(chan.remote_chanid) + m2.add_int(1) # bytes to add + self._send_message(m2) + return _negotiate_keys(self, m) + self.tc._handler_table[MSG_KEXINIT] = _negotiate_keys_wrapper + + # Parameters for the test + iterations = 500 # The deadlock does not happen every time, but it + # should after many iterations. + timeout = 5 + + # This event is set when the test is completed + done_event = threading.Event() + + # Start the sending thread + st = SendThread(schan, iterations, done_event) + st.start() + + # Start the receiving thread + rt = ReceiveThread(chan, done_event) + rt.start() + + # Act as a watchdog timer, checking + deadlocked = False + while not deadlocked and not done_event.isSet(): + for event in (st.watchdog_event, rt.watchdog_event): + event.wait(timeout) + if done_event.isSet(): + break + if not event.isSet(): + deadlocked = True + break + event.clear() + + # Tell the threads to stop (if they haven't already stopped). Note + # that if one or more threads are deadlocked, they might hang around + # forever (until the process exits). + done_event.set() + + # Assertion: We must not have detected a timeout. + self.assertFalse(deadlocked) + + # Close the channels + schan.close() + chan.close() # Begin bundle IyBCYXphYXIgcmV2aXNpb24gYnVuZGxlIHY0CiMKQlpoOTFBWSZTWZELBd4ACWR/gFxURERZ//// f//e6r////BgEo7X3x30HVX19ej09AAAD4UFW1axvl2M0rWqtDV21TlQ7sq723Z3boCCSSZEaamm Mieqe0akb00U2UANANDamj1GgAABqekxCZAiE0yGQBmo0AAAAAAA0DVMymkam0mRvUEbU9TIaGNR gTAmAmEGEYhoEhTRKn+lKeo2iNNNk09SemhqeoDAPVGQGgGQNqBgiUITRMTTQJtTE9RT9MpqeU/I 1NTYTU8pvUhoZMam0agEiQTQTE00KelNk1MTU9qNT2pMk0ekeoHqNGCNpNPSZqXgSS4cSK6TLUPz kH6U/4u3MRJvnAOg0lhebTj+0pwc17G9yMbRzL9TBRQ222ZXXD+Z0jp3OApmCDYxqg4bJvTzZMga W9117jbFliNDUMSCpS8JoG6CCM82f6tSmkXOZ6dxxaGgtWiw2M3s3sqeeFB3JNBsmn3y9J6bfTcs LIW7+Rrq0iAtvEPGaxndDl2/6w378dB6MDOKic+3jqKgO/v6rwIoCRSllOAOUMA507A71+15uT5c PDlvu5tAQCRfzDeCMkiSBIX/oBfZxdJnPTYpzYbJDZb1ennyGAadVEzu7jzuoHWN9ORdfKhjNNwh FSxsQq0mq+/Pm7TZMJdWCDPMggTDws9KlJQDXCMgGlALSfFNntm0HmTZlGiVTUlQJWaAqDypydb7 amZoCYIoUBTCCqZPdCR4fwJjQ8chfiUZKjJASMY5HCYJYzCwLJCSpEjUMXaG/NXwHAL0FwbEUCkh oWm+q53EUGGeFqMCS2N4vAfNRJ5NUZiOCuAoWJIikFlz4PDJZDa0rFhxLpEWYVT0Xs2trjmKxJmc YSyB8WUAmuqS0hFM99HHODl1MIkUqfAkSCVsjSHdO4kVmtA4bTcaXrSYsF1pO9sk0iwF4cLYX1uU UGUoSGBlNYAKbgXsbB6sYnVkzUOIdOGdP/cts5tXQQSiTcm6RZMI1wAC5UQU6ONAVolkdkFkFNmU 3aQXCL35ltyvHUYx6q9c8uUrjiKMyW0Nxz6Uy1/LF0wiuBvmB8d9xHCaGPDvm3Nwga9eh1uTZatS eGUGDXFxtca7a8l89KzpWn0S1PqPFCK3UyXcqLigYkfawLIEW8MDvsJJZi2s29dbALr0gcNjjOHd 2FLsO7JSUpNHpgKDkiTUP+lEVKzoYBzCEe6VN7jgDjalBswQcBrSIT4QkMJDV9JEiVLaM4D8UFDC AHYHQSL/eZqVma4+SOUE8zVqhJVZjshOXn8Azm87HAuyWJt0pU6a2bPrguKFirdxS18i6qXyCF7F 6EBf8V6FZHmtslwXvXvQV02fdrOUcWWcExxFCu89Hmttu2xdo38dE97ezWsqxSMaiZJF1xrDEgbI xG4O3pMOQUkHpOeCnJCTCZ0O28xd85dgqigrldmkGWOl1X4mKk2SSvWLCBoGxjD1AU9tCIiIdzJK YqwmTqBldKkmYqYRigA9MNxFTghHVXWo8FW6ZkhI7ytkijXgFx+BqT1MRpURcQCWBqTP0DRjmOwd Rl9EATsiXssi4uuKkNoqXmJqSIKEzxkd6pbPklfWANMd5DsRdKC70EG+uxdakr8JbKZWtG63rlPY /2SxPmSwWUlmjEuWIhTOHM6o+VdoXoGdWYpEZpYnY0DmZ6rqzpHjaqiBdkirrNUtwBfcgC46q45l MQqoOlBcUlgTKrJdiQVmDzSWnXI0IuVTsYGqZeGqRgYnM0MeGhuYHMUEB708eBijjrATicD7ppGq jqWClubNyaXcUwRWDmkSIlmdr55IzIe3M6XuYSKmAzgjoZGJIGSGI2CkLLMwTJh1MEriV4hZcuQ9 HRBNB1aD1ipqSkFtXea3i12WBwuOJcapcyaCCp/RIg0Ohjkzd6ZZTcbCy2QXTZy7GFTDaIUzIrhW xUx5GhqgpzXKxIsbFGSWvA6GwqrY5FjczKEy93c5rFooVJxeQpiFUvKnXfoGJ34dTpsa1QZX6hAX AWWZuamxQg689Tc1WkFXraeZU6k51HQLuVQseFMDSNoNS+FkIlB1OpQgXIySMqpoKb5cZPnxxqW0 xLri9KoxCtGl9sFMXUsTt0HoM4LEob4ZVIqSNIM+GI1spwdOlTU0NixM5Hz/1XtNrjZyXB8ngcdU LmXki83I4GiCMTI5nqFYOpM4FjIVCxmTPr8vfZQ2LoP5hi/IDCTflfCyMuQcYN0zU1IJrnFRrcHc oAoI7CnclZIrr5CRn/jDHQxQ97B2hsFLO70tGkwGj1NWky75GQkKyrANr7143katzQcGNHELNyhV F8xnQ+tT1GnVNRhAiyMbz7opY+yJ8WfnY96FENJV0uP+y5T7N0/JXzussO5m1G42AfvU+SH4IWSF SwuaBwC3QoDdgf2NEMP/ikDHT4oZFIjwqWwiHwwDKhCrvjAoDro3cxSwOY49BYh8lTXX9kIYGx5k q1TVeQkIxjHUfM/Qal4PPpk1BUDQZT9UIh80LJvI+4hiaw4IE6QMgHlOx2nnSp2PoKFDz3no9pDr KnucDMSEJuB0obD9lPmfB/B3rA9v8LUOIh5gv7wUE6Ntu9BYLj3G5+g09Z6mMYz/M9ttzDh1Vsn1 kJCRIQhimpDQ2kd68Mp3WVwDMJsuCofHRZ65Kx79v+P1cEXmWF8bNjFmibjEUhKRXAJ0JXhLOHmO Y844sLCQgRnERmgiP9MmU0aj0EdLyC5y80lQtg0A5CAu6XHpPtOAuLnSK0I4BBSkMufEbgfYr4dV mnZhVkxyEhVGAYvMJeXkopZquWhVYwkBgta1keGH2Pu7mxWTBDwDGC8bzysNcUu1YzuSYt82Ilxp 1DSZ6rmMUxwADt4zrOQ2nKdZDsNRZRQbxcNxYY0G2lakkrTYq0fjkX5PhJKK1cbpkgrRewmwcajI YCg6RUUjFIaEJQKOifCIwKQ4CoaCqfhYFO4ou2SDS1JzzaGA7eXlg5onNmhBpjNRcmEOuPBGzFCY ggXGFwQlwPh+UyMzEiDqK/arq7Tedw8unkH7NdLDKNQdHDFZMdpyt2lonVlYLBNHBovIzqm+dT8h UFxm8ZA6BxmgiS8S4mXBGSAZQ4JwMUG2RBXZr3Gh7TCpZeHiaHH0UNkdP6l0Px0XfQN9Otaa0uWF qFFiJPjEWUOsawUIyyLhs9rBtX6HYQzkGQHBkT0W3bxdo7O7y93TEpdDRisdwgoZmAzhc50VTiPp hmxnJLjRHgfV7V85uYs7aFqKYawfeBk5QuxmT4FWVLIuR1w77oDyKfTHsPzG8/60rMqfOeJ0JH1n YmcVtyUKF+kOKWQpISrZFwx5HE5mQtgAWCgZFOAQ4oulEgl0gZT2PbsLj9o0FpVwmPP6iCI+vHlI 786kuMczcholf5nken2e3/k7F25x0XJNYnifkqH2pF4dsAV5A9gmg7EjiVHut5T8tmrvGRM0ymzk pI567XHQP9iI3ztwWkIaBkKBQwHeHfJBABCwuK7LGnrVsXk4jmieEYhJe3vTCSwLnoiXL1kjpq/G K+bbp7AoYs4Y9ikcY1NTzvryxde6+Qmq/5XjaAiVrL5GlzG1nYBF0JPFVShuBwcUxLwukyYXB2Lz DF97IaCKUJwgX42kvNmaRIOg+yQMYKCZ3leB4o0SM7qO6qPUew5TrMx+86joOAbyxzQTPM3mUGlg NmgZpOyR94faFg7DMmj1euFAyBAPY9WdTE3XnIp2O0cTcBtA+mOwZSIGhZl4bGlEguUXAtTBsG1Q 0BvMbw17VLgwJ/1TkekcwsRNf7khR/FJGUDoWG1qJ1FgIwAkWG/W4810fXKBBvKWDLfVLDIRX6I8 Yt5666+FoSJ3oeSvRyN01oGjeG8yDt7SZ/5/SeKu7M6+Xgi5dXhCBAI+VpLnZP47SKDGDU6kfFI7 icZGO5jLCn0y/N0LqVtIxeJNwL6lTxA6/I6HB3EzsZFCAdJ9U19z6DQNnkjhudNkCochrJ+DhjpE gfheQogeeKlblrBbi1IvBQt7u5kGImXTQZ2HMAOGA8uozmqPWllbjpXraGLntMBsixdIlPWfikFE uvgZuxh8WjiyG2DGFLihll6rIZ4QuVHtcDrJMhhibubJR6I6GGlwcJSBCA6PkGORlYxhZSJLH6Ui ikzhQ4EGhAQfCTUg553ll4ZiIZrsthxmrSmSE971NG5y4Ua1WuLLQKYl0W5y+dcMCPjcDSQqTAyQ KkDRhaNiEcoGTw0yM80LodLcHgHScSa2IGBSGJXuc8NUmVS0V5HiKDTbLJDQU2VBqVa4MQiLAC8f AJvKGN84RyCYtCGticQZgi6UAglgRTEwYAMHNRCkAIhmbHP4R8s1yk8EaJ4Gm+oe0HR341KIGARS nPaFQgFT7gc1akNeEAw0uyEIL7SI5z+V0T3OIBfet+XTx0BpmM4GaBVSBuTei3ZAC5Dxoup6w2Dj qiRnJ5AtC/lUgTTkt2qPvqZOL7mfiJ63HtTEjBarVaIilS+U6mbyB0kC86rsvBQVcJEU9asW/Bhw XATWaw1BO5DODxHR8HBb2SQ3KUJJnhQI0nfgPjYbRitopLlNPgKgeZ0ljycXffbIkJMxkxA+bIlo yFgYM0Ql4nq0U+5iNSYoSi8EYnisb09efY+psHfYhV96GsX0s0cJwGrNcMWv2ge0PuZiFxZniYQC 3wwxH9kgmMGNKNKCJMXArESvSjWo1yFupyrt2sVzb/bJWpWMM14K4sEDCiGLiUpK8qBBCJhIuWiQ JRWIuoHqVQVminrooE1ei4lYhCPJcfY9UJXevhpuykZwTqNUV+iGUDO9qyeWEPsJ/rsmXgNjbG4U X+vf6cI0WgOVDn1ljTSlzesh8ZtOAci3re44uIxI3VA6iMLmD9CokbqGDQh/shWJYS6y3kiZOgyf SgsBrBZpGZJ8/e3SmeNYcQPK0+Eo45cQeIbkcCxfKBcjVETYuyca4KFpSM5wiINVlKILZvaSEGga 4ndmcEVxppOU5TwhtibScoiPoSMUid4rCriXXhUKBL4AO70IsVe4hhwJRvU0jJDw5auVlgqTch0u xyg6Frf0Fp3+akBsmkg/SMA9J6SA6LjkMGPoLPev4+GEg4sW53F/SSVFRfKwN8ULJB1N1TsVgpyM djEbuKC4MRNTLnMWhNYpH2IOB5VX0Hl+o9x6L1YtY8UUyz9VwtixKDqUDmK78/B6YsZbSAjbD2KA Nwk0H3pgjogfJjC0VTQLspHo4oYH7FuhKQLv+EczEzXQ7CmY5ns0YH5wj3LZRyGjg0jot0HTW75q hJPee0tk/X2q7pIlAWHVvECjqU6qp3IZEMoAZXIXBQrgFmBZ1If/F3JFOFCQkQsF3g==