Offlineimap sync stalls at particular message

Josiah Schwab jschwab at gmail.com
Mon Apr 23 20:21:32 BST 2018 

Hello,

I recently started having a problem where the offlineimap sync for one
of my GMail accounts does not complete.

The sync appears to consistently stall when it reaches a particular
message.  There is no network traffic during the stall, so it does not
seem due to something such as the transfer of a large file.

Eventually, I kill it with repeated Ctrl-C.

In order to understand what is happening, it would be useful to see the
details of the message where it stops.  I tried running offlineimap with
-d ALL, but this did not provide sufficient identifying information
(e.g. subject).

An example log is below.  Some debugging information (XOAUTH, folder
list) was removed for privacy.  (I killed this after only a minute or
so, but waited ~1 hr with no apparent progress in a previous test.)

Does anyone have any suggestions of what I should do in order to better
understand what is happening?

Thanks,
Josiah


2018-04-23 15:02:32 INFO: OfflineImap 7.2.0 starting...
  Python: 2.7.14 Platform: linux2
  Args: /usr/bin/offlineimap -a santacruz -f MESA -d ALL -1 -l /tmp/mesa.log
2018-04-23 15:02:32 INFO: imaplib2 v2.57 (bundled), Python v2.7.14, OpenSSL 1.1.0h  27 Mar 2018
2018-04-23 15:02:32 INFO: Debug mode: Forcing to singlethreaded.
2018-04-23 15:02:32 DEBUG: Now debugging for imap: IMAP protocol debugging
2018-04-23 15:02:32 DEBUG: Now debugging for maildir: Maildir repository debugging
2018-04-23 15:02:32 DEBUG: Now debugging for thread: Threading debugging
2018-04-23 15:02:32 DEBUG: Now debugging for : Other offlineimap related sync messages
2018-04-23 15:02:32 DEBUG: [thread]: Register new thread 'Account sync santacruz' (account 'santacruz')
2018-04-23 15:02:32 DEBUG: [imap]: Using authentication mechanisms ['XOAUTH2']
2018-04-23 15:02:32 DEBUG: [maildir]: MaildirRepository initialized, sep is '.'
2018-04-23 15:02:32 INFO: *** Processing account santacruz
2018-04-23 15:02:32 INFO: Establishing connection to imap.gmail.com:993 (santacruz-remote)
2018-04-23 15:02:32 DEBUG: [imap]: santacruz-remote: level 'tls_compat', version 'None'
2018-04-23 15:02:33 DEBUG: [imap]: Attempting XOAUTH2 authentication
2018-04-23 15:02:33 DEBUG: [maildir]: _GETFOLDERS_SCANDIR STARTING. root = /home/jschwab/Mail/santacruz, extension = None
2018-04-23 15:02:33 DEBUG: [maildir]:   toppath = /home/jschwab/Mail/santacruz
2018-04-23 15:02:33 DEBUG: [maildir]:   dirname = MESA
2018-04-23 15:02:33 DEBUG: [maildir]:   This is maildir folder 'MESA'.
2018-04-23 15:02:33 DEBUG: []: Copying folder structure from santacruz-remote to santacruz-local
2018-04-23 15:02:33 DEBUG: [thread]: Register thread 'Account sync santacruz' (previously 'santacruz', now 'santacruz')
2018-04-23 15:02:33 INFO: Syncing MESA: Gmail -> Maildir
2018-04-23 15:02:33 DEBUG: Loading message list for Maildir[MESA]
2018-04-23 15:02:34 DEBUG: Message list for Maildir[MESA] loaded: 6205 messages
2018-04-23 15:02:34 DEBUG: Loading message list for Gmail[MESA]
2018-04-23 15:02:34 DEBUG: [imap]: calling imaplib2 fetch command: '1:*' (FLAGS UID INTERNALDATE)
2018-04-23 15:02:52 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"10-Oct-2016 19:44:47 +0000"', 'FLAGS': '(\\Seen)', 'UID': '1'}
[...snip...]
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 05:43:05 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6200'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 08:23:48 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6201'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 10:45:20 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6202'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 14:01:24 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6203'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 16:45:13 +0000"', 'FLAGS': '()', 'UID': '6204'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 17:09:55 +0000"', 'FLAGS': '()', 'UID': '6205'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 20:05:17 +0000"', 'FLAGS': '()', 'UID': '6206'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 20:06:46 +0000"', 'FLAGS': '()', 'UID': '6207'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 20:10:57 +0000"', 'FLAGS': '()', 'UID': '6208'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 20:44:21 +0000"', 'FLAGS': '()', 'UID': '6209'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 21:10:00 +0000"', 'FLAGS': '()', 'UID': '6210'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 21:20:57 +0000"', 'FLAGS': '()', 'UID': '6211'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 21:25:57 +0000"', 'FLAGS': '()', 'UID': '6212'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 21:26:51 +0000"', 'FLAGS': '()', 'UID': '6213'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 21:29:09 +0000"', 'FLAGS': '()', 'UID': '6214'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 22:38:52 +0000"', 'FLAGS': '()', 'UID': '6215'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"22-Apr-2018 23:16:51 +0000"', 'FLAGS': '()', 'UID': '6216'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 09:38:27 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6217'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 13:35:13 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6218'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 13:51:44 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6219'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 14:02:35 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6220'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 14:15:14 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6221'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 14:43:41 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6222'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 15:05:37 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6223'}
2018-04-23 15:02:58 DEBUG: [imap]: __options2hash returning: {'INTERNALDATE': '"23-Apr-2018 16:05:19 +0000"', 'FLAGS': '(\\Seen)', 'UID': '6224'}
2018-04-23 15:02:58 DEBUG: Message list for Gmail[MESA] loaded: 6218 messages
2018-04-23 15:02:58 DEBUG: Syncing messages Gmail[MESA] -> Maildir[MESA]
2018-04-23 15:02:58 INFO: Copy message UID 6210 (1/13) santacruz-remote:MESA -> santacruz-local:MESA
2018-04-23 15:04:33 WARNING: Terminating NOW (this may take a few seconds)...
2018-04-23 15:04:33 DEBUG: [thread]: ** Thread List:

2018-04-23 15:04:33 DEBUG: [thread]: 1 Thread is at:
    return self._command_complete(self._command(name, *args), kw)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1490, in _command_complete
    typ, dat = rqb.get_response('command: %s => %%s' % rqb.name)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 195, in get_response
    self.ready.wait(threading.TIMEOUT_MAX)
  File: "/usr/lib/python2.7/threading.py", line 614, in wait
    self.__cond.wait(timeout)
  File: "/usr/lib/python2.7/threading.py", line 359, in wait
    _sleep(delay)
  => Stopped to handle current signal.

2018-04-23 15:04:33 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 2033, in _writer
    rqb = self.ouq.get()
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:04:33 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1891, in _reader
    r = poll.poll(timeout)

2018-04-23 15:04:33 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1805, in _handler
    line = self.inq.get(True, timeout)
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:04:33 DEBUG: [thread]: Dumped a total of 4 Threads.
2018-04-23 15:05:12 WARNING: Terminating NOW (this may take a few seconds)...
2018-04-23 15:05:12 DEBUG: [thread]: ** Thread List:

2018-04-23 15:05:12 DEBUG: [thread]: 1 Thread is at:
    return self._command_complete(self._command(name, *args), kw)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1490, in _command_complete
    typ, dat = rqb.get_response('command: %s => %%s' % rqb.name)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 195, in get_response
    self.ready.wait(threading.TIMEOUT_MAX)
  File: "/usr/lib/python2.7/threading.py", line 614, in wait
    self.__cond.wait(timeout)
  File: "/usr/lib/python2.7/threading.py", line 359, in wait
    _sleep(delay)
  => Stopped to handle current signal.

2018-04-23 15:05:12 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 2033, in _writer
    rqb = self.ouq.get()
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:12 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1891, in _reader
    r = poll.poll(timeout)

2018-04-23 15:05:12 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1805, in _handler
    line = self.inq.get(True, timeout)
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:12 DEBUG: [thread]: Dumped a total of 4 Threads.
2018-04-23 15:05:13 WARNING: Terminating NOW (this may take a few seconds)...
2018-04-23 15:05:13 DEBUG: [thread]: ** Thread List:

2018-04-23 15:05:13 DEBUG: [thread]: 1 Thread is at:
    return self._command_complete(self._command(name, *args), kw)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1490, in _command_complete
    typ, dat = rqb.get_response('command: %s => %%s' % rqb.name)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 195, in get_response
    self.ready.wait(threading.TIMEOUT_MAX)
  File: "/usr/lib/python2.7/threading.py", line 614, in wait
    self.__cond.wait(timeout)
  File: "/usr/lib/python2.7/threading.py", line 359, in wait
    _sleep(delay)
  => Stopped to handle current signal.

2018-04-23 15:05:13 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 2033, in _writer
    rqb = self.ouq.get()
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:13 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1891, in _reader
    r = poll.poll(timeout)

2018-04-23 15:05:13 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1805, in _handler
    line = self.inq.get(True, timeout)
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:13 DEBUG: [thread]: Dumped a total of 4 Threads.
2018-04-23 15:05:13 WARNING: Signaled thrice. Aborting!
2018-04-23 15:05:15 WARNING: Terminating NOW (this may take a few seconds)...
2018-04-23 15:05:15 DEBUG: [thread]: ** Thread List:

2018-04-23 15:05:15 DEBUG: [thread]: 1 Thread is at:
    typ, dat = self._simple_command('LOGOUT')
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1740, in _simple_command
    return self._command_complete(self._command(name, *args), kw)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1394, in _command
    self.state_change_free.wait(threading.TIMEOUT_MAX)
  File: "/usr/lib/python2.7/threading.py", line 614, in wait
    self.__cond.wait(timeout)
  File: "/usr/lib/python2.7/threading.py", line 359, in wait
    _sleep(delay)
  => Stopped to handle current signal.

2018-04-23 15:05:15 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 2033, in _writer
    rqb = self.ouq.get()
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:15 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1891, in _reader
    r = poll.poll(timeout)

2018-04-23 15:05:15 DEBUG: [thread]: 1 Thread is at:
  File: "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File: "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File: "/usr/lib/python2.7/site-packages/offlineimap/bundled_imaplib2.py", line 1805, in _handler
    line = self.inq.get(True, timeout)
  File: "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File: "/usr/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()

2018-04-23 15:05:15 DEBUG: [thread]: Dumped a total of 4 Threads.
2018-04-23 15:05:15 WARNING: Signaled thrice. Aborting!
2018-04-23 15:05:15 INFO: *** Finished account 'santacruz' in 2:42

More information about the OfflineIMAP-project mailing list