librelist archives

« back to archive

Paramiko Hangs during SSH authentication.

Paramiko Hangs during SSH authentication.

From:
Deepak Rokade
Date:
2014-12-19 @ 10:55
Hi,
I am using paramiko SSH client in my application which fetches files from
remote host continuously batch wise in a loop. If the connection fails , I
re open the connection.

Everything works just fine , however sometimes ( very rarely) my paramiko
API's hang while establishing the connection and when I used the debug logs
I found  it hangs during authentication.

Below is the sample code I have written in my application ( sequence of
APIs)

    host_keys =
paramiko.util.load_host_keys(os.path.expanduser('~/.ssh/known_hosts'))
    t = paramiko.Transport((hostname, port))
    t.connect(username=username, password=password, hostkey=hostkey)
    sftp = paramiko.SFTPClient.from_transport(t)
    sftp.sock.setblocking(0)
    sftp.sock.settimeout(set_timeout)
    t.sock.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF,(256*1024))



*Test Result :*
Bellow are the debug level logs of paramiko while I conducted the test.
# I have designed the test so that my remote host keeps on rebooting every
after 10 mins.
# Application continued to run fine for 2 days.
...
...
DEB [20141219-11:10:38.800] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:10:39.824] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:10:40.848] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:10:42.104] thr=8   paramiko.transport: starting thread
(client mode): 0xddc3710L
INF [20141219-11:10:42.105] thr=8   paramiko.transport: Connected (version
2.0, client OpenSSH_3.9p1)
DEB [20141219-11:10:42.106] thr=8   paramiko.transport: kex
algos:['diffie-hellman-group-exchange-sha1', 'diffie-hellman-group14-sha1',
'diffie-hellman-group1-sha1'] server key:['ssh-dss'] client
encrypt:['aes128-cbc', '3des-cbc', 'blowfish-cbc', 'cast128-cbc',
'arcfour', 'aes192-cbc', 'aes256-cbc', 'rijndael-cbc@lysator.liu.se',
'aes128-ctr', 'aes192-ctr', 'aes256-ctr'] server encrypt:['aes128-cbc',
'3des-cbc', 'blowfish-cbc', 'cast128-cbc', 'arcfour', 'aes192-cbc',
'aes256-cbc', 'rijndael-cbc@lysator.liu.se', 'aes128-ctr', 'aes192-ctr',
'aes256-ctr'] client mac:['hmac-md5', 'hmac-sha1', 'hmac-ripemd160', '
hmac-ripemd160@openssh.com', 'hmac-sha1-96', 'hmac-md5-96'] server
mac:['hmac-md5', 'hmac-sha1', 'hmac-ripemd160', 'hmac-ripemd160@openssh.com',
'hmac-sha1-96', 'hmac-md5-96'] client compress:['none', 'zlib'] server
compress:['none', 'zlib'] client lang:[''] server lang:[''] kex
follows?False
DEB [20141219-11:10:42.106] thr=8   paramiko.transport: Ciphers agreed:
local=aes128-cbc, remote=aes128-cbc
DEB [20141219-11:10:42.106] thr=8   paramiko.transport: using kex
diffie-hellman-group1-sha1; server key type ssh-dss; cipher: local
aes128-cbc, remote aes128-cbc; mac: local hmac-sha1, remote hmac-sha1;
compression: local none, remote none
DEB [20141219-11:10:42.159] thr=8   paramiko.transport: Switch to new keys
...
DEB [20141219-11:10:42.173] thr=2   paramiko.transport: Attempting password
auth...
DEB [20141219-11:10:42.173] thr=2   paramiko.transport: password is starent
DEB [20141219-11:10:42.173] thr=2   paramiko.transport: my event is
<threading._Event object at 0xe0c9310>
DEB [20141219-11:10:42.173] thr=2   paramiko.transport: Calling AuthHnadler
DEB [20141219-11:10:42.174] thr=2   paramiko.transport: Calling auth
password after auth handler
DEB [20141219-11:10:42.174] thr=2   paramiko.transport: called auth password
DEB [20141219-11:10:42.174] thr=2   paramiko.transport: calling wait for
response
DEB [20141219-11:10:42.174] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.199] thr=8   paramiko.transport: userauth is OK
DEB [20141219-11:10:42.274] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.274] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.375] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.375] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.476] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.476] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.577] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.577] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.678] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.678] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:10:42.779] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.779] thr=2   paramiko.transport: calling wait on
event
INF [20141219-11:10:42.825] thr=8   paramiko.transport: Authentication
(password) successful!
DEB [20141219-11:10:42.843] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:10:42.844] thr=2   paramiko.transport: [chan 1] Max packet
in: 34816 bytes
DEB [20141219-11:10:42.844] thr=8   paramiko.transport: [chan 1] Max packet
out: 32768 bytes
INF [20141219-11:10:42.844] thr=8   paramiko.transport: Secsh channel 1
opened.
DEB [20141219-11:10:42.846] thr=8   paramiko.transport: [chan 1] Sesch
channel 1 request ok
INF [20141219-11:10:42.850] thr=2   paramiko.transport.sftp: [chan 1]
Opened sftp connection (server version 3)
DEB [20141219-11:10:42.851] thr=2   paramiko.transport.sftp: [chan 1]
normalize('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:10:42.854] thr=2   paramiko.transport.sftp: [chan 1]
open('/hd-raid/records/cdr/LESS_EPC1/CDR_12_19_2014_11_12_14_1020_file1.u',
'rb')
DEB [20141219-11:10:42.855] thr=2   paramiko.transport.sftp: [chan 1]
open('/hd-raid/records/cdr/LESS_EPC1/CDR_12_19_2014_11_12_14_1020_file1.u',
'rb') -> 00000000
DEB [20141219-11:10:42.858] thr=2   paramiko.transport.sftp: [chan 1]
stat('/hd-raid/records/cdr/LESS_EPC1/CDR_12_19_2014_11_12_14_1020_file1.u')
DEB [20141219-11:10:43.001] thr=2   paramiko.transport.sftp: [chan 1]
close(00000000)
...
...
# Everything is still fine.
...
...
DEB [20141219-11:11:36.179] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:11:37.200] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:11:38.221] thr=2   paramiko.transport.sftp: [chan 1]
listdir('/hd-raid/records/cdr/LESS_EPC1')
DEB [20141219-11:11:38.322] thr=17  paramiko.transport: EOF in transport
thread
INF [20141219-11:11:38.322] thr=2   paramiko.transport.sftp: [chan 1] sftp
session closed.
DEB [20141219-11:11:39.364] thr=21  paramiko.transport: starting thread
(client mode): 0xc0003590L
INF [20141219-11:11:39.365] thr=21  paramiko.transport: Connected (version
2.0, client OpenSSH_3.9p1)
DEB [20141219-11:11:39.365] thr=21  paramiko.transport: kex
algos:['diffie-hellman-group-exchange-sha1', 'diffie-hellman-group14-sha1',
'diffie-hellman-group1-sha1'] server key:['ssh-dss'] client
encrypt:['aes128-cbc', '3des-cbc', 'blowfish-cbc', 'cast128-cbc',
'arcfour', 'aes192-cbc', 'aes256-cbc', 'rijndael-cbc@lysator.liu.se',
'aes128-ctr', 'aes192-ctr', 'aes256-ctr'] server encrypt:['aes128-cbc',
'3des-cbc', 'blowfish-cbc', 'cast128-cbc', 'arcfour', 'aes192-cbc',
'aes256-cbc', 'rijndael-cbc@lysator.liu.se', 'aes128-ctr', 'aes192-ctr',
'aes256-ctr'] client mac:['hmac-md5', 'hmac-sha1', 'hmac-ripemd160', '
hmac-ripemd160@openssh.com', 'hmac-sha1-96', 'hmac-md5-96'] server
mac:['hmac-md5', 'hmac-sha1', 'hmac-ripemd160', 'hmac-ripemd160@openssh.com',
'hmac-sha1-96', 'hmac-md5-96'] client compress:['none', 'zlib'] server
compress:['none', 'zlib'] client lang:[''] server lang:[''] kex
follows?False
DEB [20141219-11:11:39.366] thr=21  paramiko.transport: Ciphers agreed:
local=aes128-cbc, remote=aes128-cbc
DEB [20141219-11:11:39.366] thr=21  paramiko.transport: using kex
diffie-hellman-group1-sha1; server key type ssh-dss; cipher: local
aes128-cbc, remote aes128-cbc; mac: local hmac-sha1, remote hmac-sha1;
compression: local none, remote none
DEB [20141219-11:11:39.419] thr=21  paramiko.transport: Switch to new keys
...
DEB [20141219-11:11:39.433] thr=2   paramiko.transport: Attempting password
auth...
DEB [20141219-11:11:39.433] thr=2   paramiko.transport: password is starent
DEB [20141219-11:11:39.433] thr=2   paramiko.transport: my event is
<threading._Event object at 0x2b4bc0021f10>
DEB [20141219-11:11:39.433] thr=2   paramiko.transport: Calling AuthHnadler
DEB [20141219-11:11:39.433] thr=2   paramiko.transport: Calling auth
password after auth handler
DEB [20141219-11:11:39.434] thr=2   paramiko.transport: called auth password
DEB [20141219-11:11:39.434] thr=2   paramiko.transport: calling wait for
response
DEB [20141219-11:11:39.434] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:39.458] thr=21  paramiko.transport: userauth is OK
DEB [20141219-11:11:39.534] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:39.534] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:39.635] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:39.635] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:39.736] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:39.736] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:39.837] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:39.837] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:39.938] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:39.938] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:40.039] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:40.039] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:40.140] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:40.140] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:40.241] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:40.241] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:40.342] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:40.342] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-11:11:40.415] thr=8   paramiko.transport: EOF in transport
thread
DEB [20141219-11:11:40.443] thr=2   paramiko.transport: called wait on event
DEB [20141219-11:11:40.443] thr=2   paramiko.transport: calling wait on
event
...
...
# Here onwards paraiko never responded and it continued to be in this state
all over.
...
DEB [20141219-16:09:29.323] thr=2   paramiko.transport: calling wait on
event
DEB [20141219-16:09:29.424] thr=2   paramiko.transport: called wait on event
DEB [20141219-16:09:29.424] thr=2   paramiko.transport: calling wait on
event

May I know, why paramiko might hang during the test.


-- Deepak Rokade