[Dovecot] Are these events normal?
We have dropped dovecot in place of UW-IMAP for about 40000 users and have solved our immediate problem: disk I/O overload, mainly from people doing POP3 and "leave mail on server". Thank you!
Now i got loads of dovecot error messages in the logs and don't know if there is any significance. Here are a few examples:
The most common event is:
2007-12-06 16:00:17.837654500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1547 got too little data: 5176 vs 5184 2007-12-06 16:00:18.575403500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1548 got too little data: 4749 vs 4757 2007-12-06 16:00:19.276147500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1548 got too little data: 4749 vs 4757 2007-12-06 16:00:20.371238500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1540 got too little data: 5162 vs 5170 2007-12-06 16:00:20.996483500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1540 got too little data: 5162 vs 5170 2007-12-06 16:00:21.650218500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1541 got too little data: 4086 vs 4094 2007-12-06 16:00:22.273782500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1541 got too little data: 4086 vs 4094 2007-12-06 16:00:22.920507500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1542 got too little data: 3556 vs 3562 2007-12-06 16:00:23.490787500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1542 got too little data: 3556 vs 3562 2007-12-06 16:00:24.052849500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1543 got too little data: 4098 vs 4106 2007-12-06 16:00:24.741072500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1543 got too little data: 4098 vs 4106 2007-12-06 16:00:25.448977500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1544 got too little data: 4627 vs 4635 2007-12-06 16:00:26.130131500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1544 got too little data: 4627 vs 4635 2007-12-06 16:00:26.819376500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1545 got too little data: 7582 vs 7590 2007-12-06 16:00:27.445497500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1545 got too little data: 7582 vs 7590
Somewhat rarer are events like
2007-12-06 19:36:44.114294500 dovecot: Info: POP3(yyyyyyyy): Disconnected: Storage error during logout. top=1/1723, retr=1/4665462, del=27/61, size=17280696
and rarely we got
2007-11-24 12:10:01.086620500 dovecot: Error: IMAP(zzzzzzzz): file istream-header-filter.c: line 194 (read_header): assertion failed: (hdr == NULL) 2007-11-24 12:10:01.086718500 dovecot: Error: IMAP(zzzzzzzz): Raw backtrace: 2007-11-24 12:10:01.089552500 dovecot: Error: child 13083 (imap) killed with signal 6 2007-11-24 12:10:01.655875500 dovecot: Error: IMAP(zzzzzzzz): file istream-header-filter.c: line 194 (read_header): assertion failed: (hdr == NULL) 2007-11-24 12:10:01.656106500 dovecot: Error: IMAP(zzzzzzzz): Raw backtrace: 2007-11-24 12:10:01.659853500 dovecot: Error: child 13098 (imap) killed with signal 6 2007-11-24 12:10:02.022553500 dovecot: Error: IMAP(zzzzzzzz): file istream-header-filter.c: line 194 (read_header): assertion failed: (hdr == NULL) 2007-11-24 12:10:02.022761500 dovecot: Error: IMAP(zzzzzzzz): Raw backtrace: 2007-11-24 12:10:02.025866500 dovecot: Error: child 13121 (imap) killed with signal 6
Our dovecot is
1.0.5: /usr/local/dovecot/etc/dovecot.conf
log_path: /dev/stderr log_timestamp: protocols: pop3 imap listen(default): 134.147.64.16:143 listen(imap): 134.147.64.16:143 listen(pop3): 134.147.64.16:110 ssl_disable: yes disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/local/dovecot/libexec/dovecot/imap-login login_executable(imap): /usr/local/dovecot/libexec/dovecot/imap-login login_executable(pop3): /usr/local/dovecot/libexec/dovecot/pop3-login login_process_per_connection: no valid_chroot_dirs: /net/sunu007/disc3/home:/net/sunu007/disc4/home max_mail_processes: 4096 first_valid_uid: 50 mail_location: mbox:~/Mail:INBOX=~/Mailbox:INDEX=~/ mail_executable(default): /usr/local/dovecot/libexec/dovecot/imap mail_executable(imap): /usr/local/dovecot/libexec/dovecot/imap mail_executable(pop3): /usr/local/dovecot/libexec/dovecot/pop3 mail_plugin_dir(default): /usr/local/dovecot/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/dovecot/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/dovecot/lib/dovecot/pop3 mail_log_max_lines_per_sec: 0 pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv auth default: passdb: driver: shadow args: blocking=yes userdb: driver: passwd
Is there anything we should do? The crashes have stopped in the meantime, it seems.
Jost
| Helft Spam ausrotten! HTML in Mail ist unhöflich. | | Postmaster, JAPH, manchmal Wahrsager am RZ der RUB | | Wahre Worte sind nicht gefällig, gefällige Worte sind nicht wahr.| | Lao Tse, Tao Te King 81 |
On Fri, 2007-12-07 at 21:08 +0100, Jost Krieger wrote:
We have dropped dovecot in place of UW-IMAP for about 40000 users and have solved our immediate problem: disk I/O overload, mainly from people doing POP3 and "leave mail on server". Thank you!
Now i got loads of dovecot error messages in the logs and don't know if there is any significance. Here are a few examples:
The most common event is:
2007-12-06 16:00:17.837654500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1547 got too little data: 5176 vs 5184 2007-12-06 16:00:18.575403500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1548 got too little data: 4749 vs 4757
This means that the cached message size doesn't match what it is currently. Message sizes should never change. Is something else than Dovecot changing the mailboxes? Are you using NFS or other shared filesystem?
Somewhat rarer are events like
2007-12-06 19:36:44.114294500 dovecot: Info: POP3(yyyyyyyy): Disconnected: Storage error during logout. top=1/1723, retr=1/4665462, del=27/61, size=17280696
It should have logged the actual storage error before this.
and rarely we got
2007-11-24 12:10:01.086620500 dovecot: Error: IMAP(zzzzzzzz): file istream-header-filter.c: line 194 (read_header): assertion failed: (hdr == NULL)
I'm not sure about this. Might be because of the same reason as the FETCH problem, but could as well that there's a bug.. I've done several changes in v1.1 to this code already, I could backport them to v1.0 if these don't disappear.
On Sat, Dec 08, 2007 at 11:20:12AM +0200, Timo Sirainen wrote:
On Fri, 2007-12-07 at 21:08 +0100, Jost Krieger wrote:
The most common event is:
2007-12-06 16:00:17.837654500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1547 got too little data: 5176 vs 5184 2007-12-06 16:00:18.575403500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1548 got too little data: 4749 vs 4757
This means that the cached message size doesn't match what it is currently. Message sizes should never change. Is something else than Dovecot changing the mailboxes?
That is possible. We have a direct access webmail system in place. I'll check there.
Are you using NFS or other shared filesystem?
None of that.
Somewhat rarer are events like
2007-12-06 19:36:44.114294500 dovecot: Info: POP3(yyyyyyyy): Disconnected: Storage error during logout. top=1/1723, retr=1/4665462, del=27/61, size=17280696
It should have logged the actual storage error before this.
No. The environment in a current case was this:
2007-12-08 19:22:16.642824500 dovecot: Info: pop3-login: Login: user=<yyyyyyyy>, method=PLAIN, rip=134.147.64.5, lip=134.147.64.16 2007-12-08 19:24:10.487533500 dovecot: Info: pop3-login: Login: user=<yyyyyyyy>, method=PLAIN, rip=134.147.64.5, lip=134.147.64.16 2007-12-08 19:29:11.413311500 dovecot: Info: POP3(yyyyyyyy): Disconnected: Storage error during logout. top=0/0, retr=5/85885, del=5/5, size=85787 2007-12-08 19:32:17.225681500 dovecot: Info: POP3(yyyyyyyy): Disconnected for inactivity top=0/0, retr=1/4015, del=0/5, size=85787
and rarely we got
2007-11-24 12:10:01.086620500 dovecot: Error: IMAP(zzzzzzzz): file istream-header-filter.c: line 194 (read_header): assertion failed: (hdr == NULL)
I'm not sure about this. Might be because of the same reason as the FETCH problem, but could as well that there's a bug.. I've done several changes in v1.1 to this code already, I could backport them to v1.0 if these don't disappear.
Please don't put any work in that, it was rather rare and seems to have ceased. A few times when I looked it was associated with zero bytes in messages, possibly immediately before the end. Maybe these were leftovers from UW-IMAP.
Jost
| Helft Spam ausrotten! HTML in Mail ist unhöflich. | | Postmaster, JAPH, manchmal Wahrsager am RZ der RUB | | Wahre Worte sind nicht gefällig, gefällige Worte sind nicht wahr.| | Lao Tse, Tao Te King 81 |
On Sat, 2007-12-08 at 22:20 +0100, Jost Krieger wrote:
On Sat, Dec 08, 2007 at 11:20:12AM +0200, Timo Sirainen wrote:
On Fri, 2007-12-07 at 21:08 +0100, Jost Krieger wrote:
The most common event is:
2007-12-06 16:00:17.837654500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1547 got too little data: 5176 vs 5184 2007-12-06 16:00:18.575403500 dovecot: Error: IMAP(xxxxxxxx): FETCH for mailbox UCE-TMP UID 1548 got too little data: 4749 vs 4757
This means that the cached message size doesn't match what it is currently. Message sizes should never change. Is something else than Dovecot changing the mailboxes?
That is possible. We have a direct access webmail system in place. I'll check there.
Since the sizes seemed to always grow 6-8 bytes, maybe it's adding a new header to the messages. If it's really doing that and you want to keep letting it do it, you can add the header to mbox_hide_headers[] and mbox_save_drop_headers[] in src/lib-storage/index/mbox/mbox-storage.c.
participants (3)
-
Jost Krieger
-
Jost Krieger
-
Timo Sirainen