[Dovecot] Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'
Hi,
Since the 23rd of March, we encounter mailbox corruption for some users (15 out of 5000) using POP mainly via Thunderbird. Symptoms are :
-users can login but fail to receive new mails and fail to read their inbox -Dovecot.log : ar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'
We can temporarily fix the issue by manually editing the mailbox so that it begins with a proper 'From'. For some users, the problem reoccurred after we apply this workaround. I have to mention that this server has been running fine since almost a year with the current hardware and software configuration.
Does anybody has an idea regarding this issue?
Many thanks
Henri
============================= System : openSUSE 11.1 (x86_64) Local FS : ReiserFS
dovecot -n # 1.1.7: /etc/dovecot/dovecot.conf # OS: Linux 2.6.27.37-0.1-default x86_64 openSUSE 11.1 (x86_64) log_path: /var/log/dovecot.log syslog_facility: local7 protocols: imap imaps pop3 pop3s managesieve listen(default): * listen(imap): * listen(pop3): * listen(managesieve): *:2000 ssl_cert_file: /etc/ssl/certs/cert_742088754.pem ssl_key_file: /etc/ssl/private/imap.ehess.fr.key disable_plaintext_auth: no verbose_ssl: 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_executable(managesieve): /usr/lib/dovecot/managesieve-login login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no login_greeting_capability(managesieve): no mail_max_userip_connections(default): 10 mail_max_userip_connections(imap): 10 mail_max_userip_connections(pop3): 3 mail_max_userip_connections(managesieve): 10 mail_uid: mail mail_gid: mail mail_location: mbox:~/:INBOX=/var/mail/%u:INDEX=/var/run/dovecot/indexes/%n mbox_lazy_writes: no mail_executable(default): /usr/lib/dovecot/imap mail_executable(imap): /usr/lib/dovecot/imap mail_executable(pop3): /usr/lib/dovecot/pop3 mail_executable(managesieve): /usr/lib/dovecot/managesieve mail_plugins(default): quota imap_quota trash expire mail_plugins(imap): quota imap_quota trash expire mail_plugins(pop3): quota mail_plugins(managesieve): mail_plugin_dir(default): /usr/lib64/dovecot/modules/imap mail_plugin_dir(imap): /usr/lib64/dovecot/modules/imap mail_plugin_dir(pop3): /usr/lib64/dovecot/modules/pop3 mail_plugin_dir(managesieve): /usr/lib64/dovecot/modules/managesieve imap_client_workarounds(default): outlook-idle delay-newmail imap_client_workarounds(imap): outlook-idle delay-newmail imap_client_workarounds(pop3): imap_client_workarounds(managesieve): pop3_reuse_xuidl(default): no pop3_reuse_xuidl(imap): no pop3_reuse_xuidl(pop3): yes pop3_reuse_xuidl(managesieve): no pop3_lock_session(default): no pop3_lock_session(imap): no pop3_lock_session(pop3): yes pop3_lock_session(managesieve): no pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh pop3_client_workarounds(managesieve): dict_db_config: /etc/dovecot/dovecot-db.conf sieve_storage(default): sieve_storage(imap): sieve_storage(pop3): sieve_storage(managesieve): ~/sieve sieve(default): sieve(imap): sieve(pop3): sieve(managesieve): ~/.dovecot.sieve auth default: mechanisms: plain login verbose: yes debug: yes passdb: driver: pam args: dovecot userdb: driver: passwd socket: type: listen client: path: /var/run/dovecot/auth-client mode: 432 master: path: /var/run/dovecot/auth-master mode: 384 plugin: quota: fs:User quota:user:mount=/var/spool/mail quota_rule: *:storage=40M quota_rule2: INB0X:storage=250M quota_rule3: Trash:storage=20M quota_rule4: Spam:ignore quota_rule4: Sent:storage=20M trash: /etc/dovecot/dovecot-trash.conf expire: Trash 7 Spam 1 expire_dict: proxy::expire dict: expire: db:/var/lib/dovecot/expire.db
On Tue, 2010-03-30 at 14:56 +0200, Henri Khou wrote:
-Dovecot.log : ar 29 11:00:06 Error: POP3(user_login): Couldn't initINBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'
I haven't seen these since v0.99. Are you using also Dovecot deliver? Is anything else than Dovecot modifying the mbox files? I don't really have any great ideas, other than some locking problem if something besides Dovecot does changes..
-Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'I haven't seen these since v0.99. Are you using also Dovecot deliver? Is anything else than Dovecot modifying the mbox files? I don't really have any great ideas, other than some locking problem if something besides Dovecot does changes..
We're having the same issues on our servers here and it oddly started at exactly the same time (March 20th or so) with no changes made by us.
We've upgraded to the latest Dovecot 1.2.11 and are using Dovecot 'deliver' exclusively. Tried setting fsync_disable=no, but the problem persists. It seems to only occur for mailboxes that are being accessed via POP3 and leaving mail on the server.
Any further insights? I'm surprised more people aren't experiencing this problem. I don't think we're doing anything particularly special.
Thanks, Erik
# 1.2.11: /etc/postfix/dovecot.conf # OS: FreeBSD 7.2-STABLE i386 base_dir: /var/run/dovecot protocols: imap imaps pop3 pop3s ssl_cert_file: sslcert.pem ssl_key_file: sslcert.pem ssl_cipher_list: ALL:!aNULL:!ADH:!eNULL:!LOW:!EXP:RC4+RSA:+HIGH:+MEDIUM:!SSLv2 disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/local/libexec/dovecot/imap-login login_executable(imap): /usr/local/libexec/dovecot/imap-login login_executable(pop3): /usr/local/libexec/dovecot/pop3-login mbox_read_locks: flock mbox_write_locks: flock mail_executable(default): /usr/local/libexec/dovecot/imap mail_executable(imap): /usr/local/libexec/dovecot/imap mail_executable(pop3): /usr/local/libexec/dovecot/pop3 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(pop3): quota mail_plugin_dir(default): /usr/local/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle tb-extra-mailbox-sep imap_client_workarounds(imap): outlook-idle tb-extra-mailbox-sep imap_client_workarounds(pop3): pop3_no_flag_updates: yes pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh lda: auth_socket_path: /var/run/dovecot/auth-master postmaster_address: postmaster mail_plugins: quota sendmail_path: /usr/sbin/sendmail auth default: mechanisms: plain login master_user_separator: * passdb: driver: passwd-file args: virtual.passwd passdb: driver: passwd-file args: username_format=%n@%l virtual.ip.passwd passdb: driver: passwd-file args: master.passwd passdb: driver: passwd-file args: master.user pass: yes master: yes userdb: driver: passwd-file args: virtual.passwd userdb: driver: passwd-file args: master.passwd socket: type: listen master: path: /var/run/dovecot/auth-master mode: 432 user: vmail group: users
On Wed, 2010-04-28 at 10:46 -0400, Erik Kratzenberg wrote:
-Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'We're having the same issues on our servers here and it oddly started at exactly the same time (March 20th or so) with no changes made by us.
How often do they happen? If it really is related to time, the only thing I can think of is that daylight saving time changed, which increased/decreased some timestamp string and broke some length calculation..
We've upgraded to the latest Dovecot 1.2.11 and are using Dovecot 'deliver' exclusively. Tried setting fsync_disable=no, but the problem persists.
You could try mbox_lazy_writes=no and mbox_dirty_syncs=no, although disabling lazy writing makes the performance worse. Let me know if those fix it..
On 04/29/10 13:52, Timo Sirainen wrote:
On Wed, 2010-04-28 at 10:46 -0400, Erik Kratzenberg wrote:
-Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'We're having the same issues on our servers here and it oddly started at exactly the same time (March 20th or so) with no changes made by us.
How often do they happen? If it really is related to time, the only thing I can think of is that daylight saving time changed, which increased/decreased some timestamp string and broke some length calculation..
It's happening several times a day, sometimes to the same mailbox. I'm not sure if that's a reflection of how busy the mailbox is or not. It's difficult to say how many mailboxes we have being accessed via POP3 since it only seems to affect those, so I can't give you a percentage.
We've upgraded to the latest Dovecot 1.2.11 and are using Dovecot 'deliver' exclusively. Tried setting fsync_disable=no, but the problem persists.
You could try mbox_lazy_writes=no and mbox_dirty_syncs=no, although disabling lazy writing makes the performance worse. Let me know if those fix it..
Unfortunately, these didn't help. We definitely did notice some locking issues with those turned off though so we turned them back on once we were sure they didn't help with the corruption.
We also noticed some other storage and assertion errors around the same time the corruption occurs which may or may not be related:
Mar 28 11:24:20 dovecot: POP3(user@home.com): Disconnected: Storage error during logout. top=0/0, retr=0/0, del=1/35, size=1167453
Mar 26 14:49:36 dovecot: Panic: POP3(user@home.com): file mbox-sync.c: line 1314 (mbox_sync_handle_eof_updates): assertion failed: (offset == 0|| offset > 31)
Mar 24 15:21:59 dovecot: POP3(user@home.com): Cached message offset 2 is invalid for mbox file /usr/boxes/mailbox Mar 24 15:21:59 dovecot: POP3(user@home.com): Disconnected: Storage error during logout. top=0/0, retr=0/0, del=1/232, size=10622872
I'm not sure if "mail_debug=yes" will give us any additional info, but I'm turning that on now.
Thanks, Erik
On Fri, 2010-05-07 at 15:03 -0400, Erik Kratzenberg wrote:
-Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'It's happening several times a day, sometimes to the same mailbox.
How often does the same user get the error?
We also noticed some other storage and assertion errors around the same time the corruption occurs which may or may not be related:
Mar 26 14:49:36 dovecot: Panic: POP3(user@home.com): file mbox-sync.c: line 1314 (mbox_sync_handle_eof_updates): assertion failed: (offset == 0|| offset > 31)
There's a good chance this is related.
Mar 24 15:21:59 dovecot: POP3(user@home.com): Cached message offset 2 is invalid for mbox file /usr/boxes/mailbox
Are you using filesystem quota for users? That might explain this. Otherwise, the above shouldn't be happening if Dovecot is the only software writing to the mbox files..
I'm not sure if "mail_debug=yes" will give us any additional info, but I'm turning that on now.
No, that won't log anything useful.
We've had situations where the same user will have their mailbox corrupted 2 or 3 times a day.
We're not using filesystem quotas and nothing but Dovecot is writing to these mailboxes.
We've been pushing people to switch to IMAP which seems to be the only solution so far. That's decreased the number of reports we're getting, but they're definitely still coming in.
On 05/25/10 15:10, Timo Sirainen wrote:
On Fri, 2010-05-07 at 15:03 -0400, Erik Kratzenberg wrote:
-Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): Couldn't init INBOX: Mailbox isn't a valid mbox -The mailbox start with either 'FFrom or 'FrFrom'It's happening several times a day, sometimes to the same mailbox.
How often does the same user get the error?
We also noticed some other storage and assertion errors around the same time the corruption occurs which may or may not be related:
Mar 26 14:49:36 dovecot: Panic: POP3(user@home.com): file mbox-sync.c: line 1314 (mbox_sync_handle_eof_updates): assertion failed: (offset == 0|| offset> 31)
There's a good chance this is related.
Mar 24 15:21:59 dovecot: POP3(user@home.com): Cached message offset 2 is invalid for mbox file /usr/boxes/mailbox
Are you using filesystem quota for users? That might explain this. Otherwise, the above shouldn't be happening if Dovecot is the only software writing to the mbox files..
I'm not sure if "mail_debug=yes" will give us any additional info, but I'm turning that on now.
No, that won't log anything useful.
I experienced this today with my own IMAP folder, so maybe being able to offer a more specific order of events will help. Also not sure if I previously mentioned that this is occasionally happening with IMAP folders even though it's much more common under POP3.
I had just cleaned out my Junk folder.
Two messages were received without error.
I marked the folder as read in Thunderbird.
I restarted Thunderbird
The next delivery attempt to that mailbox (using dovecot deliver) failed:
save failed to Junk: Mailbox isn't a valid mbox file
The odd thing is that the delivery *did* succeed because that message is in there. The very first message header is the one that was corrupted which always seems to be the case. Does "deliver" read/write the entire mbox file or just append the new message to the end?
On 06/08/10 11:24, Erik Kratzenberg wrote:
We've had situations where the same user will have their mailbox corrupted 2 or 3 times a day.
We're not using filesystem quotas and nothing but Dovecot is writing to these mailboxes.
We've been pushing people to switch to IMAP which seems to be the only solution so far. That's decreased the number of reports we're getting, but they're definitely still coming in.
On 05/25/10 15:10, Timo Sirainen wrote:
On Fri, 2010-05-07 at 15:03 -0400, Erik Kratzenberg wrote:
> -Dovecot.log : Mar 29 11:00:06 Error: POP3(user_login): > Couldn't init INBOX: Mailbox isn't a valid mbox > -The mailbox start with either 'FFrom or 'FrFrom' It's happening several times a day, sometimes to the same mailbox.
How often does the same user get the error?
We also noticed some other storage and assertion errors around the same time the corruption occurs which may or may not be related:
Mar 26 14:49:36 dovecot: Panic: POP3(user@home.com): file mbox-sync.c: line 1314 (mbox_sync_handle_eof_updates): assertion failed: (offset == 0|| offset> 31)
There's a good chance this is related.
Mar 24 15:21:59 dovecot: POP3(user@home.com): Cached message offset 2 is invalid for mbox file /usr/boxes/mailbox
Are you using filesystem quota for users? That might explain this. Otherwise, the above shouldn't be happening if Dovecot is the only software writing to the mbox files..
I'm not sure if "mail_debug=yes" will give us any additional info, but I'm turning that on now.
No, that won't log anything useful.
On Tue, 2010-07-20 at 08:42 -0400, Erik Kratzenberg wrote:
I experienced this today with my own IMAP folder, so maybe being able to offer a more specific order of events will help. Also not sure if I previously mentioned that this is occasionally happening with IMAP folders even though it's much more common under POP3.
- I had just cleaned out my Junk folder.
- Two messages were received without error.
So basically what POP3 clients usually do, delete everything. Does the mailbox have the "FOLDER INTERNAL DATA" message at the beginning?
I marked the folder as read in Thunderbird.
I restarted Thunderbird
The next delivery attempt to that mailbox (using dovecot deliver) failed:
save failed to Junk: Mailbox isn't a valid mbox file
The odd thing is that the delivery *did* succeed because that message is in there.
Or maybe you just got two of those same messages? :) I don't think it could have written it after giving this error.
The very first message header is the one that was corrupted which always seems to be the case. Does "deliver" read/write the entire mbox file or just append the new message to the end?
deliver first checks that the mbox file is valid by reading and verifying the From_-line at the beginning of the file. If it's ok, then it appends to end of file. The corruption most likely happened during the expunge, not in deliver.
Hmm. See what it logs with attached patch?
On Tue, 2010-07-20 at 08:42 -0400, Erik Kratzenberg wrote:
I experienced this today with my own IMAP folder, so maybe being able to offer a more specific order of events will help. Also not sure if I previously mentioned that this is occasionally happening with IMAP folders even though it's much more common under POP3.
- I had just cleaned out my Junk folder.
- Two messages were received without error.
So basically what POP3 clients usually do, delete everything. Does the mailbox have the "FOLDER INTERNAL DATA" message at the beginning?
It did not and still doesn't, after having more messages received.
I marked the folder as read in Thunderbird.
I restarted Thunderbird
The next delivery attempt to that mailbox (using dovecot deliver) failed:
save failed to Junk: Mailbox isn't a valid mbox file
The odd thing is that the delivery *did* succeed because that message is in there.
Or maybe you just got two of those same messages? :) I don't think it could have written it after giving this error.
Well, it had the exact same Message ID and also had several deliveries afterwards that succeeded before I tried to access the mailbox again with IMAP.
The very first message header is the one that was corrupted which always seems to be the case. Does "deliver" read/write the entire mbox file or just append the new message to the end?
deliver first checks that the mbox file is valid by reading and verifying the From_-line at the beginning of the file. If it's ok, then it appends to end of file. The corruption most likely happened during the expunge, not in deliver.
Hmm. See what it logs with attached patch?
I'll get that patch added and let you know. Thanks.
On Mon, 2010-07-26 at 12:47 -0400, Erik Kratzenberg wrote:
On Tue, 2010-07-20 at 08:42 -0400, Erik Kratzenberg wrote:
I experienced this today with my own IMAP folder, so maybe being able to offer a more specific order of events will help. Also not sure if I previously mentioned that this is occasionally happening with IMAP folders even though it's much more common under POP3.
- I had just cleaned out my Junk folder.
- Two messages were received without error.
So basically what POP3 clients usually do, delete everything. Does the mailbox have the "FOLDER INTERNAL DATA" message at the beginning?
It did not and still doesn't, after having more messages received.
If you delete all messages from mailbox, INTERNAL DATA message doesn't show up there? The mbox file size becomes zero? If so, it doesn't sound like you're really using Dovecot v1.x..
If you delete all messages from mailbox, INTERNAL DATA message doesn't show up there? The mbox file size becomes zero? If so, it doesn't sound like you're really using Dovecot v1.x..
It looks like if I'm starting without the folder existing (whether it's a new delivery rule or you delete the folder from IMAP), deliver doesn't create the FOLDER INTERNAL DATA so it will just start appending messages to it.
Once that first message is received, IMAP won't create the FOLDER INTERNAL DATA message until I delete all the messages from the folder.
When I delete all the messages from the folder, they are not actuall removed until I restart my mail client. If new messages are received to that folder before I restart my mail client, then it also won't create the FOLDER INTERNAL DATA message.
I'm not sure if that's directly related to this issue, but I know the corrupted From line is always the first message in a mailbox and is never the FOLDER INTERNAL DATA message.
Erik Kratzenberg put forth on 7/27/2010 8:32 AM:
If you delete all messages from mailbox, INTERNAL DATA message doesn't show up there? The mbox file size becomes zero? If so, it doesn't sound like you're really using Dovecot v1.x..
It looks like if I'm starting without the folder existing (whether it's a new delivery rule or you delete the folder from IMAP), deliver doesn't create the FOLDER INTERNAL DATA so it will just start appending messages to it.
Once that first message is received, IMAP won't create the FOLDER INTERNAL DATA message until I delete all the messages from the folder.
When I delete all the messages from the folder, they are not actuall removed until I restart my mail client. If new messages are received to that folder before I restart my mail client, then it also won't create the FOLDER INTERNAL DATA message.
I'm not sure if that's directly related to this issue, but I know the corrupted From line is always the first message in a mailbox and is never the FOLDER INTERNAL DATA message.
I've only had this problem once, many months ago. I solved it by making sure the user was not logged in, editing the mbox file with vi, removing the leading "F", and saving the file. IIRC I then deleted the Dovecot index files to be on the safe side (not sure if it was necessary) and let them auto rebuild.
-- Stan
On 07/27/10 10:09, Stan Hoeppner wrote:
I've only had this problem once, many months ago. I solved it by making sure the user was not logged in, editing the mbox file with vi, removing the leading "F", and saving the file. IIRC I then deleted the Dovecot index files to be on the safe side (not sure if it was necessary) and let them auto rebuild.
Yeah, we can easily fix them when they come up, but unfortunately with thousands of mailboxes spread across many servers we're having it occur pretty frequently. A handful of mailboxes have had it happen more than once, but usually it's a new mailbox each time.
On Tue, 2010-07-27 at 09:32 -0400, Erik Kratzenberg wrote:
If you delete all messages from mailbox, INTERNAL DATA message doesn't show up there? The mbox file size becomes zero? If so, it doesn't sound like you're really using Dovecot v1.x..
It looks like if I'm starting without the folder existing (whether it's a new delivery rule or you delete the folder from IMAP), deliver doesn't create the FOLDER INTERNAL DATA so it will just start appending messages to it.
Right, that's how it should work.
Once that first message is received, IMAP won't create the FOLDER INTERNAL DATA message until I delete all the messages from the folder.
Same here.
When I delete all the messages from the folder, they are not actuall removed until I restart my mail client. If new messages are received to that folder before I restart my mail client, then it also won't create the FOLDER INTERNAL DATA message.
I guess this means the messages are marked as \Deleted, but client hasn't sent EXPUNGE yet.
I'm not sure if that's directly related to this issue, but I know the corrupted From line is always the first message in a mailbox and is never the FOLDER INTERNAL DATA message.
What I find strange is that you said this happens to POP3 users who delete all of the mails. Once all mails are deleted, the FOLDER INTERNAL DATA message should be written. After it is written, it should never get deleted afterwards. So how is it possible that POP3 users who regularly delete all of their mails still don't have the FOLDER INTERNAL DATA message?
participants (4)
-
Erik Kratzenberg
-
Henri Khou
-
Stan Hoeppner
-
Timo Sirainen