dovecot - Apr 2011 - [LDA] save failed to INBOX: Timeout while waiting for lock

Hello

I use LDA Dovecot 2 with SIEVE as Postfix delivery agent and I
occasionally get such message in syslog.

info.log:Apr 13 12:39:40 lda(xxxxxxxx): Info:
msgid=<4DA484FF.5060903 at gmail.com>: save failed to INBOX: Timeout while
waiting for lock

See below the doveconf -n trace

Thanks for any info
> # 2.0.11: /usr/local/etc/dovecot/dovecot.conf
> # OS: FreeBSD 8.2-RELEASE amd64  
> auth_worker_max_count = 100
> debug_log_path = /var/log/dovecot/debug.log
> default_client_limit = 6144
> default_process_limit = 1024
> disable_plaintext_auth = no
> info_log_path = /var/log/dovecot/info.log
> log_path = /var/log/dovecot/dovecot.log
> mail_location =
mbox:%h/:INDEX=/var/cache/dovecot/index/%u:INBOX=/var/mail/%u
> 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
> mbox_write_locks = fcntl
> passdb {
>   driver = passwd
> }
> plugin/sieve = ~/.dovecot.sieve
> plugin/sieve_dir = ~/sieve
> postmaster_address = postmaster at esiee.fr
> protocols = imap pop3 sieve sieve
> sendmail_path = /usr/local/sbin/sendmail
> service auth {
>   client_limit = 7169
> }
> service imap-login {
>   inet_listener imap {
>     port = 143
>   }
>   inet_listener imaps {
>     port = 993
>     ssl = yes
>   }
>   process_min_avail = 10
>   service_count = 1
>   vsz_limit = 1 G
> }
> service imap {
>   process_limit = 2048
>   vsz_limit = 1 G
> }
> service managesieve-login {
>   inet_listener sieve {
>     port = 4190
>   }
>   inet_listener sieve_deprecated {
>     port = 2000
>   }
> }
> service pop3-login {
>   inet_listener pop3 {
>     port = 110
>   }
>   inet_listener pop3s {
>     port = 995
>     ssl = yes
>   }
> }
> ssl_ca = /etc/ssl/RENATER/chain-1828-mail.esiee.fr.pem
> ssl_cert = </etc/ssl/RENATER/cert-1828-mail.esiee.fr.pem
> ssl_key = </etc/ssl/RENATER/mail.esiee.fr.key
> userdb {
>   driver = passwd
> }
> verbose_proctitle = yes
> protocol lda {
>   info_log_path = /var/log/dovecot/dovecot-lda.log
>   log_path = /var/log/dovecot/dovecot-lda-errors.log
>   mail_plugins = " sieve"
> }
> protocol imap {
>   imap_client_workarounds = tb-extra-mailbox-sep
> }
> protocol sieve {
>   managesieve_implementation_string = Dovecot Pigeonhole
> }
> mail# dovecof -n > /tmp/doveconf.txt
> dovecof: Command not found.
> mail# doveconf -n > /tmp/doveconf.txt
> mail# wc -l /tmp/doveconf.txt
>       75 /tmp/doveconf.txt
> mail# cat /tmp/doveconf.txt 
> # 2.0.11: /usr/local/etc/dovecot/dovecot.conf
> # OS: FreeBSD 8.2-RELEASE amd64  
> auth_worker_max_count = 100
> debug_log_path = /var/log/dovecot/debug.log
> default_client_limit = 6144
> default_process_limit = 1024
> disable_plaintext_auth = no
> info_log_path = /var/log/dovecot/info.log
> log_path = /var/log/dovecot/dovecot.log
> mail_location =
mbox:%h/:INDEX=/var/cache/dovecot/index/%u:INBOX=/var/mail/%u
> 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
> mbox_write_locks = fcntl
> passdb {
>   driver = passwd
> }
> plugin/sieve = ~/.dovecot.sieve
> plugin/sieve_dir = ~/sieve
> postmaster_address = postmaster at esiee.fr
> protocols = imap pop3 sieve sieve
> sendmail_path = /usr/local/sbin/sendmail
> service auth {
>   client_limit = 7169
> }
> service imap-login {
>   inet_listener imap {
>     port = 143
>   }
>   inet_listener imaps {
>     port = 993
>     ssl = yes
>   }
>   process_min_avail = 10
>   service_count = 1
>   vsz_limit = 1 G
> }
> service imap {
>   process_limit = 2048
>   vsz_limit = 1 G
> }
> service managesieve-login {
>   inet_listener sieve {
>     port = 4190
>   }
>   inet_listener sieve_deprecated {
>     port = 2000
>   }
> }
> service pop3-login {
>   inet_listener pop3 {
>     port = 110
>   }
>   inet_listener pop3s {
>     port = 995
>     ssl = yes
>   }
> }
> ssl_ca = /etc/ssl/x.pem
> ssl_cert = </etc/ssl/y.pem
> ssl_key = </etc/ssl/x.key
> userdb {
>   driver = passwd
> }
> verbose_proctitle = yes
> protocol lda {
>   info_log_path = /var/log/dovecot/dovecot-lda.log
>   log_path = /var/log/dovecot/dovecot-lda-errors.log
>   mail_plugins = " sieve"
> }
> protocol imap {
>   imap_client_workarounds = tb-extra-mailbox-sep
> }
> protocol sieve {
>   managesieve_implementation_string = Dovecot Pigeonhole
> }

On 14.4.2011, at 10.47, Frank Bonnet wrote:
> I use LDA Dovecot 2 with SIEVE as Postfix delivery agent and I
> occasionally get such message in syslog.
> 
> info.log:Apr 13 12:39:40 lda(xxxxxxxx): Info:
> msgid=<4DA484FF.5060903 at gmail.com>: save failed to INBOX: Timeout
while
> waiting for lock
..
>> mail_location =
mbox:%h/:INDEX=/var/cache/dovecot/index/%u:INBOX=/var/mail/%u
That's the way mbox format works. One IMAP or POP3 client can lock the
mailbox for a long time. LDA can either wait longer of fail and let MTA retry
the delivery later. The default is:

mbox_lock_timeout = 5 mins

So apparently the LDA already waited for 5 minutes for the lock.

(There is also actually mail_max_lock_timeout setting, but the default is 0 =
disabled.)

On Thu, 2011-04-14 at 10:18 +0200, Frank Bonnet wrote:
> >>> mail_location =
mbox:%h/:INDEX=/var/cache/dovecot/index/%u:INBOX=/var/mail/%u
> > 
> > That's the way mbox format works. One IMAP or POP3 client can lock
the mailbox for a long time. LDA can either wait longer of fail and let MTA
retry the delivery later. The default is:
> > 
> > mbox_lock_timeout = 5 mins
> > 
> > So apparently the LDA already waited for 5 minutes for the lock.
> > 
> > (There is also actually mail_max_lock_timeout setting, but the default
is 0 = disabled.)
> >  
> 
> Should I do something to correct ?
I don't really know if there is anything except switching away from
mbox.
> When the problem occured some users were unable to access their mailboxes
How long does it occur? You'd need to find out what exactly is locking
those mailboxes for that long. It could simply be the user's client. Or
I guess it could be LDA itself, or anything really.. Difficult to say.
Difficult also to tell easy way to debug this..

Or when this happens does it happen to many people at the same time? Is
the system load really high at that time then?