Possible solr and indexing bug

Netfront Customer Service support at netfront.net
Fri Dec 16 05:53:20 UTC 2016 

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)

More information about the dovecot mailing list