Re: [Dovecot] Question about index reset in dovecot 2.0.15
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@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@confcfp.org, size=23256, nrcpt=1 (queue active) Dec 14 21:43:00 buzon postfix/qmgr[4015]: E7E61C7DED: from=scet2012a@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@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)?
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?
participants (2)
-
Maria Arrea
-
Timo Sirainen