Dimos Alevizos
2013-Jun-19 13:00 UTC
[Dovecot] Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'
Hello, we're having some problems with our dovecot setup. I've seen similar problems in the mailing list some years ago but alas wasn't able to find a solution. Our setup is as follows : An MX farm (postfix) sends mails via LMTP to a director farm (dovecot 2.1.12) which proxies pop3/imap/lmtp traffic to a dovecot farm (dovecot 2.1.16). All mailboxes and indexes are on NFS and all servers are Centos. The problem is that at times we see mailboxes (all of them are in mbox format) beginning with FFrom or FrFrom and of course dovecot says it's not a valid mbox file. If we manually remove the offending extra characters from the beginning of the file everything is working again, but often the same user will show the problem again tomorrow. However it's very rare and so far we haven't been able to reproduce the problem. After activating the mail_log plugin hoping it'll help us locate the problem we run across this case : The user (let's call him user at domain.gr) logs in via pop3 and deletes some mails but one of them fails: Jun 19 11:09:18 pop01 dovecot: pop3-login: Login: user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.40, mpid=1389, secured, session=<Ao+rWH3fHgBT660a> Jun 19 11:09:18 director5 dovecot: pop3-login: proxy(user at domain.gr): started proxying to 83.235.66.40:110: user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.65, session=<Ao+rWH3fHgBT660a> Jun 19 11:09:24 pop01 dovecot: pop3(user at domain.gr): expunge: box=INBOX, uid=20670, msgid=<9f5b1a20a9428ed31a9e7e42ce4411f08d0.20130612070424 at mail84.us2.rsgsv.net>, size=36526 Jun 19 11:09:24 pop01 dovecot: pop3(user at domain.gr): expunge: box=INBOX, uid=20671, msgid=<b27d72dc5a47a3235a232494c6fe8aa0 at newsletter.stockout.gr>, size=4637 Jun 19 11:09:24 pop01 dovecot: pop3(user at domain.gr): expunge: box=INBOX, uid=20672, msgid=<1113670779560.1111910791405.1470.2.32032003 at scheduler.constantcontact.com>, size=38655 Jun 19 11:09:24 pop01 dovecot: pop3(user at domain.gr): expunge: box=INBOX, uid=20673, msgid=<83600a274c1407c5aa4c263e2592cb54 at debop.gr>, size=1181688 Jun 19 11:09:24 pop01 dovecot: pop3(user at domain.gr): expunge: box=INBOX, uid=20674, msgid=<F2A59BE7-007A-4567-9BA5-803446C3D7F8 at bernier-eliades.gr>, size=61116 Jun 19 11:09:26 pop01 dovecot: pop3(user at domain.gr): Error: Next message unexpectedly corrupted in mbox file /var/mail/K/Y/V/domain_gr_user_007 at 1 Jun 19 11:09:26 pop01 dovecot: pop3(user at domain.gr): Error: Cached message offset 1 is invalid for mbox file /var/mail/K/Y/V/domain_gr_user_007 Jun 19 11:09:27 pop01 dovecot: pop3(user at domain.gr): Disconnected: Logged out top=0/0, retr=2/1502843, del=122/359, size=137448432 Jun 19 11:09:27 pop01 dovecot: pop3(user at domain.gr): Warning: Our dotlock file /var/mail/K/Y/V/domain_gr_user_007.lock was deleted (locked 9 secs ago, touched 9 secs ago) Jun 19 11:09:27 pop01 dovecot: pop3(user at domain.gr): Error: file_dotlock_delete() failed with mbox file /var/mail/K/Y/V/domain_gr_user_007: No such file or directory Jun 19 11:09:27 director5 dovecot: pop3-login: proxy(user at domain.gr): disconnecting 83.235.173.26 (Disconnected by server): user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.65, session=<Ao+rWH3fHgBT660a> However he's still able to log in again : Jun 19 11:11:36 pop01 dovecot: pop3-login: Login: user=<user at domain.gr>, method=PLAIN, rip=85.74.231.10, lip=83.235.66.40, mpid=10094, secured, session=<QDLrYH3f7ABVSucK> Jun 19 11:11:36 director3 dovecot: pop3-login: proxy(user at domain.gr): started proxying to 83.235.66.40:110: user=<user at domain.gr>, method=PLAIN, rip=85.74.231.10, lip=83.235.66.63, session=<QDLrYH3f7ABVSucK> Jun 19 11:11:51 pop01 dovecot: pop3(user at domain.gr): Disconnected: Logged out top=0/0, retr=0/0, del=0/237, size=75036938 Jun 19 11:11:51 director3 dovecot: pop3-login: proxy(user at domain.gr): disconnecting 85.74.231.10 (Disconnected by server): user=<user at domain.gr>, method=PLAIN, rip=85.74.231.10, lip=83.235.66.63, session=<QDLrYH3f7ABVSucK> A few minutes later he receives another mail which is delivered with no problem : Jun 19 11:30:39 corvus amavis[546]: (00546-22) Passed CLEAN, [91.190.168.40] [91.190.168.40] <tk-14439 at free.splio.com> -> <user at domain.gr>, Message-ID: <58175-bWFyaW5hQGJlcm5pZXItZWxpYWR lcy5ncg==@free.splio.com>, mail_id: J1P-0WpmQksJ, Hits: 1.412, size: 9025, queued_as: 02BA4AE00414, Tests: [DKIM_VALID=-0.1,DKIM_VERIFIED=-0.1,FREEMAIL_FROM=0.001,HTML_IMAGE_RATIO_04=0.61,INVALID_MSGID=1,URIBL_BLOCKED=0.001], autolearn=disabled, 1533 ms Jun 19 11:30:39 corvus smtp/smtpd[1283]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 02BA4AE00414; from=<tk-14439 at free.splio.com> to=<marina at bernier-eliades.gr> proto=ESMTP helo=<poc-pbcs2.splio.com> Jun 19 11:30:39 pop01 dovecot: lmtp(4099, user at domain.gr): 77O4IHlGwVEDEAAAYg/qxw: msgid=58175-bWFyaW5hQGJlcm5pZXItZWxpYWRlcy5ncg==@free.splio.com: from=residence.suddenly at gmx.com size=9610 saved mail to INBOX Jun 19 11:30:39 corvus postfix/lmtp[1350]: 02BA4AE00414: to=<user at domain.gr>, relay=lmtp.otenet.gr[62.103.147.209]:24, delay=0.12, delays=0.01/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 <user at domain.gr> 77O4IHlGwVEDEAAAYg/qxw Saved) And then RIGHT after the successful delivery, the mbox somehow ends up corrupted with an FFrom in the beginning : Jun 19 11:31:27 pop01 dovecot: pop3-login: Login: user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.40, mpid=14630, secured, session=<eBLjp33fUwBT660a> Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Error: Syncing INBOX failed: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Error: Couldn't init INBOX: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Mailbox init failed top=0/0, retr=0/0, del=0/0, size=0 Jun 19 11:31:27 director5 dovecot: pop3-login: proxy(user at domain.gr): Login failed to 83.235.66.40:110: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3-login: Login: user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.40, mpid=14642, secured, session=<eBLjp33fUwBT660a> Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Error: Syncing INBOX failed: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Error: Couldn't init INBOX: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user at domain.gr): Mailbox init failed top=0/0, retr=0/0, del=0/0, size=0 Jun 19 11:31:27 director5 dovecot: pop3-login: proxy(user at domain.gr): Login failed to 83.235.66.40:110: Mailbox isn't a valid mbox file Jun 19 11:31:27 director5 dovecot: pop3-login: Aborted login (proxy dest auth failed): user=<user at domain.gr>, method=PLAIN, rip=83.235.173.26, lip=83.235.66.65, session=<eBLjp33fUwBT660a Our config : # 2.1.16: /opt/dovecot-2.1.16/etc/dovecot/dovecot.conf # OS: Linux 2.6.18-92.1.22.el5 x86_64 CentOS release 5.9 (Final) auth_cache_negative_ttl = 10 mins auth_cache_size = 5 M auth_cache_ttl = 10 mins auth_verbose = yes default_client_limit = 5000 default_process_limit = 500 deliver_log_format = msgid=%m: from=%f size=%p %$ dict { sqlquota = mysql:/opt/dovecot/etc/dovecot/dovecot-dict-sql.conf.ext } disable_plaintext_auth = no first_valid_uid = 20 lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes listen = * log_timestamp = "%Y-%m-%d %H:%M:%S " login_greeting = ready login_trusted_networks = 83.235.66.0/24 mail_access_groups = mail disk root mail_fsync = always mail_nfs_index = yes mail_nfs_storage = yes mail_plugins = quota managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave imapflags notify mbox_lock_timeout = 3 secs mbox_read_locks = dotlock fcntl mmap_disable = yes passdb { args = /opt/dovecot/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename flag_change append mail_log_fields = uid box msgid size quota = dict:User quota::noenforcing:proxy::sqlquota sieve = ~/.sieve sieve_dir = ~/sieve sieve_extensions = +notify +imapflags } postmaster_address = postmaster at otenet.gr quota_full_tempfail = yes service auth-worker { user = dovenull } service dict { unix_listener dict { group = mail mode = 0666 } } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } } service lmtp { client_limit = 1 inet_listener lmtp { port = 24 } } service pop3-login { inet_listener pop3 { port = 110 } inet_listener pop3s { port = 995 ssl = yes } } service quota-warning { executable = script /opt/dovecot/etc/dovecot/quota-warning.sh user = dovecot } ssl = no userdb { args = /opt/dovecot/etc/dovecot/dovecot-ldap.conf.ext driver = ldap } verbose_proctitle = yes protocol lmtp { mail_plugins = quota sieve quota } protocol lda { mail_plugins = quota sieve quota } protocol imap { imap_client_workarounds = delay-newmail tb-extra-mailbox-sep mail_max_userip_connections = 100 mail_plugins = quota imap_quota quota notify mail_log } protocol pop3 { mail_max_userip_connections = 100 mail_plugins = quota quota mail_log notify pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_fast_size_lookups = yes pop3_lock_session = yes pop3_reuse_xuidl = yes pop3_uidl_format = %08Xu%08Xv } Thank you for your time. Dimos Alevizos
Benny Pedersen
2013-Jun-20 08:23 UTC
[Dovecot] Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'
Dimos Alevizos skrev den 2013-06-19 15:00:> protocol imap { > imap_client_workarounds = delay-newmail tb-extra-mailbox-sep > mail_max_userip_connections = 100 > mail_plugins = quota imap_quota quota notify mail_log > }quota listed 2 times -- senders that put my email into body content will deliver it to my own trashcan, so if you like to get reply, dont do it
Timo Sirainen
2013-Jun-24 10:16 UTC
[Dovecot] Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'
On 19.6.2013, at 16.00, Dimos Alevizos <dalevizo at otenet.gr> wrote:> we're having some problems with our dovecot setup. > I've seen similar problems in the mailing list some years ago but alas wasn't able to find a solution. > > Our setup is as follows : > An MX farm (postfix) sends mails via LMTP to a director farm (dovecot 2.1.12) which proxies pop3/imap/lmtp traffic to a dovecot farm (dovecot 2.1.16). > All mailboxes and indexes are on NFS and all servers are Centos. > > The problem is that at times we see mailboxes (all of them are in mbox format) beginning with FFrom or FrFrom and of course dovecot says it's not a valid mbox file.This is quite an old bug, but it happens rarely enough that I haven't been able to reproduce and fix it. Actually people hadn't complained about it for a long time now, so I had assumed it had somehow gotten fixed already. With the attached debug patch it should crash instead of (completely) corrupting the mbox file. Debugging the resulting core file with gdb could be useful in figuring this out. Although I wouldn't recommend mbox format for any big installation anyway.. -------------- next part -------------- A non-text attachment was scrubbed... Name: diff Type: application/octet-stream Size: 414 bytes Desc: not available URL: <http://dovecot.org/pipermail/dovecot/attachments/20130624/9f607fe8/attachment.obj> -------------- next part --------------
Maybe Matching Threads
- Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'
- Windows 7 client trying to authenticate with windows machine name
- Windows 7 client trying to authenticate with windows machine name
- Windows 7 client trying to authenticate with windows machine name
- Windows 7 client trying to authenticate with windows machine name