Offlineimap sync stalls at particular message

Josiah Schwab <[email protected]>
Newsgroups gmane.mail.imap.offlineimap.general
Message-ID <[email protected]> 
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

_______________________________________________
OfflineIMAP-project mailing list: [email protected]
https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/offlineimap-project

OfflineIMAP homepages:
- https://github.com/OfflineIMAP
- http://offlineimap.org
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.