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 u...@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=<u...@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(u...@domain.gr):
started proxying to 83.235.66.40:110: user=<u...@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(u...@domain.gr): expunge: box=INBOX,
uid=20670,
msgid=<9f5b1a20a9428ed31a9e7e42ce4411f08d0.20130612070...@mail84.us2.rsgsv.net>,
size=36526
Jun 19 11:09:24 pop01 dovecot: pop3(u...@domain.gr): expunge: box=INBOX,
uid=20671,
msgid=<b27d72dc5a47a3235a232494c6fe8...@newsletter.stockout.gr>, size=4637
Jun 19 11:09:24 pop01 dovecot: pop3(u...@domain.gr): expunge: box=INBOX,
uid=20672,
msgid=<1113670779560.1111910791405.1470.2.32032...@scheduler.constantcontact.com>,
size=38655
Jun 19 11:09:24 pop01 dovecot: pop3(u...@domain.gr): expunge: box=INBOX,
uid=20673, msgid=<83600a274c1407c5aa4c263e2592c...@debop.gr>, size=1181688
Jun 19 11:09:24 pop01 dovecot: pop3(u...@domain.gr): expunge: box=INBOX,
uid=20674,
msgid=<f2a59be7-007a-4567-9ba5-803446c3d...@bernier-eliades.gr>, size=61116
Jun 19 11:09:26 pop01 dovecot: pop3(u...@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(u...@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(u...@domain.gr): Disconnected:
Logged out top=0/0, retr=2/1502843, del=122/359, size=137448432
Jun 19 11:09:27 pop01 dovecot: pop3(u...@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(u...@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(u...@domain.gr):
disconnecting 83.235.173.26 (Disconnected by server):
user=<u...@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=<u...@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(u...@domain.gr):
started proxying to 83.235.66.40:110: user=<u...@domain.gr>,
method=PLAIN, rip=85.74.231.10, lip=83.235.66.63, session=<QDLrYH3f7ABVSucK>
Jun 19 11:11:51 pop01 dovecot: pop3(u...@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(u...@domain.gr):
disconnecting 85.74.231.10 (Disconnected by server):
user=<u...@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-14...@free.splio.com> ->
<u...@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-14...@free.splio.com>
to=<mar...@bernier-eliades.gr> proto=ESMTP helo=<poc-pbcs2.splio.com>
Jun 19 11:30:39 pop01 dovecot: lmtp(4099, u...@domain.gr):
77O4IHlGwVEDEAAAYg/qxw:
msgid=58175-bWFyaW5hQGJlcm5pZXItZWxpYWRlcy5ncg==@free.splio.com:
from=residence.sudde...@gmx.com size=9610 saved mail to INBOX
Jun 19 11:30:39 corvus postfix/lmtp[1350]: 02BA4AE00414:
to=<u...@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
<u...@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=<u...@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(u...@domain.gr): Error: Syncing
INBOX failed: Mailbox isn't a valid mbox file
Jun 19 11:31:27 pop01 dovecot: pop3(u...@domain.gr): Error: Couldn't
init INBOX: Mailbox isn't a valid mbox file
Jun 19 11:31:27 pop01 dovecot: pop3(u...@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(u...@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=<u...@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(u...@domain.gr): Error: Syncing
INBOX failed: Mailbox isn't a valid mbox file
Jun 19 11:31:27 pop01 dovecot: pop3(u...@domain.gr): Error: Couldn't
init INBOX: Mailbox isn't a valid mbox file
Jun 19 11:31:27 pop01 dovecot: pop3(u...@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(u...@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=<u...@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 = postmas...@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
