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: OfflineIMAP-project@alioth-lists.debian.net
https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/offlineimap-project
OfflineIMAP homepages:
- https://github.com/OfflineIMAP
- http://offlineimap.org
