IMAP protocol error with davmail

[John Hein]

Using latest version off the trunk (rev 1074), I get the following error when trying to get mail via imap served by davmail (an imap/pop/etc. proxy that speaks to an exchange server on one side):

IMAP protocol error: "expected (RFC822.SIZE number) in FETCH response"

This may be a problem with davmail's imap server implementation, but it seems to work fine with thunderbird and evolution.

back trace:

Debugger entered--Lisp error: (vm-imap-protocol-error "expected (RFC822.SIZE number) in FETCH response")
  signal(vm-imap-protocol-error ("expected (RFC822.SIZE number) in FETCH response"))
  vm-imap-protocol-error("expected (RFC822.SIZE number) in FETCH response")
  vm-imap-get-message-size(#<process IMAP> 1)
  byte-code("^H ^Z\211^[\306\nI\210*\307^\\310^M \211#\211^T@A^V^]^N^^^N^]\240\210^N^^A^N^_\240\210^N^^^N $
  byte-code("^H\203^M^@\306\307^H\310 \n#\"\210\311 ^K\312#\211^T\204^\^@\306\307\313\"\210\305\f!^U\212^$
  vm-imap-move-mail("imap:localhost:1143:inbox:login:jhein:*" "/h/jhein/mail/INBOX.CRASH")
  vm-get-spooled-mail-normal(t)
  vm-get-spooled-mail(t)
  vm-get-new-mail(nil)
  call-interactively(vm-get-new-mail nil nil)

[Uday Reddy (reddyuday)]

Hi John, this will be a difficult problem to track down. As far as I
can remember, this is using the original code from Kyle Jones. So, I
will need as much information as you can provide.

1. Is this the first time you are trying VM with this server, or has
it worked before?

2. Does the problem exist with the previous release VM 8.1.1 and the
alpha-testing release 8.1.93a?

3. If you look at the buffer list in Emacs, there should be a buffer
with a name like "trace of IMAP session to ...". Can you send me the
contents of this buffer after you receive the error? I will mark the
bug report as 'private' so that it is not visible on the web.

Cheers,
Uday

[John Hein (xpqheqdvq4)]

Uday Reddy wrote at 13:36 -0000 on Feb 20, 2011:
 > Hi John, this will be a difficult problem to track down. As far as I
 > can remember, this is using the original code from Kyle Jones. So, I
 > will need as much information as you can provide.

Understood. My first step was to report the bug hoping for an outside
shot that it might have been encountered. Next was to dig into the
imap RFC and use tcpdump to debug. I'm no imap protocol expert.

 > 1. Is this the first time you are trying VM with this server, or has
 > it worked before?

This is the first time, yes. It's really the first time I've used
davmail. Until now, I've talked to exchange servers that had imap
turned on. In this case, the exchange server admins have imap (and
pop) turned off, so I tried davmail (which will also convert the
exchange calendar protocol to a more standard one, so davmail is quite
worthwhile on a non-windows platform even if you don't need the
imap/pop proxy, but that's not relevant to this imap issue).

That said, I tried using vm to talk to davmail's pop proxy, and it
seems to work as expected. So I have a sort of a workaround, but
imap would be better.

 > 2. Does the problem exist with the previous release VM 8.1.1 and the
 > alpha-testing release 8.1.93a?

Tried on 8.1.1 and trunk - same problem on both. I did not try 8.1.93a.

 > 3. If you look at the buffer list in Emacs, there should be a buffer
 > with a name like "trace of IMAP session to ...". Can you send me the
 > contents of this buffer after you receive the error? I will mark the
 > bug report as 'private' so that it is not visible on the web.

Yes, there was on 8.1.1 - but for some reason not on trunk. The trace
buffer on 8.1.1 was:

starting IMAP session Sun Feb 20 08:26:27 2011
connecting to fb8:1143
connected
* OK [CAPABILITY IMAP4REV1 AUTH=LOGIN] IMAP4rev1 DavMail 3.8.7-trunk server ready^M
VM CAPABILITY^M
* CAPABILITY IMAP4REV1 AUTH=LOGIN^M
VM OK CAPABILITY completed^M
VM LOGIN <parameters omitted>^M
VM OK Authenticated^M
VM SELECT "inbox"^M
* 1 EXISTS^M
* 1 RECENT^M
* OK [UIDVALIDITY 1]^M
* OK [UIDNEXT 60886]^M
* FLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)^M
* OK [PERMANENTFLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)]^M
VM OK [READ-WRITE] SELECT completed^M
VM FETCH 1:1 (UID)^M
* 1 FETCH (UID 60885)^M
VM OK FETCH completed^M
VM FETCH 1:1 (RFC822.SIZE)^M
* 1 FETCH (UID 60885 RFC822.SIZE 2326)^M
VM LOGOUT^M
VM OK FETCH completed^M
* BYE Closing connection^M

Process IMAP connection broken by remote peer

[Uday Reddy (reddyuday)]

John Hein writes:

> Yes, there was on 8.1.1 - but for some reason not on trunk.

It probably got deleted. Please set vm-imap-keep-trace-buffer to t.
That keeps the trace buffer around.

> The trace buffer on 8.1.1 was:
> VM FETCH 1:1 (RFC822.SIZE)^M
> * 1 FETCH (UID 60885 RFC822.SIZE 2326)^M

This shows that the server is volunteering UID when we ask it for
SIZE. That is a mild discrepancy. I will modify VM to ignore the
additional UID.

In the current VM, we ask it for both the UID and SIZE together. I
would be curious to see what it says to that.

Cheers,
Uday

[John Hein (xpqheqdvq4)]

Uday Reddy wrote at 16:12 -0000 on Feb 20, 2011:
 > > The trace buffer on 8.1.1 was:
 > > VM FETCH 1:1 (RFC822.SIZE)^M
 > > * 1 FETCH (UID 60885 RFC822.SIZE 2326)^M
 >
 > This shows that the server is volunteering UID when we ask it for
 > SIZE. That is a mild discrepancy. I will modify VM to ignore the
 > additional UID.
 >
 > In the current VM, we ask it for both the UID and SIZE together. I
 > would be curious to see what it says to that.

Starting IMAP session Sun Feb 20 09:37:29 2011
-- connecting to fb8:1143
* OK [CAPABILITY IMAP4REV1 AUTH=LOGIN] IMAP4rev1 DavMail 3.8.7-trunk server ready^M
-- connected for movemail
VM CAPABILITY^M
* CAPABILITY IMAP4REV1 AUTH=LOGIN^M
VM OK CAPABILITY completed^M
VM LOGIN <parameters omitted>^M
VM OK Authenticated^M
VM SELECT "inbox"^M
* 1 EXISTS^M
* 1 RECENT^M
* OK [UIDVALIDITY 1]^M
* OK [UIDNEXT 60886]^M
* FLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)^M
* OK [PERMANENTFLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)]^M
VM OK [READ-WRITE] SELECT completed^M
VM FETCH 1:1 (UID)^M
* 1 FETCH (UID 60885)^M
VM OK FETCH completed^M
VM FETCH 1:1 (RFC822.SIZE)^M
* 1 FETCH (UID 60885 RFC822.SIZE 2326)^M
VM LOGOUT^M
VM OK FETCH completed^M
* BYE Closing connection^M

Process IMAP connection broken by remote peer
ending IMAP session Sun Feb 20 09:37:30 2011

[Uday Reddy (reddyuday)]

Dear John, please try the attached patch in the lisp directory.

[John Hein (xpqheqdvq4)]

Yes, it seems happier now. I'm curious, do you feel this behavior by the imap server is legal or is vm having to workaround real misbehavior? I'm happy to raise the issue with the davmail folks.

[John Hein (xpqheqdvq4)]

On second thought, I'm getting some duplicate messages in my inbox now. I'm not blaming the patch - I'll see if I can identify which moving part is the cause. I'll open a separate bug if I can determine this is vm related.

[Uday Reddy (reddyuday)]

John Hein writes:

> Yes, it seems happier now. I'm curious, do you feel this behavior by
> the imap server is legal or is vm having to workaround real misbehavior?
> I'm happy to raise the issue with the davmail folks.

Oh, it is probably legal if they bothered to implement it. The RFC
isn't that specific about these things. But davmail is being silly
volunteering stuff that wasn't asked for. The fix I did just assumes
that there could be arbitrary junk that needs to be skipped over.

Cheers,
Uday

[Uday Reddy (reddyuday)]

John Hein writes:

> On second thought, I'm getting some duplicate messages in my inbox now.
> I'm not blaming the patch - I'll see if I can identify which moving part
> is the cause. I'll open a separate bug if I can determine this is vm
> related.

It is probably an independent problem. Again, looking at the trace
buffer should give you clues as to what is happening.

Cheers,
Uday

[Uday Reddy (reddyuday)]

When you look in the buffer-list, you might see multiple IMAP trace buffers. But they will be time-stamped. The attached redefinition of vm-make-trace-buffer-name, which you can put in your .vm file, gives more compact buffer names so that you can see the timestamps easily.

[John Hein (xpqheqdvq4)]

I did capture a trace where vm-expunge-imap-messages _said_ it expunged 11, but really only did 6. This is with the patch applied.

Starting IMAP session Tue Feb 22 05:15:22 2011
-- connecting to fb8:1143
* OK [CAPABILITY IMAP4REV1 AUTH=LOGIN] IMAP4rev1 DavMail 3.8.7-trunk server ready^M
-- connected for expunge
VM CAPABILITY^M
* CAPABILITY IMAP4REV1 AUTH=LOGIN^M
VM OK CAPABILITY completed^M
VM LOGIN <parameters omitted>^M
VM OK Authenticated^M
VM SELECT "inbox"^M
* 11 EXISTS^M
* 11 RECENT^M
* OK [UIDVALIDITY 1]^M
* OK [UIDNEXT 61075]^M
* FLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)^M
* OK [PERMANENTFLAGS (\Answered \Deleted \Draft \Flagged \Seen $Forwarded Junk)]^M
VM OK [READ-WRITE] SELECT completed^M
VM FETCH 1:11 (UID)^M
* 1 FETCH (UID 61064)^M
* 2 FETCH (UID 61065)^M
* 3 FETCH (UID 61066)^M
* 4 FETCH (UID 61067)^M
* 5 FETCH (UID 61068)^M
* 6 FETCH (UID 61069)^M
* 7 FETCH (UID 61070)^M
* 8 FETCH (UID 61071)^M
* 9 FETCH (UID 61072)^M
* 10 FETCH (UID 61073)^M
* 11 FETCH (UID 61074)^M
VM OK FETCH completed^M
VM STORE 1:1 +FLAGS.SILENT (\Deleted)^M
* 1 FETCH (UID 61064 FLAGS (\Deleted))^M
* 1 EXPUNGE^M
VM OK STORE completed^M
VM STORE 2:2 +FLAGS.SILENT (\Deleted)^M
* 2 FETCH (UID 61066 FLAGS (\Deleted))^M
* 2 EXPUNGE^M
VM OK STORE completed^M
VM STORE 3:3 +FLAGS.SILENT (\Deleted)^M
* 3 FETCH (UID 61068 FLAGS (\Deleted))^M
* 3 EXPUNGE^M
VM OK STORE completed^M
VM STORE 4:4 +FLAGS.SILENT (\Deleted)^M
* 4 FETCH (UID 61069 FLAGS (\Deleted))^M
* 3 EXPUNGE^M
* 3 EXPUNGE^M
VM OK STORE completed^M
VM STORE 5:5 +FLAGS.SILENT (\Deleted)^M
* 5 FETCH (UID 61070 FLAGS (\Deleted))^M
* 3 EXPUNGE^M
* 3 EXPUNGE^M
* 3 EXPUNGE^M
VM OK STORE completed^M
VM STORE 6:6 +FLAGS.SILENT (\Deleted)^M
* 6 FETCH (UID 61074 FLAGS (\Deleted))^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM STORE 7:7 +FLAGS.SILENT (\Deleted)^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM STORE 8:8 +FLAGS.SILENT (\Deleted)^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM STORE 9:9 +FLAGS.SILENT (\Deleted)^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM STORE 10:10 +FLAGS.SILENT (\Deleted)^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM STORE 11:11 +FLAGS.SILENT (\Deleted)^M
* 6 EXPUNGE^M
VM OK STORE completed^M
VM CLOSE^M
VM OK CLOSE completed^M
VM LOGOUT^M
* BYE Closing connection^M

Process IMAP connection broken by remote peer
ending IMAP session Tue Feb 22 05:15:27 2011

[Uday Reddy (reddyuday)]

This server definitely looks bad.

> VM STORE 1:1 +FLAGS.SILENT (\Deleted)^M
> * 1 FETCH (UID 61064 FLAGS (\Deleted))^M
> * 1 EXPUNGE^M
> VM OK STORE completed^M

VM asked the server to store \Deleted attribute. But it expunged it
as well! It is not supposed to do so.

> VM STORE 2:2 +FLAGS.SILENT (\Deleted)^M
> * 2 FETCH (UID 61066 FLAGS (\Deleted))^M
> * 2 EXPUNGE^M
> VM OK STORE completed^M

Now we have a problem. VM thinks the message 1 is still there, and
asks it to delete the second message. But, since the message 1 has
been expunged, message 2 is now numbered 1. So, message 3 (with UID
61066) is actually deleted and expunged. This is chaos.

The RFC says "An EXPUNGE response MUST NOT be sent when no command is
in progress, nor while responding to a FETCH, STORE, or SEARCH
command." The server just sent an EXPUNGE response to STORE commands.
This is an explicit violation. This server is bad, bad, bad!

Uday

[John Hein (xpqheqdvq4)]

Bug filed with davmail for the expunge issue:

http://sourceforge.net/tracker/?func=detail&aid=3189285&group_id=184600&atid=909904