offlineimap 6.3.4-rc3 crash

Tue Jul 26 01:10:17 BST 2011

On Mon, Jul 25, 2011 at 02:46:59PM -0700, Marc MERLIN wrote:
> In case this helps.
> 
> This happened during a long running sync with IDLE turned on.
> 
> Said sync seems to otherwise work.

Actually, scratch that: the problem I had with old hacked up code is back.
I get occasional hangs:
 Next refresh in 50 seconds
 Next refresh in 40 seconds
 Next refresh in 30 seconds
 Next refresh in 20 seconds
 Next refresh in 10 seconds
 ***** Finished processing account google.com
 Copying folder structure from IMAP to Maildir

(nothing, I just need to kill offlineimap there and restart)

This is most likely linked to the IDLE code, but I kind of have to use it
since I would exceed my imap BW quota if I did full syncs of my folders all
the time.

I re-ran with -d imap, and this is what I get:
'handler terminating: "socket error: <type 'exceptions.IOError'> - Too many read 0"'

Is there a way for offlineimap to self recover from that condition instead of hanging?

More details:
 DEBUG[imap]:   06:18.79 imap.gmail.com reader poll => [(6, 1)]
 DEBUG[imap]:   06:18.79 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:18.86 imap.gmail.com reader poll => [(4, 1)]
 DEBUG[imap]:   06:18.86 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:18.89 imap.gmail.com reader poll => [(6, 1)]
 DEBUG[imap]:   06:18.89 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:18.96 imap.gmail.com reader poll => [(4, 1)]
 DEBUG[imap]:   06:18.96 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:18.99 imap.gmail.com reader poll => [(6, 1)]
 DEBUG[imap]:   06:18.99 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:19.06 imap.gmail.com reader poll => [(4, 1)]
 DEBUG[imap]:   06:19.06 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:19.06 imap.gmail.com reader last 20 log messages:
 DEBUG[imap]:   32:02.44 Copy message 60880 from [Gmail]/Sent Mail [sync] EXAMINE ('[Gmail]/Sent Mail',)
 DEBUG[imap]:   32:03.70 Copy message 60880 from [Gmail]/Sent Mail state => SELECTED
 DEBUG[imap]:   32:03.70 Copy message 60880 from [Gmail]/Sent Mail [async] UID ('FETCH', '60880', '(BODY.PEEK[])')
 DEBUG[imap]:   32:03.98 Copy message 60881 from [Gmail]/Sent Mail [async] UID ('FETCH', '60881', '(BODY.PEEK[])')
 DEBUG[imap]:   32:04.44 Copy message 60882 from [Gmail]/Sent Mail [async] UID ('FETCH', '60882', '(BODY.PEEK[])')
 DEBUG[imap]:   32:19.67 Copy message 23059 from lists [sync] EXAMINE ('lists',)
 DEBUG[imap]:   32:20.02 Copy message 23059 from lists state => SELECTED
 DEBUG[imap]:   32:20.02 Copy message 23059 from lists [async] UID ('FETCH', '23059', '(BODY.PEEK[])')
 DEBUG[imap]:   32:20.16 Copy message 23060 from lists [async] UID ('FETCH', '23060', '(BODY.PEEK[])')
 DEBUG[imap]:   32:20.31 Copy message 23061 from lists [async] UID ('FETCH', '23061', '(BODY.PEEK[])')
 DEBUG[imap]:   33:18.30 Thread-100 [sync] SELECT ('INBOX',)
 DEBUG[imap]:   33:19.18 Thread-100 state => SELECTED
 DEBUG[imap]:   33:19.18 Thread-100 [sync] IDLE ()
 DEBUG[imap]:   34:18.30 Thread-100 [async] NOOP ()
 DEBUG[imap]:   34:18.39 Thread-105 [async] NOOP ()
 DEBUG[imap]:   35:18.52 Thread-106 [sync] SELECT ('INBOX',)
 DEBUG[imap]:   35:19.06 Thread-106 state => SELECTED
 DEBUG[imap]:   35:19.06 Thread-106 [sync] IDLE ()
 DEBUG[imap]:   36:18.52 Thread-106 [async] NOOP ()
 DEBUG[imap]:   36:18.61 Thread-111 [async] NOOP ()
 DEBUG[imap]:   06:19.07 imap.gmail.com reader socket error: <type 'exceptions.IOError'> - Too many read 0
 DEBUG[imap]:   06:19.07 imap.gmail.com reader finished
imap.gmail.com handler:
 DEBUG[imap]:   06:19.07 imap.gmail.com handler terminating: "socket error: <type 'exceptions.IOError'> - Too many read 0"
 DEBUG[imap]:   06:19.07 imap.gmail.com handler state_change_free.set
 DEBUG[imap]:   06:19.07 imap.gmail.com handler finished
imap.gmail.com writer:
 DEBUG[imap]:   06:19.07 imap.gmail.com writer finished
imap.gmail.com reader:
 DEBUG[imap]:   06:19.09 imap.gmail.com reader poll => [(6, 1)]
 DEBUG[imap]:   06:19.09 imap.gmail.com reader rcvd 0
 DEBUG[imap]:   06:19.09 imap.gmail.com reader last 20 log messages:
 DEBUG[imap]:   31:34.12 Account sync google.com state => NONAUTH
 DEBUG[imap]:   31:34.12 Account sync google.com [async] CAPABILITY ()
 DEBUG[imap]:   31:34.16 Account sync google.com CAPABILITY: ('IMAP4REV1', 'UNSELECT', 'IDLE', 'NAMESPACE', 'QUOTA', 'ID', 'XLIST', 'CHILDREN', 'X-GM-EXT-1', 'XYZZY', 'SASL-IR', 'AUTH=XOAUTH')
 DEBUG[imap]:   31:34.16 Account sync google.com [sync] LOGIN ('merlin at google.com', '"d3pbclbsvbnonacx"')
 DEBUG[imap]:   31:35.27 Account sync google.com state => AUTH
 DEBUG[imap]:   31:35.27 Account sync google.com [async] LIST ('""', '*')
 DEBUG[imap]:   32:04.65 Copy message 60883 from [Gmail]/Sent Mail [sync] EXAMINE ('[Gmail]/Sent Mail',)
 DEBUG[imap]:   32:05.92 Copy message 60883 from [Gmail]/Sent Mail state => SELECTED
 DEBUG[imap]:   32:05.92 Copy message 60883 from [Gmail]/Sent Mail [async] UID ('FETCH', '60883', '(BODY.PEEK[])')
 DEBUG[imap]:   32:18.37 Copy message 23054 from lists [sync] EXAMINE ('lists',)
 DEBUG[imap]:   32:18.86 Copy message 23054 from lists state => SELECTED
 DEBUG[imap]:   32:18.86 Copy message 23054 from lists [async] UID ('FETCH', '23054', '(BODY.PEEK[])')
 DEBUG[imap]:   32:19.07 Copy message 23055 from lists [async] UID ('FETCH', '23055', '(BODY.PEEK[])')
 DEBUG[imap]:   32:19.27 Copy message 23056 from lists [async] UID ('FETCH', '23056', '(BODY.PEEK[])')
 DEBUG[imap]:   32:19.41 Copy message 23057 from lists [async] UID ('FETCH', '23057', '(BODY.PEEK[])')
 DEBUG[imap]:   32:19.54 Copy message 23058 from lists [async] UID ('FETCH', '23058', '(BODY.PEEK[])')
 DEBUG[imap]:   33:18.30 Thread-101 [async] NOOP ()
 DEBUG[imap]:   34:18.39 Thread-104 [async] NOOP ()
 DEBUG[imap]:   35:18.52 Thread-107 [async] NOOP ()
 DEBUG[imap]:   36:18.61 Thread-110 [async] NOOP ()
 DEBUG[imap]:   06:19.09 imap.gmail.com reader socket error: <type 'exceptions.IOError'> - Too many read 0
 DEBUG[imap]:   06:19.09 imap.gmail.com reader finished
imap.gmail.com handler:
 DEBUG[imap]:   06:19.09 imap.gmail.com handler terminating: "socket error: <type 'exceptions.IOError'> - Too many read 0"
 DEBUG[imap]:   06:19.09 imap.gmail.com handler state_change_free.set
 DEBUG[imap]:   06:19.09 imap.gmail.com handler finished
imap.gmail.com writer:
 DEBUG[imap]:   06:19.09 imap.gmail.com writer finished
imap.gmail.com reader:
 DEBUG[imap]:   06:20.48 imap.gmail.com reader poll => []
 DEBUG[imap]:   06:50.51 imap.gmail.com reader poll => []
 DEBUG[imap]:   07:20.53 imap.gmail.com reader poll => []
 DEBUG[imap]:   07:50.55 imap.gmail.com reader poll => []
 DEBUG[imap]:   08:20.57 imap.gmail.com reader poll => []

Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  