[Dovecot] got too little data ??
I just switched in a hurry one of our mailbox servers from UW-imapd to Dovecot in an attempt to address performance and stability problems.
This server hosts ~5500 accounts, ~2000 are daily used, ~600 simultaneous IMAP connexions in rush hours, and lots of POP ones. Some accounts may be accessed simultaneously with IMAP and POP.
The system is :
- Debian Sarge (x86 with amd64 kernel)
- MBOX files mailboxes
- indexes migrated out of filesystem quotas
- Sendmail MTA
- Procmail local delivery agent (not easily replaceable due to extensive use of procmailrc filters)
- Both Procmail and Dovecot use [dotlock, fcntl] as mailbox locking scheme
- No other processes have access to mailboxes in normal use
- Dovecot 1.0.8 hand-compiled from tarball
The good new is that it seems to perform better than UW-imapd.
The bad new is that we get lots or errors like this in log:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too little data:3186 vs 3206
Such "accidents" happen about 4-5 times a day, and does not correct themselves, even with a mailbox expunge or reopen. However manual deletion of the faulty mailbox index seems to clear the problem, until another one occurs. On such errors some mail clients (Thunderbird) retry operation in infinite loop, so log gets really cluttered.
In imap-fetch-body.c it is stated : "We shouldn't really ever get here. One reason is if mail was deleted from NFS server while we were reading it. Another is some temporary disk error."
Both reasons do not seem to apply in our case: mail partition is not NFS-mounted, and disks (a RAID5 array) seem healthy. Furthermore, affected accounts are not over quota.
So may we have found a bug ? Or may we have a locking problem ? Or an index handling one ?
I tried to disable mbox_lazy_writes without success. I will try to disable disk indexes totally, which should help since problems seem index-related; but performance may suffer.
Any clues appreciated...
Dovecot -n says :
# 1.0.8: /usr/local/etc/dovecot.conf protocols: imap imaps pop3 pop3s listen: [::] ssl_cert_file: /usr/local/etc/ssl/private/our-certificate.pem ssl_key_file: /usr/local/etc/ssl/private/our-certificate.pem disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/local/libexec/dovecot/imap-login login_executable(imap): /usr/local/libexec/dovecot/imap-login login_executable(pop3): /usr/local/libexec/dovecot/pop3-login first_valid_uid: 200 first_valid_gid: 200 mail_location: mbox:~/mail:INBOX=~/mail/INBOX:INDEX=/espace/dovecot/indexes/%u fsync_disable: yes mbox_lazy_writes: no mail_executable(default): /usr/local/libexec/dovecot/imap mail_executable(imap): /usr/local/libexec/dovecot/imap mail_executable(pop3): /usr/local/libexec/dovecot/pop3 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(pop3): quota mail_plugin_dir(default): /usr/local/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle tb-extra-mailbox-sep delay-newmail imap_client_workarounds(imap): outlook-idle tb-extra-mailbox-sep delay-newmail imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xv%08Xu pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh auth default: passdb: driver: pam args: * userdb: driver: passwd plugin: quota: fs
-- Ce message a ete verifie par MailScanner pour des virus ou des polluriels et rien de suspect n'a ete trouve.
On 11.12.2007, at 19.54, Benoit Branciard wrote:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too little
data: 3186 vs 3206
Wonder why this started happening only now. I heard first about this
last saturday, and now you.. Looks like I can reproduce this myself
with stress testing as well. I don't remember seeing it before
though. I'll see if I can get it fixed soon.
For God's sake, Timo, cut us adrift for a week and study for your exams. You warned us; exercise some self-preservation. The community should understand that it has to fend for itself for awhile.........and not make big changes on production systems
Timo Sirainen wrote:
On 11.12.2007, at 19.54, Benoit Branciard wrote:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too littledata: 3186 vs 3206
Wonder why this started happening only now. I heard first about this last saturday, and now you.. Looks like I can reproduce this myself with stress testing as well. I don't remember seeing it before though. I'll see if I can get it fixed soon.
No kidding. I went out and snow blowed the driveway and before I came back, the bug existed, you said what I was thinking, and Timo had a patch for it.
If he doesn't have a commanding job prior to graduation I'll be flabbergasted.
Blow me down. It's even on the web page already.
Stewart Dean wrote:
For God's sake, Timo, cut us adrift for a week and study for your exams. You warned us; exercise some self-preservation. The community should understand that it has to fend for itself for awhile.........and not make big changes on production systems
Timo Sirainen wrote:
On 11.12.2007, at 19.54, Benoit Branciard wrote:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too littledata: 3186 vs 3206
Wonder why this started happening only now. I heard first about this last saturday, and now you.. Looks like I can reproduce this myself with stress testing as well. I don't remember seeing it before though. I'll see if I can get it fixed soon.
On Tue, 2007-12-11 at 20:03 +0200, Timo Sirainen wrote:
On 11.12.2007, at 19.54, Benoit Branciard wrote:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too little
data: 3186 vs 3206Wonder why this started happening only now. I heard first about this
last saturday, and now you.. Looks like I can reproduce this myself
with stress testing as well. I don't remember seeing it before
though. I'll see if I can get it fixed soon.
Fixed: http://hg.dovecot.org/dovecot-1.0/rev/7c83c2d9c378
I guess I'll do 1.0.9 release as well.
On Tue, 2007-12-11 at 20:37 +0200, Timo Sirainen wrote:
On Tue, 2007-12-11 at 20:03 +0200, Timo Sirainen wrote:
On 11.12.2007, at 19.54, Benoit Branciard wrote:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too little
data: 3186 vs 3206Wonder why this started happening only now. I heard first about this
last saturday, and now you.. Looks like I can reproduce this myself
with stress testing as well. I don't remember seeing it before
though. I'll see if I can get it fixed soon.
Benoit Branciard a écrit :
I just switched in a hurry one of our mailbox servers from UW-imapd to Dovecot in an attempt to address performance and stability problems. [...] The bad new is that we get lots or errors like this in log:
IMAP(username): FETCH for mailbox INBOX UID 23862 got too little data: 3186 vs 3206
We are running 1.0.9 (which includes Timo's patch) for about one day without the bug showing up anymore. So the fix seems OK.
I believe Dovecot is the only software for which bugs are fixed in less time I need to complete the bug report :-)
-- Ce message a ete verifie par MailScanner pour des virus ou des polluriels et rien de suspect n'a ete trouve.
participants (4)
-
Benoit Branciard
-
Rick Romero
-
Stewart Dean
-
Timo Sirainen