{"action":"created","issue":{"url":"https://api.github.com/repos/paramiko/paramiko/issues/822","repository_url":"https://api.github.com/repos/paramiko/paramiko","labels_url":"https://api.github.com/repos/paramiko/paramiko/issues/822/labels{/name}","comments_url":"https://api.github.com/repos/paramiko/paramiko/issues/822/comments","events_url":"https://api.github.com/repos/paramiko/paramiko/issues/822/events","html_url":"https://github.com/paramiko/paramiko/issues/822","id":180420010,"number":822,"title":"Key-exchange timeout over session channels, but not sftp","user":{"login":"mathrick","id":179487,"avatar_url":"https://avatars.githubusercontent.com/u/179487?v=3","gravatar_id":"","url":"https://api.github.com/users/mathrick","html_url":"https://github.com/mathrick","followers_url":"https://api.github.com/users/mathrick/followers","following_url":"https://api.github.com/users/mathrick/following{/other_user}","gists_url":"https://api.github.com/users/mathrick/gists{/gist_id}","starred_url":"https://api.github.com/users/mathrick/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mathrick/subscriptions","organizations_url":"https://api.github.com/users/mathrick/orgs","repos_url":"https://api.github.com/users/mathrick/repos","events_url":"https://api.github.com/users/mathrick/events{/privacy}","received_events_url":"https://api.github.com/users/mathrick/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/paramiko/paramiko/labels/Bug","name":"Bug","color":"a04040"},{"url":"https://api.github.com/repos/paramiko/paramiko/labels/Needs%20investigation","name":"Needs investigation","color":"fad8c7"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-09-30T23:07:58Z","updated_at":"2016-10-24T16:52:53Z","closed_at":null,"body":"We're running into the key-exchange timeout exception when talking to OpenSSH, but it only happens when using a \"session\" channel. SFTP transfers proceed just fine, and we see successful key exchange in the logs.\r\n\r\n[This gist](https://gist.github.com/mathrick/1b2ead63553f2bfc8d3e129e1d4512e2) demonstrates the issue:\r\n```\r\n$ ssh quicksilver \"base64 /dev/urandom | head -c 200000 > /tmp/file.txt\"\r\n$ python test_paramiko.py quicksilver -u mkatafiasz /tmp/file.txt --sftp\r\nREKEY_BYTES: 102400\r\nREKEY_PACKETS: 536870912\r\nUsing SFTPClient, which should succeed in rekeying\r\nRead file 1 times\r\nRead file 2 times\r\nRead file 3 times\r\nRead file 4 times\r\nRead file 5 times\r\n^C\r\nKeyboardInterrupt\r\n\r\n$ python test_paramiko.py quicksilver -u mkatafiasz /tmp/file.txt\r\nREKEY_BYTES: 102400\r\nREKEY_PACKETS: 536870912\r\nUsing SSHClient, which should fail in rekeying\r\nNeed rekey\r\nRead file 1 times\r\nRead file 2 times\r\nTraceback (most recent call last):\r\nNo handlers could be found for logger \"paramiko.transport\"\r\n  File \"test_paramiko.py\", line 45, in <module>\r\n    for line in stdout:\r\n  File \"/usr/lib/python2.7/dist-packages/paramiko/file.py\", line 106, in next\r\n    line = self.readline()\r\n  File \"/usr/lib/python2.7/dist-packages/paramiko/file.py\", line 214, in readline\r\n    new_data = self._read(n)\r\n  File \"/usr/lib/python2.7/dist-packages/paramiko/channel.py\", line 1253, in _read\r\n    return self.channel.recv(size)\r\n  File \"/usr/lib/python2.7/dist-packages/paramiko/channel.py\", line 628, in recv\r\n    self.transport._send_user_message(m)\r\n  File \"/usr/lib/python2.7/dist-packages/paramiko/transport.py\", line 1442, in _send_user_message\r\n    raise SSHException('Key-exchange timed out waiting for key negotiation')\r\nparamiko.SSHException: Key-exchange timed out waiting for key negotiation\r\n```\r\n\r\nThe remote side is running OpenSSH (tried with 6.6 and 6.7), and setting `LogLevel DEBUG` yields the following output:\r\n\r\n* SFTP (successfully rekeys)\r\n```\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: SSH2_MSG_KEXINIT received\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: SSH2_MSG_KEXINIT sent\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: kex: client->server aes128-ctr hmac-sha2-256 none\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: kex: server->client aes128-ctr hmac-sha2-256 none\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: expecting SSH2_MSG_KEXDH_INIT\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: set_newkeys: rekeying\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: SSH2_MSG_NEWKEYS sent\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: expecting SSH2_MSG_NEWKEYS\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: set_newkeys: rekeying\r\nSep 27 17:48:42 myhost sshd[20158]: debug1: SSH2_MSG_NEWKEYS received\r\n```\r\n* SSH session (fails)\r\n```\r\nSep 27 17:44:14 myhost sshd[19591]: debug1: SSH2_MSG_KEXINIT received\r\nSep 27 17:44:14 myhost sshd[19591]: debug1: SSH2_MSG_KEXINIT sent\r\nSep 27 17:44:14 myhost sshd[19591]: debug1: kex: client->server aes128-ctr hmac-sha2-256 none\r\nSep 27 17:44:14 myhost sshd[19591]: debug1: kex: server->client aes128-ctr hmac-sha2-256 none\r\nSep 27 17:44:14 myhost sshd[19591]: debug1: expecting SSH2_MSG_KEXDH_INIT\r\nSep 27 17:44:44 myhost sshd[19591]: fatal: Read from socket failed: Connection reset by peer\r\n```\r\n\r\nGiven these logs, the issue makes me think of one I believe was fixed earlier, related to OpenSSH server not liking intervening traffic after a rekey request was sent, though I can't find the issue number right now."},"comment":{"url":"https://api.github.com/repos/paramiko/paramiko/issues/comments/255798129","html_url":"https://github.com/paramiko/paramiko/issues/822#issuecomment-255798129","issue_url":"https://api.github.com/repos/paramiko/paramiko/issues/822","id":255798129,"user":{"login":"tsellers-r7","id":20306699,"avatar_url":"https://avatars.githubusercontent.com/u/20306699?v=3","gravatar_id":"","url":"https://api.github.com/users/tsellers-r7","html_url":"https://github.com/tsellers-r7","followers_url":"https://api.github.com/users/tsellers-r7/followers","following_url":"https://api.github.com/users/tsellers-r7/following{/other_user}","gists_url":"https://api.github.com/users/tsellers-r7/gists{/gist_id}","starred_url":"https://api.github.com/users/tsellers-r7/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tsellers-r7/subscriptions","organizations_url":"https://api.github.com/users/tsellers-r7/orgs","repos_url":"https://api.github.com/users/tsellers-r7/repos","events_url":"https://api.github.com/users/tsellers-r7/events{/privacy}","received_events_url":"https://api.github.com/users/tsellers-r7/received_events","type":"User","site_admin":false},"created_at":"2016-10-24T16:52:53Z","updated_at":"2016-10-24T16:52:53Z","body":"I think that this is caused by a deadlock that occurs when a channel close for channel 0 is sent from the server after the key exchange process has started.\r\n\r\nSequence of events:\r\n\r\nThe key exchange process (`transport.._send_kex_init()`) is triggered due to `self.packetizer.need_rekey` being true.\r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1753\r\n\r\n`Transport._send_kex_init` clears the `clear_to_send` flag, preventing traffic\r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1920\r\n\r\nThe loop reads messages from the server\r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1756\r\n\r\nBefore the `MSG_KEXINIT` message is sent from the server, a `MSG_CHANNEL_CLOSE` (type 97 ) message is sent, which is handled by the `_channel_handler_table`\r\n- https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1779\r\n\r\nThe above calls Channel._handle_close\r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L2379\r\n\r\nChannel._handle_close generates an EOF message and attempts to send it to the server via `transport._send_user_message`\r\n - https://github.com/paramiko/paramiko/blob/master/paramiko/channel.py#L1071\r\n\r\n`Transport._send_user_message` loops while waiting on, among other things, the `clear_to_send` flag.  \r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1585\r\n\r\nSince the server has closed the channel, it will never finish the key exchange / negotiations and so the `transport.run` loop will continue until `_send_user_message` times out and returns `Key-exchange timed out waiting for key negotiation`\r\n - https://github.com/paramiko/paramiko/blob/833d9f76be9676419d5a0eb3bd9a66ce27b40214/paramiko/transport.py#L1600\r\n\r\n\r\n"}}
{"actor":{"display_login":"tsellers-r7"}}