[paramiko] Threads getting stuck during SFTP using Paramiko.
Yateen Joshi
yateenjoshi at gmail.com
Thu May 31 03:36:56 PDT 2007
Though I removed call to prefetch, (to avoid the threads stuck issue), the
speed of fetching is reduced a lot. Looks like there is no alternative to
prefetch for getting (sftp) files at a good speed. However, if prefetch is
used, I am seeing below issue.
Does anyone have any idea as to why this problem is seen? (prefetch
initiates another thread that is probably getting locked with an existing
thread).
Any inputs?
Thanks and regards,
Yateen V. Joshi
Today's Topics:
>
> 1. Re: Threads getting stuck during SFTP using Paramiko.
> (Yateen Joshi)
>
>
> ----------------------------------------------------------------------
>
> Message: 1
> Date: Mon, 28 May 2007 20:52:28 +0530
> From: "Yateen Joshi" <yateenjoshi at gmail.com>
> Subject: Re: [paramiko] Threads getting stuck during SFTP using
> Paramiko.
> To: paramiko at lag.net
> Message-ID:
> <6b22365e0705280822o34869772r485a87f1c0a3eaf at mail.gmail.com>
> Content-Type: text/plain; charset="windows-1252"
>
> Additionally,
>
> If I disable prefetch, the problem is not seen.
>
> Yateen V. Joshi
>
>
> On 5/26/07, Yateen Joshi <yateenjoshi at gmail.com> wrote:
> >
> > Hi,
> >
> >
> >
> > The simple nature of the problem is as follows ?
> >
> >
> >
> > I am periodically getting files from a remote machine (which is having
> > openSSH) using Paramiko sftp client as a part of my python script.
> >
> > The files keep on generating at the remote server and my application
> > fetches it on a regular basis. It is observed that the application gets
> > stuck after some time and it no longer fetches any file.
> >
> >
> >
> > Here is the analysis ?
> >
> >
> >
> > I observed in the paramiko logs that it is stuck after a certain number
> of
> > rekeys. To easily reproduce the problem, I reduced the number of bytes
> and
> > packets after which the rekey happens. Default is 2 power 30, I made
> them 2
> > power 13 and the problem gets reproduced easily.
> >
> > Just to verify my logic, I disabled this rekeying mechanism (instead of
> > incrementing the bytes and packets in read_message, I kept them
> constant)
> > and found the problem was NOT reproduced.
> >
> >
> >
> > Since my application was running on a Solaris (9) machine, I took a
> gcore
> > of the same and found that one of the threads was stuck. I put more logs
> in
> > paramiko code, and found that it got stuck in channel::_feed() method
> while
> > trying to acquire lock.
> >
> >
> >
> > Here are the paramiko logs -
> >
> >
> >
> > DEB [20070526-19:21:47.001] thr=1 paramiko.transport.1 : releasing
> lock
> > - channel::_feed
> >
> > DEB [20070526-19:21:47.002] thr=1 paramiko.transport.1 : released lock
> -
> > channel::_feed
> >
> > DEB [20070526-19:21:47.002] thr=1 paramiko.transport : calling
> > send_kex_init in need key
> >
> > DEB [20070526-19:21:47.002] thr=1 paramiko.transport : acquiring clear
> > to send lock - _send_kex_init
> >
> > DEB [20070526-19:21:47.002] thr=1 paramiko.transport : acquired clear
> to
> > send lock - _send_kex_init
> >
> > DEB [20070526-19:21:47.003] thr=2 paramiko.transport.1.sftp :
> > stat('/records/edr/NC38_RB_05262007190750_000_000057032.gz')
> >
> > DEB [20070526-19:21:47.003] thr=1 paramiko.transport : releasing lock
> -
> > clear to send lock _send_kex_init
> >
> > DEB [20070526-19:21:47.004] thr=2 paramiko.transport.1 : acquiring
> lock
> > - channel::send
> >
> > DEB [20070526-19:21:47.004] thr=1 paramiko.transport : released lock -
> > clear to send lock _send_kex_init
> >
> > DEB [20070526-19:21:47.005] thr=2 paramiko.transport.1 : acquired lock
> -
> > channel::send
> >
> > DEB [20070526-19:21:47.007] thr=1 paramiko.transport : coming out of
> > _send_kex_init
> >
> > DEB [20070526-19:21:47.008] thr=1 paramiko.transport : called
> > send_kex_init in need key
> >
> > DEB [20070526-19:21:47.011] thr=1 paramiko.transport.1 : acquiring
> lock
> > - channel::_feed
> >
> >
> >
> >
> >
> > Here is the dbx output ?
> >
> >
> >
> > Reading parser.so
> >
> > t at 2 (l at 2) terminated by signal 0 (UNKNOWN SIGNAL)
> >
> > 0xfee354b0: __lwp_park+0x0010: ta 8
> >
> > Current function is PyThread_acquire_lock
> >
> > dbx.11: warning: can't find file "/sol10/SOURCES/S8/Python-2.4.2
> > /Python/thread_pthread.h"
> >
> > dbx.11: warning: see `help finding-files'
> >
> > (dbx.11)
> >
> > (dbx.11) where
> >
> > current thread: t at 2
> >
> > dbx.11: warning: invalid type for LCSYM/STSYM stab:
> >
> /export/home/edrserver/ess/3rdparty/python/solaris/bin/python2.4:Objects/classobject.c
> > stab #10921 docstr:V(49,10)
> >
> > [1] __lwp_park(0x0, 0x0, 0x0, 0x1, 0xfee48000, 0x206288), at
> 0xfee354b0
> >
> > [2] cond_wait_queue(0x2035c0, 0xfee48c08, 0x0, 0x0, 0xfed70200,
> > 0xfee48000), at 0xfee326b8
> >
> > [3] _cond_wait_cancel(0x2035c0, 0x2035d0, 0x7c, 0xfed29138, 0x140000,
> > 0x0), at 0xfee32e74
> >
> > [4] _pthread_cond_wait(0x2035c0, 0x2035d0, 0xfe8fb08c, 0x0, 0x1b,
> 0x1),
> > at 0xfee32eb0
> >
> > =>[5] PyThread_acquire_lock(lock = 0x2035b8, waitflag = 2110928), line
> 416
> > in "thread_pthread.h"
> >
> > [6] lock_PyThread_acquire_lock(self = 0x17d4c0, args = 0x141030), line
> > 63 in "threadmodule.c"
> >
> > [7] PyCFunction_Call(func = 0x334198, arg = 0x141030, kw = (nil)),
> line
> > 94 in "methodobject.c"
> >
> > [8] call_function(pp_stack = 0xfe8fb290, oparg = 0), line 3558 in "
> > ceval.c"
> >
> > [9] PyEval_EvalFrame(f = 0x59deb0), line 2163 in "ceval.c"
> >
> > [10] PyEval_EvalCodeEx(co = 0x278060, globals = (nil), locals =
> 0x81da0,
> > args = 0x327b54, argcount = 2, kws = (nil), kwcount = 0, defs = (nil),
> > defcount = 0, closure = (nil)), line 2736 in " ceval.c"
> >
> > [11] function_call(func = 0x27ea70, arg = 0x327b48, kw = (nil)), line
> > 548 in "funcobject.c"
> >
> > [12] PyObject_Call(func = 0x27ea70, arg = 0x327b48, kw = (nil)), line
> > 1756 in "abstract.c"
> >
> > [13] instancemethod_call(func = 0x27ea70, arg = 0x327b48, kw = (nil)),
> > line 2447 in "classobject.c "
> >
> > [14] PyObject_Call(func = 0x27ea70, arg = 0x327b48, kw = (nil)), line
> > 1756 in "abstract.c"
> >
> > [15] do_call(func = 0x1e5378, pp_stack = 0xfe8fb890, na = 2, nk =
> > 3308360), line 3766 in "ceval.c "
> >
> > [16] call_function(pp_stack = 0xfe8fb890, oparg = 2), line 3581 in "
> > ceval.c"
> >
> > [17] PyEval_EvalFrame(f = 0x5f0488), line 2163 in "ceval.c"
> >
> > [18] fast_function(func = 0x3320b0, pp_stack = 0x18d420, n = 1, na =
> > 6211252, nk = 6227080), line 3640 in " ceval.c"
> >
> > [19] call_function(pp_stack = 0xfe8fba38, oparg = 1), line 3579 in "
> > ceval.c"
> >
> > [20] PyEval_EvalFrame(f = 0x18d2c0), line 2163 in "ceval.c"
> >
> > [21] PyEval_EvalCodeEx(co = 0x2238a0, globals = (nil), locals =
> 0x81da0,
> > args = 0x1edd9c, argcount = 1, kws = (nil), kwcount = 0, defs = (nil),
> > defcount = 0, closure = (nil)), line 2736 in " ceval.c"
> >
> > [22] function_call(func = 0x244430, arg = 0x1edd90, kw = (nil)), line
> > 548 in "funcobject.c"
> >
> > [23] PyObject_Call(func = 0x244430, arg = 0x1edd90, kw = (nil)), line
> > 1756 in "abstract.c"
> >
> > [24] instancemethod_call(func = 0x244430, arg = 0x1edd90, kw = (nil)),
> > line 2447 in "classobject.c "
> >
> > [25] PyObject_Call(func = 0x244430, arg = 0x1edd90, kw = (nil)), line
> > 1756 in " abstract.c"
> >
> > [26] PyEval_CallObjectWithKeywords(func = 0x31d828, arg = 0x141030, kw
> =
> > (nil)), line 3425 in "ceval.c "
> >
> > [27] t_bootstrap(boot_raw = 0x6abfd8), line 434 in "threadmodule.c"
> >
> > (dbx.11) threads
> >
> > t at 1 a l at 1 ?() running in _poll()
> >
> > > t at 2 b l at 2 t_bootstrap() sleep on 0x2035c0 in __lwp_park()
> >
> > (dbx.11)
> >
> > (dbx.11)
> >
> > (dbx.11)
> >
> > (dbx.11)
> >
> > (dbx.11)
> >
> > (dbx.11)
> >
> > (dbx.11) thread -blockedby t at 1
> >
> > Thread t at 1 is not asleep
> >
> > (dbx.11) thread -blockedby t at 2
> >
> > Thread t at 2 is blocked by:
> >
> > 0x002035c0 (0x2035c0): thread condition variable
> >
> > (dbx.11) thread -blocks t at 1
> >
> > Locks held by t at 1:
> >
> > (dbx.11) thread -blocks t at 2
> >
> > Locks held by t at 2:
> >
> > (dbx.11) thread -info t at 1
> >
> > Thread t at 1 (0xfed70000) at priority 0
> >
> > state: active on l at 1
> >
> > base function: 0x0: 0x00000000() stack: 0xffc00000[8388608]
> >
> > flags: (none)
> >
> > masked signals: (none)
> >
> > Currently active in _poll
> >
> > (dbx.11) thread -info t at 2
> >
> > Thread t at 2 (0xfed70200) at priority 0
> >
> > state: asleep on 0x002035c0 (0x2035c0): thread condition
> variable
> >
> >
> > base function: 0xc54f8: t_bootstrap() stack: 0xfe8fc000[1032192]
> >
> > flags: BOUND|DETACHED|SUSPENDED
> >
> > masked signals: (none)
> >
> > Currently inactive in __lwp_park
> >
> > (dbx.11)
> >
> >
> >
> >
> >
> > As can be seen from the dbx and paramiko logs, thread is
> > channel::_feed() and thread2 is channel::send().
> >
> > The thread 2 (send) is waiting in an infinite while loop (please see
> code
> > below) to get a variable set (clear_to_send), however, that will be set
> > after some data is received. The other thread that might receive the
> data is
> > now stuck in channel::_feed().
> >
> > transport.py -
> > def _send_user_message(self, data):
> > """
> > send a message, but block if we're in key negotiation. this is
> > used
> > for user-initiated requests.
> > """
> > while True:
> > self.clear_to_send.wait(0.1)
> > if not self.active:
> > self._log(DEBUG, 'Dropping user packet because
> connection
> > is dea
> > d.')
> > return
> > self.clear_to_send_lock.acquire()
> > if self.clear_to_send.isSet():
> > break
> > self.clear_to_send_lock.release()
> > try:
> > self._send_message(data)
> > finally:
> > self.clear_to_send_lock.release()
> >
> >
> > I tried to use pdb (python debugger), however, did not have any luck.
> Can
> > you give any pointers as to why this is happening and reason for the
> thread
> > getting stuck? Also, any pointers why this is related to rekeying?
> >
> >
> >
> > Appreciating your response in advance,
> >
> >
> >
> > Best regards,
> >
> >
> >
> >
> >
> > Yateen Vishnu Joshi
> >
> >
> >
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL:
> http://mail.lag.net/pipermail/paramiko/attachments/20070528/49cf7d25/attachment.html
>
> ------------------------------
>
> _______________________________________________
> paramiko mailing list
> paramiko at lag.net
> http://mail.lag.net/mailman/listinfo/paramiko
>
> End of paramiko Digest, Vol 29, Issue 8
> ***************************************
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.lag.net/pipermail/paramiko/attachments/20070531/b0ce40fd/attachment.htm
More information about the paramiko
mailing list