Bug Report:
We had one of our solr server down for a while, then observed a lot of
"Warning: fscking index file " actions. Version 2.2.27 with auto
fsck.
A follow up investigation shows direct one to one relationship between solr
error and subsequent fscking. The fscking lasts for quite a long time (for at
least an hour) when the mailbox is concurrently accessed.
Thank you.
Netfront Hong Kong
Dec 16 07:48:14 dovecot: pop3(glhk44): Disconnected: Logged out top=0/0,
retr=0/0, del=0/221, size=143216382
Dec 16 08:13:20 dovecot: pop3-login: Login: user=<glhk44>, method=PLAIN,
rip=4.5.6.7, lip=1.2.3.4, mpid=99633, TLS, session=<JzQEcLtDEooqYqt/>
Dec 16 08:13:23 dovecot: pop3(glhk44): Disconnected: Logged out top=0/0,
retr=0/0, del=0/221, size=143216382
Dec 16 08:39:10 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 08:46:01 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 08:53:33 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 08:57:53 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:00:39 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:05:00 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:09:32 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:21:44 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:24:59 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:29:52 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:31:08 dovecot: indexer-worker(glhk44): Indexed 1 messages in INBOX
Dec 16 09:44:18 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=22866, session=<0yNKtbxDwuTaZxfh>
Dec 16 09:44:18 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=22867, session=<GWJLtbxDw+TaZxfh>
Dec 16 09:44:18 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=22868, session=<WBtOtbxDxOTaZxfh>
Dec 16 09:44:18 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=22869, session=<ueZOtbxDxeTaZxfh>
Dec 16 09:44:29 dovecot: pop3-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=23090, TLS, session=<iGL6tbxDsGDaZxfh>
Dec 16 09:44:30 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=127.0.0.1, lip=127.0.0.1, mpid=23093, secured,
session=<wOkJtrxDpkl/AAAB>
Dec 16 09:44:31 dovecot: imap(glhk44): Connection closed in=0 out=404
Dec 16 09:45:34 dovecot: pop3(glhk44): Disconnected: Logged out top=0/0,
retr=11/3587310, del=0/232, size=146803474
Dec 16 09:45:38 dovecot: imap(glhk44): Logged out in=202 out=4336
Dec 16 09:46:17 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=27449, session=<zLltvLxD0OTaZxfh>
Dec 16 09:46:19 dovecot: imap-login: Login: user=<glhk44>, method=PLAIN,
rip=6.7.8.9, lip=1.2.3.4, mpid=27550, session=<FtiHvLxD0eTaZxfh>
Dec 16 09:46:20 dovecot: imap(glhk44): copy from INBOX: box=Deleted Messages,
uid=1690, msgid=<RkJNAAAAAAqAgMEKAAAACoAA7m1Hw9Fq0 at
ShawsCrabHouse.fbmta.com>, size=6759
Dec 16 09:46:20 dovecot: imap(glhk44): delete: box=INBOX, uid=124159,
msgid=<20161215164627444789108 at sensioinc.cn>, size=127611
Dec 16 09:46:20 dovecot: imap(glhk44): expunge: box=INBOX, uid=124159,
msgid=<20161215164627444789108 at sensioinc.cn>, size=127611
Dec 16 09:46:28 dovecot: imap(glhk44): Error: fts_solr: Indexing failed: 503
Service Unavailable < ----------------------- solr error
Dec 16 09:46:28 dovecot: indexer-worker(glhk44): Error: fts_solr: Indexing
failed: 503 Service Unavailable
Dec 16 09:46:28 dovecot: indexer-worker(glhk44): Error: Mailbox Deleted
Messages: Transaction commit failed: FTS transaction commit failed: backend
deinit
Dec 16 09:46:28 dovecot: imap(glhk44): copy from INBOX: box=Deleted Messages,
uid=1691, msgid=<20161215003910.C4439ABB653 at smtp3.mthai.in.th>,
size=17896
Dec 16 09:46:29 dovecot: indexer-worker(glhk44): Indexed 1 messages in Deleted
Messages
Dec 16 09:46:30 dovecot: imap(glhk44): delete: box=INBOX, uid=124164,
msgid=<00c701d256b1$3bbbcfd0$b3336f70$@com>, size=107064
Dec 16 09:46:30 dovecot: imap(glhk44): expunge: box=INBOX, uid=124164,
msgid=<00c701d256b1$3bbbcfd0$b3336f70$@com>, size=107064
Dec 16 09:46:31 dovecot: imap(glhk44): delete: box=INBOX, uid=124175,
msgid=<00f201d256c2$a4db5f10$ee921d30$@com>, size=3518208
Dec 16 09:46:31 dovecot: imap(glhk44): expunge: box=INBOX, uid=124175,
msgid=<00f201d256c2$a4db5f10$ee921d30$@com>, size=3518208
Dec 16 09:46:31 dovecot: imap(glhk44): copy from INBOX: box=Deleted Messages,
uid=1692, msgid=<1616393.344200011xAAAAA at
enterprisecommunicationnetwork.com>, size=47100
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Corrupted transaction log file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index.log seq 1268: file
size shrank (28960 < 29056) (sync_offset=29056) <-------- fscking
starts
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: indexer-worker(glhk44): Indexed 1 messages in Deleted
Messages
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Error: Index
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for
seq=1268 offset=24900: Failed to map file seq=1268
offset=24900..18446744073709551615 (ret=0) (initial_mapped=1, reason=Index
mapped)
Dec 16 09:46:31 dovecot: imap(glhk44): Warning: fscking index file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index
Dec 16 09:46:31 dovecot: imap(glhk44): Logged out in=833 out=13350
Dec 16 09:46:31 dovecot: imap(glhk44): copy from INBOX: box=Deleted Messages,
uid=1693, msgid=<1616408.344200011xAAAAA at
enterprisecommunicationnetwork.com>, size=44739
Dec 16 09:46:31 dovecot: indexer-worker(glhk44): Error: Transaction log file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index.log: marked
corrupted
Dec 16 09:46:32 dovecot: indexer-worker(glhk44): Indexed 1 messages in Deleted
Messages
Dec 16 09:46:32 dovecot: imap(glhk44): Error: Corrupted transaction log file
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index.log seq 1268:
Invalid transaction log size (28960 vs 24900):
/home/glhk44/mdbox/mailboxes/INBOX/dbox-Mails/dovecot.index.log (sync_offset=289
60)
