[Dovecot] Occasional error msgs from 1.0-test49

newer
[Dovecot] default_mail_env problems

Gregory Bond

20 Oct 2004 20 Oct '04

2:32 a.m.

I'm running 1.0-test49 on Solaris 2.8. MUA is Thunderbird (or mutt) running on FreeBSD. I'm using Maildir boxes.

Occasionally, when browsing new mail in INBOX, I get an error back from the imapd, displayed in Thunderbird as the following popup msg:

The current command did not succeed.  The mail server responded: 
Error in IMAP command UID: Invalid BODY[..] parameter: 
Missing '>' in '&lt;36864,-34800>'.

...

Nothing is in the maillog.

This _didn't_ happen with 0.99.

Show replies by date

Curtis Maloney

20 Oct 20 Oct

2:37 a.m.

Gregory Bond wrote:

...

I'm running 1.0-test49 on Solaris 2.8. MUA is Thunderbird (or mutt) running on FreeBSD. I'm using Maildir boxes.

For comparison:

I'm running 0.99.11 on Solaris 2.9. MUS is Thunderbird (with one Outlook user) for about 25 users... oh, and a couple of dial up users using Eudora to collect via POP3.

And it runs just fine.

So, as nifty as all the wonderful new features are in the 1.0 series (and I _do_ want to get my hands on some of them) I'm sticking with what works for now.

I note from your earlier mail you were using an older 0.99.10.9 version. Perhaps give 0.99.11 a shot?

-- Curtis

Timo Sirainen

2:45 a.m.

On 20.10.2004, at 02:32, Gregory Bond wrote:

...

There are two potential reasons for this. One is that Dovecot replies something wrong and causes Thunderbird to send negative message size request. Another is that it's entirely Thunderbird bug which Dovecot just points out. Most (all?) other servers would treat -34800 as 4294932496 and hide the problem. This is what Dovecot 0.99.x did too.

So far I'm thinking it's Thunderbird bug which should be fixed. Even if Dovecot was responsible in some way for it, it shouldn't be sending negative message sizes.

Gregory Bond

3:16 a.m.

Timo Sirainen wrote:

...

I've snagged a repeatable case and got a truss of the imap process. I'm inclined to agree with you.

I'll report it to the Thunderbird ppl.

The sequence is (more or less) this:

Client: 10 UID fetch 90309 (BODYSTRUCTURE)

[imapd reads the whole message, then futzes with the dovecot.index file]

Imapd: * 6056 FETCH (BODYSTRUCTURE ("text" "plain" ("charset" "iso-8859-1") NIL NIL "7bit" 796 22 NIL NIL NIL) UID 90309) Imapd: 10 OK Fetch completed.

Client:11 UID fetch 90309 (UID RFC822.SIZE BODY[]<0.10240>)

[imapd read the whole file again - TWICE!]

Imapd: * 6056 FETCH (BODY[]<0> {2064} [entire message] UID 90309 RFC822.SIZE 2064)

[more index stuffing]

Imapd: 11 OK Fetch completed.

Client: 12 UID fetch 90309 (UID RFC822.SIZE BODY[]<10240.-8176>)

Imapd: 12 BAD Error in IMAP command UID: Invalid BODY[..] parameter: Missing '>' in '<10240.-8176>'

Gregory Bond

3:39 a.m.

Gregory Bond wrote:

...

I'll report it to the Thunderbird ppl.

Loks like Jan Kuipers already did!

http://bugzilla.mozilla.org/show_bug.cgi?id=263904

Timo Sirainen

4:59 a.m.

On 20.10.2004, at 03:16, Gregory Bond wrote:

...

Imapd: * 6056 FETCH (BODYSTRUCTURE ("text" "plain" ("charset" "iso-8859-1") NIL NIL "7bit" 796 22 NIL NIL NIL) UID 90309) Imapd: 10 OK Fetch completed.

So the message body is 796 bytes.

...

Client:11 UID fetch 90309 (UID RFC822.SIZE BODY[]<0.10240>)

And Thunderbird requests first 10240 bytes of the message.

...

Imapd: * 6056 FETCH (BODY[]<0> {2064}

But gets only 2064 bytes because header + body is only 2064 bytes long.

...

Client: 12 UID fetch 90309 (UID RFC822.SIZE BODY[]<10240.-8176>)

Then it's requesting next -8176 next bytes (10240 - 8176 = 2064). So for some reason it's thinking the message is larger then 10240 bytes and messes up the calculations.

Does Dovecot ever reply wrong message size for RFC822.SIZE request? ..

Gregory Bond

5:52 a.m.

...

Timo Sirainen wrote:

...

Then it's requesting next -8176 next bytes (10240 - 8176 = 2064).

Yep, noticed that "coincidence".

...

Does Dovecot ever reply wrong message size for RFC822.SIZE request? ..

Not that I can see here in this session, tho it is possible that it has done so previously and the (bogus) size is being cached by Thunderbird somehow. I've had a poke around thunderbird's state file and it seems not (but without understanding the INBOX.msf file format I can't be sure).

I'll try and set up some truss runs to catch this failure on a new message - it seems pretty common so we'll see.

10240 is also a suspicious number (=10k); I wonder if that magic number appears anywhere in Dovecot? (or Thunderbird, but I ain't scanning 200Mb of source to find out!)

Gregory Bond

7:53 a.m.

Timo Sirainen wrote:

...

Does Dovecot ever reply wrong message size for RFC822.SIZE request? ..

Got one. It just happened again on a new message, and I was running tcpflow on the connection from waaaay before this email (UID 90356) arrived.

Looks like a gen-you-wine Thunderbird bug, as Dovecot never gives the bogus msg size (20480 - which is exactly 20k).

The following is from tcpflow for the imap connetion from the first mention of this UID to the error (pasting together the two tcpflow log files to recreate the conversation).

I'll attach this trace to the Bugzilla report.

Maybe a candidate for imap-client workaround?

Greg.

...

126 noop <126 OK NOOP completed

...

127 UID fetch 90356:* (FLAGS) <* 6069 FETCH (FLAGS (\Recent) UID 90356) <127 OK Fetch completed.

...

128 UID fetch 90356 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To)]) <* 6069 FETCH (BODY[HEADER.FIELDS (FROM TO CC SUBJECT DATE MESSAGE-ID PRIORITY X-PRIORITY REFERENCES NEWSGROUPS IN-REPLY-TO)] {272} {msg header here} < UID 90356 RFC822.SIZE 895 FLAGS (\Recent)) <128 OK Fetch completed.

...

129 IDLE <+ idling DONE <129 OK Idle completed.

...

130 noop <130 OK NOOP completed.

...

131 UID fetch 90357:* (FLAGS) <* 6069 FETCH (FLAGS (\Recent) UID 90356) <131 OK Fetch completed.

...

132 IDLE <+ idling DONE <132 OK Idle completed.

...

133 check <133 OK Check completed.

...

134 UID fetch 90357:* (FLAGS) <* 6069 FETCH (FLAGS (\Recent) UID 90356) <134 OK Fetch completed.

...

135 IDLE <+ idling DONE <135 OK Idle completed.

...

136 noop <136 OK NOOP completed.

...

137 UID fetch 90357:* (FLAGS) <* 6069 FETCH (FLAGS (\Recent) UID 90356) <137 OK Fetch completed.

...

138 IDLE <+ idling DONE <138 OK Idle completed.

...

139 uid store 90355 +Flags (\Answered) <* 6068 FETCH (FLAGS (\Answered \Seen \Recent)) 139 OK Store completed.

...

140 IDLE <+ idling DONE <140 OK Idle completed.

...

141 UID fetch 90356 (BODYSTRUCTURE) <* 6069 FETCH (BODYSTRUCTURE ("text" "plain" ("charset" "us-ascii") NIL NIL "7bit" 277 6 NIL ("inline" NIL) NIL) UID 90356) <141 OK Fetch completed.

...

142 UID fetch 90356 (UID RFC822.SIZE BODY[]<0.20480>) <* 6069 FETCH (BODY[]<0> {895} <msg hdr and body here> UID 90356 RFC822.SIZE 895 FLAGS (\Seen \Recent)) <142 OK Fetch completed.

...

143 UID fetch 90356 (UID RFC822.SIZE BODY[]<20480.-19585>) <143 BAD Error in IMAP command UID: Invalid BODY[..] parameter: Missing '>' in '<20480.-19585>'

...