[offlineimap] Hangs when certain remotepasseval commands fail. (#159)

[Edd Barrett]

Hi,

This was discussed on the mailing list(http://article.gmane.org/gmane.mail.imap.offlineimap.general/6647). I will duplicate the main info below.

I am running OpenBSD-current/amd64.

```
I am having problems with offlineimap occasionally hanging.

The problem manifests similarly as described in this post:
http://comments.gmane.org/gmane.mail.imap.offlineimap.general/5457

So it hangs, then I see the "Terminating NOW (this may take a few
seconds)..." message.

Note that, unlike in the above linked post,  I am not using an SSH tunnel,
just a TLS encrypted IMAP connection to a number of mail servers.

Sometimes the dreaded "Terminating NOW" message *does* clear.  On other
occasions it hangs forever.  Pressing CTRL+C again prints the message again
before hanging more.

Once at this state, you must kill -9 offlineimap, which is bad because
it leaves a lock file behind.

Annoyingly I don't know what causes this to happen. At first I though it
was when the network connection went down, but I have since convinced
myself otherwise.

I'm finding this frustrating, as it interrupts my work flow to kill the
process and clear the lock.
```

Then later:

```
> Can you, please, kill offlineimap with SIGQUIT: it will print the full
> backtrace of all threads to the stderr.  It will be interesting to see
> the output.

I (accidentally) found one scenario where the hang occurs. I apply the
SIGQUIT approach below.

First background. I have a script which runs offlineimap and mu (the
mail indexer) in a loop with a 180 second sleep in each iteration.

Last night I suspended my laptop, and when it woke this morning, offlineimap
was hanging:

---8<---
OfflineIMAP 6.5.6
  Licensed under the GNU GPL v2+ (v2 or any later version)
Account sync XXXXX:
 *** Processing account XXXXX
 Establishing connection to XXXXX:993
Traceback (most recent call last):
  File "/home/edd/source/passout/passout.py", line 111, in <module>
    entrypoint()
  File "/home/edd/source/passout/passout.py", line 108, in entrypoint
    args.func(args, expand=True)
  File "/home/edd/.local/lib/python2.7/site-packages/argspander/__init__.py", line 74, in _inner
    return func(*func_args)
  File "/home/edd/source/passout/passout.py", line 41, in cmd_stdout
    print(passout.get_password(cfg, pass_name))
  File "/home/edd/source/passout/passout/__init__.py", line 100, in get_password
    (out, err))
passout.PassOutError: gpg returned non-zero
STDOUT: 
STDERR: gpg: cancelled by user
gpg: encrypted with 2048-bit RSA key, ID XXXXXXXX, created XXXX-XX-XX
      "Edd Barrett <XXXXXXXXXXXXXXXX>"
gpg: public key decryption failed: Operation cancelled
gpg: decryption failed: No secret key

Enter password for account 'XXXXX': 
^CTerminating NOW (this may take a few seconds)...
^CTerminating NOW (this may take a few seconds)...
--->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.

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()
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/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 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/syncmaster.py", line 37, in syncitall
syncaccount(threads, config, accountname)
File: "/usr/local/lib/python2.7/site-packages/offlineimap/syncmaster.py", line 29, in
syncaccount thread.start()
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/bin/offlineimap", line 23, in <module> oi.run()
File: "/usr/local/lib/python2.7/site-packages/offlineimap/init.py", line 50, in run self.__sync(options)
File: "/usr/local/lib/python2.7/site-packages/offlineimap/init.py", line 382, in __sync threadutil.exitnotifymonitorloop(threadutil.threadexited)
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---
```

---
Reply to this email directly or view it on GitHub:
https://github.com/OfflineIMAP/offlineimap/issues/159
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/offlineimap-project/attachments/20150119/cdd88576/attachment-0002.html>