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@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@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@domain.gr): started proxying to 83.235.66.40:110: user=<user@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@domain.gr): expunge: box=INBOX, uid=20670, msgid=<9f5b1a20a9428ed31a9e7e42ce4411f08d0.20130612070424@mail84.us2.rsgsv.net>, size=36526 Jun 19 11:09:24 pop01 dovecot: pop3(user@domain.gr): expunge: box=INBOX, uid=20671, msgid=<b27d72dc5a47a3235a232494c6fe8aa0@newsletter.stockout.gr>, size=4637 Jun 19 11:09:24 pop01 dovecot: pop3(user@domain.gr): expunge: box=INBOX, uid=20672, msgid=<1113670779560.1111910791405.1470.2.32032003@scheduler.constantcontact.com>, size=38655 Jun 19 11:09:24 pop01 dovecot: pop3(user@domain.gr): expunge: box=INBOX, uid=20673, msgid=<83600a274c1407c5aa4c263e2592cb54@debop.gr>, size=1181688 Jun 19 11:09:24 pop01 dovecot: pop3(user@domain.gr): expunge: box=INBOX, uid=20674, msgid=<F2A59BE7-007A-4567-9BA5-803446C3D7F8@bernier-eliades.gr>, size=61116 Jun 19 11:09:26 pop01 dovecot: pop3(user@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@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@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@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@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@domain.gr): disconnecting 83.235.173.26 (Disconnected by server): user=<user@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@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@domain.gr): started proxying to 83.235.66.40:110: user=<user@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@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@domain.gr): disconnecting 85.74.231.10 (Disconnected by server): user=<user@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@free.splio.com> -> <user@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@free.splio.com> to=<marina@bernier-eliades.gr> proto=ESMTP helo=<poc-pbcs2.splio.com> Jun 19 11:30:39 pop01 dovecot: lmtp(4099, user@domain.gr): 77O4IHlGwVEDEAAAYg/qxw: msgid=58175-bWFyaW5hQGJlcm5pZXItZWxpYWRlcy5ncg==@free.splio.com: from=residence.suddenly@gmx.com size=9610 saved mail to INBOX Jun 19 11:30:39 corvus postfix/lmtp[1350]: 02BA4AE00414: to=<user@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@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@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@domain.gr): Error: Syncing INBOX failed: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user@domain.gr): Error: Couldn't init INBOX: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user@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@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@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@domain.gr): Error: Syncing INBOX failed: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user@domain.gr): Error: Couldn't init INBOX: Mailbox isn't a valid mbox file Jun 19 11:31:27 pop01 dovecot: pop3(user@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@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@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@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