[Dovecot] Question about index reset in dovecot 2.0.15

[Maria Arrea]

Hello Timo, thank you in advance. Full log here (1 hour time range)

 Dec 14 21:19:43 buzon postfix/pipe[27103]: 4423BC7C31: to=<fmcarrasco at domain>, relay=dovecot, delay=0.24, delays=0.03
 /0/0/0.2, dsn=2.0.0, status=sent (delivered via dovecot service)
 Dec 14 21:20:59 buzon dovecot: imap(fmcarrasco): Disconnected: Logged out bytes=556/2245
 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
 Dec 14 21:44:30 buzon dovecot: imap(fmcarrasco): Disconnected: IMAP session state is inconsistent, please relogin. bytes=42402/3153543
 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
 Dec 14 22:01:27 buzon dovecot: imap(fmcarrasco): Disconnected: IMAP session state is inconsistent, please relogin. bytes=343/8671
 Dec 14 22:02:58 buzon dovecot: imap-login: Login: user=<fmcarrasco>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=2685, TLS
 Dec 14 22:13:46 buzon dovecot: lda(fmcarrasco): sieve: msgid=<f81a253ebaceca9bf0a6635027e4d747s>: stored mail into mailbox 'INBOX'
 Dec 14 22:13:46 buzon postfix/pipe[21152]: AAD36C8501: to=<fmcarrasco>, relay=dovecot, delay=0.34, delays=0.03/0.01/0/0.31, dsn=2.0.0, status=sent (delivered via dovecot service)


 The other one:

 Dec 14 20:53:38 buzon dovecot: pop3(cfp): Connection closed top=0/0, retr=0/0, del=0/3605, size=446902389
 Dec 14 21:38:34 buzon postfix/qmgr[4015]: A90CFC7C31: from=<scet2012a at confcfp.org>, size=23256, nrcpt=1 (queue active)
 Dec 14 21:43:00 buzon postfix/qmgr[4015]: E7E61C7DED: from=<scet2012a at confcfp.org>, size=23244, nrcpt=1 (queue active)
 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
 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
 Dec 14 22:00:27 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=464, TLS
 Dec 14 22:00:27 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=465, TLS
 Dec 14 22:00:27 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=466, TLS
 Dec 14 22:00:27 buzon dovecot: imap-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=467, TLS
 Dec 14 22:30:28 buzon dovecot: pop3-login: Login: user=<cfp>, method=PLAIN, rip=192.168.1.13, lip=192.168.4.80, mpid=25194


 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:06 buzon dovecot: imap(ehlers): Connection closed bytes=357/20249
 Dec 15 13:16:06 buzon dovecot: imap(ehlers): Connection closed bytes=70/12804
 Dec 15 13:16:12 buzon dovecot: imap-login: Login: user=<ehlers>, method=PLAIN, rip=192.168.1.150, lip=192.168.4.80, mpid=1005
 Dec 15 13:16:12 buzon dovecot: imap(ehlers): Connection closed bytes=103/818
 Dec 15 13:16:19 buzon dovecot: imap-login: Login: user=<ehlers>, method=PLAIN, rip=192.168.1.150, lip=192.168.4.80, mpid=1419
 Dec 15 13:16:19 buzon dovecot: imap(ehlers): Error: Mailbox Archivador/Facultad/curso whiteboard: Corrupted index, uidvalidity=0
 Dec 15 13:16:19 buzon dovecot: imap(ehlers): Warning: mdbox /buzones/domain/11/53/ehlers/storage: rebuilding indexes
 Dec 15 13:16:19 buzon dovecot: imap-login: Login: user=<ehlers>, method=PLAIN, rip=192.168.1.150, lip=192.168.4.80, mpid=1426
 Dec 15 13:16:19 buzon dovecot: imap(ehlers): Connection closed bytes=459/3205
 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
 Dec 15 13:16:32 buzon dovecot: imap(ehlers): Disconnected: IMAP session state is inconsistent, please relogin. bytes=195/963
 Dec 15 13:16:32 buzon dovecot: imap-login: Login: user=<ehlers>, method=PLAIN, rip=192.168.1.150, lip=192.168.4.80, mpid=2006
 Dec 15 13:16:32 buzon dovecot: imap(ehlers): Connection closed bytes=274/80860
 Dec 15 13:16:49 buzon dovecot: imap-login: Login: user=<ehlers>, method=PLAIN, rip=192.168.1.150, lip=192.168.4.80, mpid=2735


 Any idea?

 Regards

 Maria




 On Wed, 2011-12-14 at 22:10 +0100, Maria Arrea wrote: > I have seen some strange error log messages in our dovecot server (2.0.15, RHEL 5.7x64, mdbox+zlib, local storage, high load) > > 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 > 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 These messages shouldn't appear alone. Is there anything else logged about them? > Dec 14 20:56:46 buzon dovecot: imap(rcam): Error: Corrupted index cache file /indices_dovecot/indices/03/6b/rcam/mailboxes/INBOX/dovecot.index.cache: Broken virtual size for mail UID 132197 Possibly related to zlib.. Again it should have logged another error message just before this. > Dec 14 21:50:38 buzon dovecot: imap(cfp): Error: Recent flags state corrupted for mailbox INBOX Possibly related to other errors. So .. none of the errors above really were what I'd call the actual cause of the problems. They were just after effects. > I have been googling without luck, why does this happen? I have tried with doveadm force-resync, maybe this could solve this issues. All of those should be fixed automatically. Do they keep happening if you don't do force-resync? How often do they happen anyway? Do they happen at any specific times (e.g. during doveadm purge)?