OfflineIMAP

Please:

• Try with the latest version of OfflineIMAP available from this site.

• Send the output of -d imap -1 (the last few pages, taking care to strip it of any private data or passwords)

I do not have the time to track down bugs in software that old, and any fix would be committed against a current version anyway.

I also encountered this bug with offlineimap git version (6fd4962b4ccf7ab75c312743607b77d5d24e6ed2). Unfortunately I didn't have the debugging turned on. I still haven't figured out how to reproduce the bug at will.

Attaching the last few pages of the debug log of a crash.

Unfortunately, there are a couple of problems here that make this not useful:

1) OfflineIMAP wasn't run with -1.

2) There is actually only one (very long) line of matching log messages included, and that line doesn't correspond with the thread that had the problem.

Can you please make sure to run OfflineIMAP with -1 and include a bit more of the log?

Thanks,

-- John

Here's the full command line I used:

cd ~/src/offlineimap/ && PYTHONPATH=. bin/offlineimap -a Home -d imap -1

I don't know why the -1 does not do what you think it should do. The manual page does say it disables "most" multithreading operations, implying it doesn't disable them all.

I have a longer excerpt of that log saved to a text file (everything that fit in my terminal's scrollback buffer). Is there any way for me to determine what bits you might be interested in, or should I just gzip and attach the whole 300K? I don't think there's any private data in there, except for maybe several mailing list passwords (it's the Mailman day today).

I don't know if it's relevant, but I guess it wouldn't hurt to mention that I connect to the imap server via SSH:

preauthtunnel = ssh -q musmire /usr/lib/dovecot/imap

I'm having this issue too. It happens with two different Exchange servers and I'm not accessing either IMAP connection with any other client than offlineimap.

Last couple pages of a debug log are attached.

I noticed that the problem kept happening in the "keepalive" thread, so I tried turning it off. No effect - still crashes in the
same way.

Let me know if there is anything I can try.

This is yesterday's version of 5.99.9

Marius,

You could be right; I may have jumped to a conclusion there because there was only one line of debugging info there. I still can't tell what is going on with your situation without more info.

P Holcomb,

I have examined your file. The root error is happening when trying to download mail. The second exception is just because the process of crashing caused something else to generate an exception, and can be safely ignored.

Your debug log is really weird. Look at this:

Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 > OHGH190 UID FETCH 17099 (BODY.PEEK[])
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 < * 6856 EXISTS
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12     matched r'\* (?P<data>\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?' => ('6856', 'EXISTS', None, None)
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 untagged_responses[EXISTS] 1 += ["6856"]
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 < * 1 RECENT
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12     matched r'\* (?P<data>\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?' => ('1', 'RECENT', None, None)
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 untagged_responses[RECENT] 1 += ["1"]
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12 < OHGH190 OK FETCH completed.
Copy message 17099 from .INBOX: DEBUG[imap]:   35:32.12     matched r'(?P<tag>OHGH\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('OHGH190', 'OK', 'FETCH completed.')
Copy message 17099 from .INBOX: DEBUG[imap]: Returned object from fetching 17099: ('OK', [None])

So OfflineIMAP sent out the request UID FETCH 17099 (BODY.PEEK[]). In response, the IMAP server sent back what looks like the results of a SELECT command instead. imaplib.py did not detect this problem, but passed back an object that did not contain a message. OfflineIMAP, obviously, expected to receive a message.

This seems to be a synchronization problem. It is most likely a bug with your server software. It could also be a bug in Python's imaplib.py. There is also a chance that it's a bug in OfflineIMAP, but it seems vanishingly small to me.

Here's all the log that I have (the start is missing), with message bodies removed. The last part is interesting. H ere's a message that was fetched successfully:

DEBUG[imap]:   19:33.07 > KMJM36 UID FETCH 75515 (BODY.PEEK[])

DEBUG[imap]:   19:33.18 < * 5 FETCH (UID 75515 BODY[] {10586}

DEBUG[imap]:   19:33.18      matched r'\* (?P<data>\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?' => ('5', 'FETCH', ' (UID 75515 BODY[] {10586}', '(UID 75515 BO

DEBUG[imap]:   19:33.18      matched r'.*{(?P<size>\d+)}$' => ('10586',)

DEBUG[imap]:   19:33.18 read literal size 10586

DEBUG[imap]:   19:33.30 untagged_responses[FETCH] 0 += ["('5 (UID 75515 BODY[] {10586}', '***removed***')"]

DEBUG[imap]:   19:33.30 < )

DEBUG[imap]:   19:33.30 untagged_responses[FETCH] 1 += [")"]

DEBUG[imap]:   19:33.30 < KMJM36 OK Fetch completed.

DEBUG[imap]:   19:33.30      matched r'(?P<tag>KMJM\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('KMJM36', 'OK', 'Fetch completed.')

DEBUG[imap]:   19:33.30 untagged_responses[FETCH] => [('5 (UID 75515 BODY[] {10586}', '***removed***'), ')']

DEBUG[imap]: Returned object from fetching 75515: ('OK', [('5 (UID 75515 BODY[] {10586}', '***removed***'), ')'])

And here's the one that causes offlineimap to abort with the traceback

DEBUG[imap]:   19:33.31 > KMJM37 UID FETCH 75516 (BODY.PEEK[])

DEBUG[imap]:   19:33.36 < KMJM37 OK Fetch completed.

DEBUG[imap]:   19:33.36      matched r'(?P<tag>KMJM\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('KMJM37', 'OK', 'Fetch completed.')

DEBUG[imap]: Returned object from fetching 75516: ('OK', [None])

For some reason the server doesn't return any data before reporting successful completion?

I would not be at all surprised if MS Exchange's IMAP implementation was causing this problem. I don't have any access to either server directly, but I am going to generate a log from the other session that gets the same error and see if its the same. The sessions are as follows: Remote: host "AT" MS Exchange (details unknown)
Local: host "ub" offlineimap 5.9.9, Ubuntu Hardy 8.04 amd64 Python: 2.5.2 (r252:60911, Mar 12 2008, 13:39:09) Remote: host "MF" MS Exchange (details unknown)
Local: host "le" offlineimap 5.9.9, Ubuntu Gutsy 7.10 amd64 (using same deb) Python 2.5.1 (r251:54863, Oct 5 2007, 13:50:07)

/>

I was also going to start synching with a remote dovecot session, but in this session for the log I posted, I'm occasionally getting empty mail messages and I'm slightly worried about data loss. So far, the good message has stayed on the remote server even while blank on the local machine.

One final note, I don't think I was seeing this behavoir with offlineimap 4.0.16. I switched to 5.9.8 because it handled my lamda function for folderfilter correctly, and 4.0.16 did not. I upgraded to 5.9.9 to make sure my issue wasn't solved in dev.

It would be very interesting to know your Exchange version. You should be able to find that out by using telnet to connect to the imap server, or by looking at the very top of the OfflineIMAP -d imap output.

Several people have reported older versions of Exchange have such a poor IMAP implementation that they are effectively unusable with multiple modern IMAP programs, including OfflineIMAP. AFAIK, newer Exchange versions work OK with OfflineIMAP however.

Looks like version 6.5.7226.0 for account "AT" and version 6.5.7651.51 for account "MF"

I got pretty much the same error when trying to sync with my GMail account:

Thread 'Copy message 258 from INBOX' terminated with exception:
Traceback (most recent call last):
  File "/Library/Python/2.5/site-packages/offlineimap/threadutil.py", line 153, in run
    Thread.run(self)
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/threading.py", line 440, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/Library/Python/2.5/site-packages/offlineimap/folder/Base.py", line 277, in copymessageto
    message = self.getmessage(uid)
  File "/Library/Python/2.5/site-packages/offlineimap/folder/IMAP.py", line 164, in getmessage
    initialresult = imapobj.uid('fetch', '%d' % uid, '(BODY.PEEK[])')
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 752, in uid
    typ, dat = self._simple_command(name, command, *args)
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 1055, in _simple_command
    return self._command_complete(name, self._command(name, *args))
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 885, in _command_complete
    typ, data = self._get_tagged_response(tag)
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 986, in _get_tagged_response
    self._get_response()
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 948, in _get_response
    data = self.read(size)
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/imaplib.py", line 1150, in read
    data = self.sslobj.read(size-read)
  File "/Library/Python/2.5/site-packages/offlineimap/imaplibutil.py", line 82, in read
    retval = self._read(n)
  File "/Library/Python/2.5/site-packages/offlineimap/imaplibutil.py", line 70, in _read
    return self.sslsock.read(n)
MemoryError

No debug messages were logged for Copy message 258 from INBOX.
Exception in thread Copy message 259 from INBOX (most likely raised during interpreter shutdown):
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/threading.py", line 460, in __bootstrap
  File "/Library/Python/2.5/site-packages/offlineimap/threadutil.py", line 239, in run
<type 'exceptions.TypeError'>: 'NoneType' object is unsubscriptable

My configuration is quite normal, just copy the minimal conf example then changed my username and password.

In the above error, you had a MemoryError. This looks like an OS issue, different from anything else here.

Hi,
I'm having exactly the same problem as the original poster. I am syncing Microsoft Exchange 2007 IMAP Server (using SSL) with Maildirs, and get the same error on the same email consistently.

Strange thing is when I view the folder in Outlook the mail on which offlineimap is failing is at the top of the list even though it is sorted by Date with "Newest on top". The headers look bizarre - almost like the mail was modified by offlineimap:

Received: from (10.1.2.10) by file-01.thismonkey.com (10.1.1.20) with IMAP;
Tue, 6 May 2008 13:36:30 +1000
Received: from mailin3.email.bigpond.com ([192.168.115.34]) by
X-OfflineIMAP-x682425568-52656d6f7465-494e424f582f667269656e6473: 1210045142-0114090035045-v4.0.11
mailms4a.email.bigpond.com (Netscape Messaging Server 4.15) with
ESMTP id GDWATD02.TQJ for
<saitken1#bigpond.net.au@domain10.bigpond.com>; Sat, 26 May 2001
00:27:13 +1000
Received: from nmcst152.netaddress.usa.net ([144.135.24.69]) by
mailin3.email.bigpond.com (Netscape Messaging Server 4.15) with
SMTP id GDWATC00.A0Q for
<saitken1#bigpond.net.au@domain10.bigpond.com>; Sat, 26 May 2001
00:27:12 +1000

The following command:
$ PYTHONPATH=. bin/offlineimap -d imap -1

when runnning version 5.99.12
gives the following output:

DEBUG[imap]: imapsplit() called with input: FLAGS (\Seen) UID 268 INTERNALDATE "06-May-2008 12:29:59 +1000"
DEBUG[imap]: imapsplit() returning: ['FLAGS', '(\\Seen)', 'UID', '268', 'INTERNALDATE', '"06-May-2008 12:29:59 +1000"']
DEBUG[imap]: options2hash called with input: ['FLAGS', '(\\Seen)', 'UID', '268', 'INTERNALDATE', '"06-May-2008 12:29:59 +1000"']
DEBUG[imap]: options2hash returning: {'INTERNALDATE': '"06-May-2008 12:29:59 +1000"', 'FLAGS': '(\\Seen)', 'UID': '268'}
DEBUG[imap]: imapsplit() called with input: FLAGS (\Seen) UID 269 INTERNALDATE "24-May-2001 16:35:30 +1000"
DEBUG[imap]: imapsplit() returning: ['FLAGS', '(\\Seen)', 'UID', '269', 'INTERNALDATE', '"24-May-2001 16:35:30 +1000"']
DEBUG[imap]: options2hash called with input: ['FLAGS', '(\\Seen)', 'UID', '269', 'INTERNALDATE', '"24-May-2001 16:35:30 +1000"']
DEBUG[imap]: options2hash returning: {'INTERNALDATE': '"24-May-2001 16:35:30 +1000"', 'FLAGS': '(\\Seen)', 'UID': '269'}
Copy message 177 IMAP[INBOX/friends] -> Maildir[INBOX.friends], LocalStatus[INBOX.friends]
DEBUG[imap]: 47:35.17 > FEOC58 UID FETCH 177 (BODY.PEEK[])
DEBUG[imap]: 47:35.18 < FEOC58 OK FETCH completed.
DEBUG[imap]: 47:35.18 matched r'(?P<tag>FEOC\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('FEOC58', 'OK', 'FETCH completed.')
DEBUG[imap]: Returned object from fetching 177: ('OK', [None])
Copy message 178 IMAP[INBOX/friends] -> Maildir[INBOX.friends], LocalStatus[INBOX.friends]
DEBUG[imap]: 47:35.19 > FEOC59 UID FETCH 178 (BODY.PEEK[])
DEBUG[imap]: 47:35.20 < FEOC59 OK FETCH completed.
DEBUG[imap]: 47:35.20 matched r'(?P<tag>FEOC\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('FEOC59', 'OK', 'FETCH completed.')
DEBUG[imap]: Returned object from fetching 178: ('OK', [None])
Copy message 179 IMAP[INBOX/friends] -> Maildir[INBOX.friends], LocalStatus[INBOX.friends]
DEBUG[imap]: 47:35.21 > FEOC60 UID FETCH 179 (BODY.PEEK[])

Thread 'Copy message 177 from INBOX/friends' terminated with exception:
Traceback (most recent call last):
File "/tmp/offlineimap/offlineimap/threadutil.py", line 153, in run
Thread.run(self)
File "/usr/local/lib/python2.5/threading.py", line 446, in run
self.__target(*self.__args, **self.__kwargs)
File "/tmp/offlineimap/offlineimap/folder/Base.py", line 277, in copymessageto
message = self.getmessage(uid)
File "/tmp/offlineimap/offlineimap/folder/IMAP.py", line 167, in getmessage
return initialresult[1][0][1].replace("\r\n", "\n")
TypeError: 'NoneType' object is unsubscriptable

Last 4 debug messages logged for Copy message 177 from INBOX/friends prior to exception:
imap: 47:35.17 > FEOC58 UID FETCH 177 (BODY.PEEK[])
imap: 47:35.18 < FEOC58 OK FETCH completed.
imap: 47:35.18 matched r'(?P<tag>FEOC\d+) (?P<type>[A-Z]+) (?P<data>.*)' => ('FEOC58', 'OK', 'FETCH completed.')
imap: Returned object from fetching 177: ('OK', [None])
Exception in thread Copy message 179 from INBOX/friends (most likely raised during interpreter shutdown):
Traceback (most recent call last):
File "/usr/local/lib/python2.5/threading.py", line 486, in __bootstrap_inner
File "/tmp/offlineimap/offlineimap/threadutil.py", line 239, in run
<type 'exceptions.TypeError'>: 'NoneType' object is unsubscriptable

This was a bug in 5.99.12 that is fixed in 5.99.13.

Please, if you are seeing a NoneType error, do not append here unless you are sure this is the same problem. We are seeing a lot of people adding comments to this bug that are not related to the original problem, which makes tracking quite difficult.

-- John

At this point, it looks like the IMAP server is to blame. will close shortly unless other info appears.

Sorry about that. I guess I couldn't work out where to create a new issue so I appended here.

When you mentioned that the bug was fixed in 5.99.13 - were you referring to the issue I posted 05/06/2008 12:56 AM?

If so, the error is still there in 5.99.13. Mind you, it wouldn't surprise me if the bug was with the Microsoft IMAP implementation.

Thanks for your help
Scott

I'm getting almost the same error (message changed slightly, but same stacktrace) with OfflineIMAP 6.0.0 and Exchange 2007. A debug log is attached in case it helps.

// Claus

This still happens with offlineimap 6.03 with Gmail and dovecot, while downloading mail. Re-running the program overcomes the problem.
It the malfunction is on the server's side, offlineimap could detect this behaviour and inform of it instead of crashing.

It is quite unclear from this ticket what, if any, problem remains, but it looks like what remains is a duplicate of #26.