On Tue, 2011-12-20 at 13:48 +0100, Maria Arrea wrote:
Hello Timo, thank you in advance. Full log here (1 hour time range)
It could be useful to have all error/warning messages logged to their own file, so you could quickly see a list of all errors from the last day or two. That's also the log I'd be more interested in seeing.
What things do you have accessing mailboxes?
- imap
- pop3
- dovecot-lda
- doveadm purge
Nothing else? No dsync for example?
Dec 14 21:44:30 buzon dovecot: imap(fmcarrasco): Error: /indices_dovecot/indices/07/47/fmcarrasco/mailboxes/INBOX/dovecot.index reset, view is now inconsistent
I think these should happen only when dbox is being rebuilt by another process at the same time.. But it's a bit strange that it happens again in another session:
Dec 14 21:45:30 buzon dovecot: imap-login: Login: user=<fmcarrasco>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=20035, TLS Dec 14 22:01:27 buzon dovecot: imap(fmcarrasco): Error: /indices_dovecot/indices/07/47/fmcarrasco/mailboxes/INBOX/dovecot.index reset, view is now inconsistent
Kind of looks as if it isn't fixing itself?.. Also it might be helpful to have PID in the log lines:
mail_log_prefix = %s(%u %p):
The other one:
Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Sent/dovecot.index reset, view is now inconsistent
Again it's strange how this begins.
Dec 14 21:50:38 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=32118/127014 Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: Recent flags state corrupted for mailbox Trash Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Trash/dovecot.index reset, view is now inconsistent Dec 14 21:50:38 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=38097/309083 Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: Recent flags state corrupted for mailbox Preinscripcion Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Preinscripcion/dovecot.index reset, view is now inconsistent Dec 14 21:50:38 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=33263/164275 Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Emagister/dovecot.index reset, view is now inconsistent Dec 14 21:50:38 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=35437/111594 Dec 14 21:50:38 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=24811, TLS Dec 14 21:50:39 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=24822, TLS Dec 14 21:52:12 buzon postfix/cleanup[21212]: 9A22CC816C: message-id=CAP3xem+Vzw4b_dmDnr=ajn9cfpA8TNotxAVbkM5xoBzxPfu_bQ@mail.gmail.com Dec 14 22:00:27 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Sent/dovecot.index reset, view is now inconsistent Dec 14 22:00:27 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=554/169764 Dec 14 22:00:27 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Trash/dovecot.index reset, view is now inconsistent Dec 14 22:00:27 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=533/10963 Dec 14 22:00:27 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/Preinscripcion/dovecot.index reset, view is now inconsistent Dec 14 22:00:27 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=629/39790 Dec 14 22:00:27 buzon dovecot: imap(cfp): Error: /indices_dovecot/indices/16/58/cfp/mailboxes/INBOX/dovecot.index reset, view is now inconsistent Dec 14 22:00:27 buzon dovecot: imap(cfp): Disconnected: IMAP session state is inconsistent, please relogin. bytes=613/496956
But all of the rest of this is quite clearly caused by the first problem.
I do not see any pattern about this problem of index reset, logs from other day, maybe the problem is I/O load based:
Dec 15 13:16:19 buzon dovecot: imap(ehlers): Error: Mailbox Archivador/Facultad/curso whiteboard: Corrupted index, uidvalidity=0
This is clearly an originating error. But perhaps this is a newly created mailbox? I just noticed that this can happen if a mailbox creation is slow, and another session opens the mailbox before its creation has been finished.
Check with:
doveadm dump ".../mdbox/mailboxes/Mailbox Archivador/Facultad/curso whiteboard/dbox-Mails"
The interesting lines in the output are:
index id ................. = 1324032275 (2011-12-16 12:44:35) uid validity ............. = 1324032275 (2011-12-16 12:44:35)
Dec 15 13:16:19 buzon dovecot: imap(ehlers): Warning: mdbox /buzones/domain/11/53/ehlers/storage: rebuilding indexes
This then caused all of the user's other existing processes to fail with:
Dec 15 13:16:32 buzon dovecot: imap(ehlers): Error: /indices_dovecot/indices/11/53/ehlers/mailboxes/INBOX/dovecot.index reset, view is now inconsistent
Perhaps the other users' problems began with similar errors?