[Dovecot] Question about index reset in dovecot 2.0.15

[Timo Sirainen]

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 at 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?