offlineimap hangs

[Nicolas Sebrecht]

Thank you much for the tests you're doing, Edd. You are good at that
game, you know. ,-)

On Sun, Jan 11, 2015 at 02:36:55PM +0000, Edd Barrett wrote:

<...>

> --->8---
> 
> What is happening here is, offlineimap was either mid-sync or due to sync
> during suspend. The stack trace you see is my password manager attempting to
> decrypt a password from disk and send it back to offlineimap (via
> remotepasseval). The password manager is communicating with gpg-agent, which
> may need to prompt the user to unlock the GPG keychain (via pinentry-gtk2 in
> my case). I suppose this can time out, or perhaps it had probems connecting
> to the X server whilst X was resuming.

Looks like we are trapped by the flexibility OfflineIMAP offers to users
for this one. FMPOV it looks more the responsability of the code we
didn't write. The code retrieveing the password is not from us, is it?

> Anyway, after this, offlineimap is hung in the way I described in my first
> mail.
> 
> I sent it a SIGQUIT:
> 
> ---8<---
> # Thread #0 (id=9702286294272), Account sync XXXXX
> File: "/usr/local/lib/python2.7/threading.py", line 783, in __bootstrap self.__bootstrap_inner()
> File: "/usr/local/lib/python2.7/threading.py", line 810, in __bootstrap_inner self.run()
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/threadutil.py", line 229, in run ExitNotifyThread.run(self)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/threadutil.py", line 158, in run Thread.run(self)
> File: "/usr/local/lib/python2.7/threading.py", line 763, in run self.__target(*self.__args, **self.__kwargs)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/accounts.py", line 241, in syncrunner self.__sync()
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/accounts.py", line 303, in __sync remoterepos.getfolders()
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/repository/IMAP.py", line 322, in getfolders imapobj = self.imapserver.acquireconnection()
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imapserver.py", line 418, in acquireconnection self.__authn_helper(imapobj)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imapserver.py", line 327, in __authn_helper if func(imapobj):
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imapserver.py", line 253, in __authn_plain imapobj.authenticate('PLAIN', self.__plainhandler)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 648, in authenticate typ, dat = self._simple_command('AUTHENTICATE', mechanism.upper())
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 1615, in _simple_command return self._command_complete(self._command(name, *args), kw)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 1343, in _command ok, data = crqb.get_response('command: %s => %%s' % name)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 170, in get_response self.ready.wait()

Here.

> File: "/usr/local/lib/python2.7/threading.py", line 621, in wait self.__cond.wait(timeout)
> File: "/usr/local/lib/python2.7/threading.py", line 340, in wait waiter.acquire()
> 
> # Thread #1 (id=9700364648960), Sync Runner

<...>

> File: "/usr/local/lib/python2.7/site-packages/offlineimap/threadutil.py", line 224, in start instancelimitedsems[self.instancename].acquire()
> File: "/usr/local/lib/python2.7/threading.py", line 468, in acquire self.__cond.wait()
> File: "/usr/local/lib/python2.7/threading.py", line 340, in wait waiter.acquire()
> 
> # Thread #2 (id=9701371553504), MainThread

<...>

> File: "/usr/local/lib/python2.7/site-packages/offlineimap/threadutil.py", line 109, in exitnotifymonitorloop thrd = exitthreads.get(True, 60)
> File: "/usr/local/lib/python2.7/Queue.py", line 177, in get self.not_empty.wait(remaining)
> File: "/usr/local/lib/python2.7/threading.py", line 359, in wait _sleep(delay)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/init.py", line 359, in sig_handler stacktrace.dump (sys.stderr)
> File: "/usr/local/lib/python2.7/site-packages/offlineimap/utils/stacktrace.py", line 20, in dump for f, lno, name, line in traceback.extract_stack (stack):
> Abort trap (core dumped) 
> --->8---
> 
> Looks like some kind of deadlock between threads?

I would not say that. OfflineIMAP is waiting for a reply from the server
after it sent the authentication request (the "here" tag). Looks like it
missed the answer but is still waiting for it. What's a bit surprising
is that this is the library imalib2 we use which is locked, waiting for
a reply that will never come.

It's obvious why the Sync Runner thread is waiting.

I have no strong opinion about this one. What should we do? Hardcode a
timer to each call to our main library? Seriously? Does impalib2 provide
a timeout option we missed somewhere? Why imaplib2 does not fix a
timeout by itself?

There are ways of investigation to do before we could make a good
opinion, I guess...

Anyway, I'd like to ask you create an issue about the last trace. It's a
good one and I feel we won't come with the simple fix in the coming
days.

-- 
Nicolas Sebrecht