thr3ads.net - dovecot - [Dovecot] Are these events normal? [Dec 2007]

If this information is useful, please help other people find it:
Share via:

Jost Krieger

2007-Dec-07 20:08 UTC

[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 |
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20071207/b1fbe900/attachment-0002.bin>

Timo Sirainen

2007-Dec-08 09:20 UTC

head link

[Dovecot] Are these events normal?

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.
-------------- 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/20071208/6d85f49c/attachment-0002.bin>

Possibly Parallel Threads

Search for more apparently analagous threads

dovecot - Dec 2007 - Are these events normal?

[Dovecot] Are these events normal?

[Dovecot] Are these events normal?

Possibly Parallel Threads