[Dovecot] Index corruption with squirrelmail.
Hi.
I don't know if the problem is related with squirrelmail or not, but I started to have index corruption when I started to try squirrelmail.
Some informaton about my instalation: dovecot 1.0.5-1 debian package with maildir squirrelmail 1.4.9a-2 debian package
Some log information:
dovecot: 2008-02-27 08:39:39 Warning: IMAP(
I'm not pretty sure, but it looks like that if I keep my thunderbird open, receive a message and a rule move the message from INBOX to some other folder and then, finally, I try to login in squirrelmail I reveive a message like this: Query: EXPUNGE
And in my log file the above message appears.
I already deleted dovecot.* files, but the error ocurred again.
Any suggestion?
Thanks!
On 2/27/2008, Fábio M. Catunda (fcatunda@contactnet.com.br) wrote:
dovecot 1.0.5-1 debian package with maildir squirrelmail 1.4.9a-2 debian package
They're both older...
The first thing I always do if I am having a problem with a certain app is make sure I'm running current versions.
Backports will have current versions of both of these...
--
Best regards,
Charles
Charles Marcus escreveu:
On 2/27/2008, Fábio M. Catunda (fcatunda@contactnet.com.br) wrote:
dovecot 1.0.5-1 debian package with maildir squirrelmail 1.4.9a-2 debian package
They're both older...
The first thing I always do if I am having a problem with a certain app is make sure I'm running current versions.
Backports will have current versions of both of these...
Yeap, but they are in stable tree.
Do you believe that this is a version problem?
Thanks!
On Feb 27, 2008, at 2:24 PM, Fábio M. Catunda wrote:
dovecot: 2008-02-27 08:39:39 Warning: IMAP(
to me>): fscking index file /var/virtual/contactnet.com.br/fcatunda/ Maildir/dovecot.index
There isn't anything else before this line? Something causes fsck,
which causes:
dovecot: 2008-02-27 08:39:39 Error: IMAP(
me>): Unexpected transaction log desync with index /var/virtual/ contactnet.com.br/fcatunda/Maildir/dovecot.index
What filesystem do you use? Do you use NFS? Show your dovecot -n output?
Timo Sirainen escreveu:
On Feb 27, 2008, at 2:24 PM, Fábio M. Catunda wrote: There isn't anything else before this line? Something causes fsck, which causes:
Now I have some more messages:
dovecot: 2008-02-27 10:30:18 Error: IMAP(<e-mail address>): Corrupted index cache file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.cache: indexid changed dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): Corrupted transaction log file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.log: invalid indexid (1204119018 != 1204118656) dovecot: 2008-02-27 10:31:06 Warning: IMAP(<e-mail address>): fscking index file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): Transaction log file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.log: marked corrupted dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): Corrupted transaction log file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.log: invalid new transaction log sequence (3 >= 3) dovecot: 2008-02-27 10:31:06 Warning: IMAP(<e-mail address>): fscking index file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): file mail-transaction-log-view.c: line 107 (mail_transaction_log_view_set): assertion failed: (min_file_seq <= max_file_seq) dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): Raw backtrace: imap [0x80ae0e1] -> imap [0x80adffc] -> imap(mail_transaction_log_view_set+0x55a) [0x809c72a] -> imap [0x80971e2] -> imap(mail_index_view_sync_begin+0xa6) [0x8097526] -> imap(index_mailbox_sync_init+0x84) [0x80863b4] -> imap(maildir_storage_sync_init+0x8a) [0x806ac7a] -> imap(imap_sync_init+0x40) [0x8063dd0] -> imap(cmd_sync+0x7b) [0x8063f0b] -> imap [0x805992f] -> imap(cmd_fetch+0x2ca) [0x8059c7a] -> imap(cmd_uid+0x50) [0x805cb60] -> imap [0x805d0ef] -> imap [0x805d17c] -> imap(_client_input+0x6f) [0x805d81f] -> imap(io_loop_handler_run+0x107) [0x80b3ed7] -> imap(io_loop_run+0x1c) [0x80b315c] -> imap(main+0x47c) [0x80657ac] -> /lib/i686/cmov/libc.so.6(__libc_start_main+0xe0) [0xb7e01450] -> imap [0x8058391] dovecot: 2008-02-27 10:31:06 Error: child 4281 (imap) killed with signal 6 dovecot: 2008-02-27 10:31:06 Error: IMAP(<e-mail address>): Transaction log file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.log: marked corrupted
This is the first time that I see this "mail-transaction-log-view.c" line.
What filesystem do you use? Do you use NFS? Show your dovecot -n output?
ext3 filesystem, it's not a NFS mount.
And here it goes dovecot -n output:
# 1.0.5: /etc/dovecot/dovecot.conf base_dir: /var/run/dovecot/ log_path: /var/log/dovecot/error.log info_log_path: /var/log/dovecot/info.log log_timestamp: %Y-%m-%d %H:%M:%S protocols: imap pop3 ssl_disable: yes disable_plaintext_auth: no shutdown_clients: no version_ignore: yes login_dir: /var/run/dovecot/login login_executable(default): /usr/lib/dovecot/imap-login login_executable(imap): /usr/lib/dovecot/imap-login login_executable(pop3): /usr/lib/dovecot/pop3-login login_greeting: Bem Vindo. login_process_per_connection: no login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no login_process_size: 128 login_processes_count: 4 login_max_processes_count: 64 first_valid_uid: 0 last_valid_uid: 9999 first_valid_gid: 0 last_valid_gid: 9999 mail_extra_groups: mail mailsystem mail_location: maildir:/var/virtual/%d/%n/Maildir mail_cache_fields: mail_never_cache_fields: maildir_copy_with_hardlinks: yes maildir_copy_preserve_filename: yes mail_executable(default): /usr/lib/dovecot/imap mail_executable(imap): /usr/lib/dovecot/imap mail_executable(pop3): /usr/lib/dovecot/pop3 mail_process_size: 512 mail_plugins(default): lazy_expunge mail_log mail_plugins(imap): lazy_expunge mail_log mail_plugins(pop3): mail_plugin_dir(default): /usr/lib/dovecot/modules/imap mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3 mail_log_max_lines_per_sec: 0 imap_client_workarounds(default): outlook-idle delay-newmail imap_client_workarounds(imap): outlook-idle delay-newmail imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh namespace: type: private prefix: INBOX. inbox: yes namespace: type: private separator: / prefix: .EXPUNGED/ location: maildir:/var/virtual/%d/%n/Maildir/expunged hidden: yes namespace: type: private separator: / prefix: .DELETED/ location: maildir:/var/virtual/%d/%n/Maildir/deleted hidden: yes namespace: type: private separator: / prefix: .DELETED/.EXPUNGED/ location: maildir:/var/virtual/%d/%n/Maildir/deleted/expunged auth default: username_format: %u passdb: driver: ldap args: /etc/dovecot/dovecot-ldap.conf userdb: driver: ldap args: /etc/dovecot/dovecot-ldap.conf plugin: lazy_expunge: .EXPUNGED/ .DELETED/ .DELETED/.EXPUNGED/ lazy_expunge: .EXPUNGED/ .DELETED/ .DELETED/.EXPUNGED/
The corruption is happening just in my account. This morning I'm testing just with thunderbird (not using squirrelmail anymore) and the problem is happening all the time.
I don't know if the issue is related with the fact that I have a lot of messages in my INBOX, but it's not that big:
du -sm ./* 1 ./courierimapkeywords 1 ./courierimapsubscribed 1 ./courierimapuiddb 87 ./cur 1 ./deleted 1 ./dovecot.index 1 ./dovecot.index.cache 1 ./dovecot.index.log 1 ./dovecot.index.log.2 1 ./dovecot-keywords 1 ./dovecot-uidlist 70 ./expunged 1 ./new 1 ./subscriptions 1 ./tmp 1 .Curriculos 4 .Dovecot 1 .Draft 1 .Drafts 1 .Nagios 3 .Request Tracker 2 .RT 14 .Sent 1 .Sent Items 1 .Spam 1 .Trash
If you need any other information, please, just ask me!
Thanks for the help!
Some addional information that I found:
This problem started on 02/21/2008 when I moved a message that has id 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos from .Spam folder to INBOX and then moved the message back to .Spam folder.
Today this message looks to be causing the problem.... still! See some loggging:
dovecot: 2008-02-27 17:55:33 Error: IMAP(fcatunda@contactnet.com.br): Maildir /var/virtual/contactnet.com.br/fcatunda/Maildir sync: UID inserted in the middle of mailbox (8055 > 8042, file = 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos,S=3129:2,ST) dovecot: 2008-02-27 17:57:46 Error: IMAP(fcatunda@contactnet.com.br): Corrupted index cache file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index.cache: indexid changed dovecot: 2008-02-27 20:17:57 Error: IMAP(fcatunda@contactnet.com.br): Maildir /var/virtual/contactnet.com.br/fcatunda/Maildir sync: UID inserted in the middle of mailbox (8055 > 8042, file = 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos,S=3129:2,ST)
I don't know if it helps or not, but I believe that this is a good tip about the problem.
Thanks.
Timo Sirainen escreveu:
On Feb 27, 2008, at 2:24 PM, Fábio M. Catunda wrote:
dovecot: 2008-02-27 08:39:39 Warning: IMAP(
): fscking index file /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index There isn't anything else before this line? Something causes fsck, which causes:
dovecot: 2008-02-27 08:39:39 Error: IMAP(
): Unexpected transaction log desync with index /var/virtual/contactnet.com.br/fcatunda/Maildir/dovecot.index What filesystem do you use? Do you use NFS? Show your dovecot -n output?
On Wed, 2008-02-27 at 20:36 -0300, "Fábio M. Catunda" wrote:
Some addional information that I found:
This problem started on 02/21/2008 when I moved a message that has id 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos from .Spam folder to INBOX and then moved the message back to .Spam folder. .. Maildir /var/virtual/contactnet.com.br/fcatunda/Maildir sync: UID inserted in the middle of mailbox (8055 > 8042, file = 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos,S=3129:2,ST) dovecot: 2008-02-27 17:57:46 Error: IMAP(fcatunda@contactnet.com.br): Corrupted index cache file
You say you moved Spam -> INBOX -> Spam, but is it possible that this was originally also in INBOX? So INBOX -> Spam -> INBOX -> Spam? That's what this looks like.
Anyway this kind of moving back and forth without changing filename isn't a good idea. It causes Dovecot to think that a message got "unexpunged" which gives the above error. v1.1 handles this a bit more nicely by renaming the new file, although it still logs a warning:
imap(tss): Warning: Maildir /home/tss/Maildir: Expunged message reappeared, giving a new UID (old uid=365234, file=foo:2,)
Timo,
That's true, the message arrived in INBOX, then I moved it to Spam and did it one more time.
What I did to solve the problem without the need to expunge that specific message is just rename the file to some other name and then logged in again.
# mv 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos teste123
Thanks!
Timo Sirainen escreveu:
On Wed, 2008-02-27 at 20:36 -0300, "Fábio M. Catunda" wrote:
Some addional information that I found:
This problem started on 02/21/2008 when I moved a message that has id 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos from .Spam folder to INBOX and then moved the message back to .Spam folder.
..
Maildir /var/virtual/contactnet.com.br/fcatunda/Maildir sync: UID inserted in the middle of mailbox (8055 > 8042, file = 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos,S=3129:2,ST) dovecot: 2008-02-27 17:57:46 Error: IMAP(fcatunda@contactnet.com.br): Corrupted index cache file
You say you moved Spam -> INBOX -> Spam, but is it possible that this was originally also in INBOX? So INBOX -> Spam -> INBOX -> Spam? That's what this looks like.
Anyway this kind of moving back and forth without changing filename isn't a good idea. It causes Dovecot to think that a message got "unexpunged" which gives the above error. v1.1 handles this a bit more nicely by renaming the new file, although it still logs a warning:
imap(tss): Warning: Maildir /home/tss/Maildir: Expunged message reappeared, giving a new UID (old uid=365234, file=foo:2,)
It might help somebody with that squirrelmail error, so I will post here, maybe google find it someday.
That "Query: EXPUNGE" message occurs becouse an index corruption error, but dovecot can handle it and rebuild the index. So why squirrelmail show the error message? Lets fix it:
in SM_PATH/functions/imap_mailbox.php go to line 260 and replace $tmp = sqimap_run_command($imap_stream, 'EXPUNGE', false, $a, $b);
by $tmp = sqimap_run_command($imap_stream, 'EXPUNGE', true, $a, $b);
I hope it helps!
[]'s, Catunda!
Fábio M. Catunda escreveu:
Timo,
That's true, the message arrived in INBOX, then I moved it to Spam and did it one more time.
What I did to solve the problem without the need to expunge that specific message is just rename the file to some other name and then logged in again.
# mv 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos teste123
Thanks!
Timo Sirainen escreveu:
On Wed, 2008-02-27 at 20:36 -0300, "Fábio M. Catunda" wrote:
Some addional information that I found:
This problem started on 02/21/2008 when I moved a message that has id 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos from .Spam folder to INBOX and then moved the message back to .Spam folder.
..
Maildir /var/virtual/contactnet.com.br/fcatunda/Maildir sync: UID inserted in the middle of mailbox (8055 > 8042, file = 1191941480.M342094P9293V0000000000000903I003B9713_0.cronos,S=3129:2,ST) dovecot: 2008-02-27 17:57:46 Error: IMAP(fcatunda@contactnet.com.br): Corrupted index cache file
You say you moved Spam -> INBOX -> Spam, but is it possible that this was originally also in INBOX? So INBOX -> Spam -> INBOX -> Spam? That's what this looks like.
Anyway this kind of moving back and forth without changing filename isn't a good idea. It causes Dovecot to think that a message got "unexpunged" which gives the above error. v1.1 handles this a bit more nicely by renaming the new file, although it still logs a warning:
imap(tss): Warning: Maildir /home/tss/Maildir: Expunged message reappeared, giving a new UID (old uid=365234, file=foo:2,)
participants (3)
-
"Fábio M. Catunda"
-
Charles Marcus
-
Timo Sirainen