[Dovecot] Mbox corruption - Inbox beginning with 'FFrom' or 'FrFrom'

Dimos Alevizos dalevizo at otenet.gr
Wed Jun 19 16:00:43 EEST 2013 

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

More information about the dovecot mailing list