dovecot - May 2008 - FETCH for mailbox INBOX UID 5003 got too little data: 5369 vs 38919

This happened a while back, I was running 1.1rc3 up until today so I have no
idea
if it would have an effect.  Sorry if its something that has been fixed.  The 
error below was repeated many many times, I deleted the index so the user would
stop getting disconnected (although I didn't hear any complaints).  I have
not
seen this happen repeatedly in this manner to any other user yet.

Apr 15 11:26:48 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX UID
5003 got too little data: 5369 vs 38919
Apr 15 11:26:48 boomhauer dovecot: IMAP(username): Corrupted index cache file
/home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
Broken virtual size for mail UID 5003
Apr 15 11:26:48 boomhauer dovecot: IMAP(username): Disconnected: Disconnected
bytes=139/145074
Apr 15 11:27:08 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX UID
5003 got too little data: 5369 vs 38919
Apr 15 11:27:08 boomhauer dovecot: IMAP(username): Corrupted index cache file
/home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
Broken virtual size for mail UID 5003
Apr 15 11:27:08 boomhauer dovecot: IMAP(username): Disconnected: Disconnected
bytes=139/145074
Apr 15 11:28:50 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX UID
5003 got too little data: 5369 vs 38919
Apr 15 11:28:50 boomhauer dovecot: IMAP(username): Corrupted index cache file
/home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
Broken virtual size for mail UID 5003
Apr 15 11:28:50 boomhauer dovecot: IMAP(username): Disconnected: Disconnected
bytes=139/145074
Apr 15 11:38:02 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX UID
5003 got too little data: 5369 vs 38919
Apr 15 11:38:02 boomhauer dovecot: IMAP(username): Corrupted index cache file
/home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
Broken virtual size for mail UID 5003
Apr 15 11:38:02 boomhauer dovecot: IMAP(username): Disconnected: Disconnected
bytes=139/145074
Apr 15 11:38:52 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX UID
5003 got too little data: 5369 vs 38919
Apr 15 11:38:52 boomhauer dovecot: IMAP(username): Corrupted index cache file
/home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
Broken virtual size for mail UID 5003
Apr 15 11:38:52 boomhauer dovecot: IMAP(username): Disconnected: Disconnected
bytes=139/145074
>From dovecot-uidlist:
5003 W38919 S38270 :1208208981.7303_0.hill:2,S

-rw-------  1 username  faculty  5236 Apr 14 17:36 1208208981.7303_0.hill:2,S

# ls -l .snapshot/*/1208208981.7303_0.hill*
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.0/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.1/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.10/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.11/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.12/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.13/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.14/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.15/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.16/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.17/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.18/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.19/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.2/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.20/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.21/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.22/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.3/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.4/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.5/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.6/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.7/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.8/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/hourly.9/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/nightly.0/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/nightly.1/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/nightly.2/1208208981.7303_0.hill:2,S
-rw-------  1 username  faculty  5236 Apr 14 17:36
.snapshot/nightly.3/1208208981.7303_0.hill:2,S

# mv dovecot.index.cache dovecot.index.cache.broken

On Mon, 2008-05-05 at 22:46 -0400, Adam McDougall wrote:
> This happened a while back, I was running 1.1rc3 up until today so I have
no idea
> if it would have an effect.  Sorry if its something that has been fixed. 
The
> error below was repeated many many times, I deleted the index so the user
would
> stop getting disconnected (although I didn't hear any complaints).
Only the index, not dovecot-uidlist also? I don't think it got fixed
until dovecot-uidlist was deleted/fixed.
> Apr 15 11:26:48 boomhauer dovecot: IMAP(username): FETCH for mailbox INBOX
UID
> 5003 got too little data: 5369 vs 38919
> Apr 15 11:26:48 boomhauer dovecot: IMAP(username): Corrupted index cache
file
> /home/username/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.cache:
> Broken virtual size for mail UID 5003
Here Dovecot already marked cache file to be corrupted, causing it to be
rebuilt.
> >From dovecot-uidlist:
> 5003 W38919 S38270 :1208208981.7303_0.hill:2,S
> 
> -rw-------  1 username  faculty  5236 Apr 14 17:36
1208208981.7303_0.hill:2,S
Now this is the problem. Why did Dovecot think the message is 38 kB and
save it to dovecot-uidlist? How far do your snapshots go? Is it possible
that the file was modified somehow? Are ctime and mtime the same?

I guess Dovecot should also automatically fix broken dovecot-uidlist
fields. I'll add in TODO.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080507/b9060165/attachment-0002.bin>