[Dovecot] Corrupted transaction log file
Hi,
I'm experiencing a problem I need some pointers to debug.
I'm running Dovecot 2.0.15 and have a client which keeps causing log-entries like:
Nov 4 15:10:42 mail dovecot: imap (test@aaaone.net): Error: Corrupted transaction log file /mail/3340444/.TestMails/dovecot.index.log seq 2: indexid changed 1320419300 -> 1320419441 (sync_offset=0) Nov 4 15:10:42 mail dovecot: imap(test@aaaone.net): Error: Corrupted transaction log file /mail/3340444/.TestMails/dovecot.index.log seq 2: Invalid transaction log size (4476 vs 4360): /mail/3340444/. TestMails/dovecot.index.log (sync_offset=4476) Nov 4 15:10:42 mail dovecot: imap(test@aaaone.net): Disconnected: IMAP session state is inconsistent, please relogin. bytes=549/100474
The client issues a lot of IMAP connections like this:
A1_0 LOGIN "test@aaaone.net" "password" A1_1 ENABLE QRESYNC CONDSTORE
- OK Waiting for authentication process to respond..
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE STARTTLS AUTH=PLAIN] Dovecot ready. A1_0 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS] Logged in
- ENABLED QRESYNC CONDSTORE A1_1 OK Enabled. A2_0 CREATE "INBOX.folder" A2_0 OK Create completed. A3_0 SUBSCRIBE "INBOX.folder" A3_0 OK Subscribe completed. A4_0 APPEND "INBOX.folder" ($CreatedByImapClient-test) {20487+} ... more similar appends.
But it only seems to be reproducible, when there's another client involved. Starting up Thunderbird with a login to the account seems to be enough to cause this. (To my knowledge this causes a series of STATUS command and then IDLE).
The installation is using Maildir and lock_method = fcntl on local disks.
/Peter
On Fri, 2011-11-04 at 20:23 +0100, Peter Mogensen wrote:
I'm running Dovecot 2.0.15 and have a client which keeps causing log-entries like:
Nov 4 15:10:42 mail dovecot: imap (test@aaaone.net): Error: Corrupted transaction log file /mail/3340444/.TestMails/dovecot.index.log seq 2: indexid changed 1320419300 -> 1320419441 (sync_offset=0)
Session A had TestMails open and created with index file whose ID was 1320419300 (that's also UNIX timestamp of its creation time, Fri Nov 4 17:08:20 EET 2011).
Session B came and recreated the index files 141 seconds later with ID 1320419441. Either it didn't see A's original index files for some reason or it simply decided to recreate them for some reason. Either way this shouldn't have happened.
Session A then notices that the indexes were recreated, and logs an error.
But it only seems to be reproducible, when there's another client involved. Starting up Thunderbird with a login to the account seems to be enough to cause this. (To my knowledge this causes a series of STATUS command and then IDLE).
The installation is using Maildir and lock_method = fcntl on local disks.
What filesystem? Have changed any service imap {} settings? Can you reproduce this by running stress test with imaptest? http://imapwiki.org/ImapTest For example:
imaptest user=testuser pass=testpass host=localhost
Or if it's really related to creating the initial files:
while imaptest user=testuser pass=testpass host=localhost secs=1; do rm -rf /home/testuser/Maildir done
On 2011-11-04 22:26, Timo Sirainen wrote:
Nov 4 15:10:42 mail dovecot: imap (test@aaaone.net): Error: Corrupted transaction log file /mail/3340444/.TestMails/dovecot.index.log seq 2: indexid changed 1320419300 -> 1320419441 (sync_offset=0)
Session A had TestMails open and created with index file whose ID was 1320419300 (that's also UNIX timestamp of its creation time, Fri Nov 4 17:08:20 EET 2011).
Session B came and recreated the index files 141 seconds later with ID 1320419441. Either it didn't see A's original index files for some reason or it simply decided to recreate them for some reason. Either way this shouldn't have happened.
Session A then notices that the indexes were recreated, and logs an error.
Oh... wait a minute...
The timestamp is UTC, so 17:08:20 is about 2:22 before the log line. 2:22 is 142 seconds. So... given that the errors doesn't appear every time the client runs the series of APPEND requests, but (now I come to think of it) probably never the first time he runs it, but the second time - and that he did run the script a few minutes before this log line with out errors, then it should have finished and logged out long before session B.
- then... the problem might be that the first run of the script doesn't finish correctly. If session A is the first run of the script,
But maybe the problem is the first run not finishing properly.
/Peter
On 2011-11-04 22:26, Timo Sirainen wrote:
Nov 4 15:10:42 mail dovecot: imap (test@aaaone.net): Error: Corrupted transaction log file /mail/3340444/.TestMails/dovecot.index.log seq 2: indexid changed 1320419300 -> 1320419441 (sync_offset=0)
Session A had TestMails open and created with index file whose ID was 1320419300 (that's also UNIX timestamp of its creation time, Fri Nov 4 17:08:20 EET 2011).
Session B came and recreated the index files 141 seconds later with ID 1320419441. Either it didn't see A's original index files for some reason or it simply decided to recreate them for some reason. Either way this shouldn't have happened.
Turns out this is expected to confuse Session A. The client in question sometimes start the session (B) with this command sequence: DELETE folder CREATE folder APPEND...
Any Session A having opened "folder" of course would be surprised that there's a new index file (makes we wish for an IMAP5 where folderID!=displayname)
This can be reproduced by hand speaking IMAP with two telnets.
Only question left is, why does Dovecot end the log sequence by saying:
"Disconnected: IMAP session state is inconsistent, please relogin."
... when it is capable of detecting this and returning "BYE folder deleted under us" and logging the same.
/Peter
participants (2)
-
Peter Mogensen
-
Timo Sirainen