dovecot - Jul 2012 - Timeout (180s) while waiting for lock for transaction log file

Hello,

	We still have problems with our updated dovecot servers... The problem 
now is that we are having errors like:

Jul  9 10:22:02 myotis31 dovecot: lmtp(15431, <user>): Error: Timeout 
(180s) while waiting for lock for transaction log file 
/var/indexes/<user>/.INBOX/dovecot.index.log
Jul  9 10:22:02 myotis31 dovecot: lmtp(15431, <user>): Error: 
+4YfCwKS+k9HPAAAmo+UlA: sieve: msgid=<4FFA8700.2080003 at um.es>: failed
to
store into mailbox 'INBOX': Internal error occurred. Refer to server log
for more information. [2012-07-09 10:19:02]
Jul  9 10:22:02 myotis31 dovecot: lmtp(15431, <user>): Error: 
+4YfCwKS+k9HPAAAmo+UlA: sieve: script /home/pdi/88/185188/.dovecot.sieve 
failed with unsuccessful implicit keep (user logfile 
/home/pdi/88/185188/.dovecot.sieve.log may reveal additional details)

	in the .dovecot.sieve.log all we have is just:

sieve: info: started log at Jul 09 10:22:02.
error: msgid=<4FFA8700.2080003 at um.es>: failed to store into mailbox 
'INBOX': Internal error occurred. Refer to server log for more 
information. [2012-07-09 10:19:02].

	maildir are in a nfs storage, but indexes are in local disk. I don't 
know if the problem could be related with a some "specific" messages
or
something specific to the user, because we are having this problem only 
with a few users and the problem repeatedly happens when our mta tries 
to deliver the queued message.

	Any idea?

-- 
Angel L. Mateo Mart?nez
Secci?n de Telem?tica
?rea de Tecnolog?as de la Informaci?n
y las Comunicaciones Aplicadas (ATICA)
http://www.um.es/atica
Tfo: 868887590
Fax: 868888337

-------------- next part --------------
# 2.1.5: /etc/dovecot/dovecot.conf
# OS: Linux 3.2.0-24-generic x86_64 Ubuntu 12.04 LTS 
auth_cache_size = 20 M
auth_cache_ttl = 1 days
auth_debug = yes
auth_master_user_separator = *
auth_verbose = yes
default_process_limit = 1000
disable_plaintext_auth = no
log_timestamp = %Y-%m-%d %H:%M:%S
login_trusted_networks = 155.54.211.176/28
mail_debug = yes
mail_location = maildir:~/Maildir:INDEX=/var/indexes/%n
mail_privileged_group = mail
mdbox_rotate_size = 20 M
passdb {
  args = /etc/dovecot/master-users
  driver = passwd-file
  master = yes
  pass = yes
}
passdb {
  args = /etc/dovecot/dovecot-ldap.conf.ext
  driver = ldap
}
passdb {
  args = session=yes dovecot
  driver = pam
}
plugin {
  lazy_expunge = .EXPUNGED/ .DELETED/ .DELETED/.EXPUNGED/
  sieve = ~/.dovecot.sieve
  sieve_dir = ~/sieve
  sieve_extensions = +imapflags
  sieve_max_redirects = 15
  zlib_save = gz
  zlib_save_level = 6
}
postmaster_address = postmaster at um.es
service anvil {
  client_limit = 2003
}
service auth {
  client_limit = 3000
  unix_listener auth-userdb {
    mode = 0666
  }
}
service doveadm {
  inet_listener {
    port = 24245
  }
}
service imap {
  process_limit = 5120
  process_min_avail = 6
  vsz_limit = 512 M
}
service lmtp {
  inet_listener lmtp {
    port = 24
  }
  process_min_avail = 10
  vsz_limit = 512 M
}
service pop3 {
  process_min_avail = 6
}
ssl = no
ssl_cert = </etc/ssl/certs/dovecot.pem
ssl_key = </etc/ssl/private/dovecot.pem
userdb {
  driver = prefetch
}
userdb {
  args = /etc/dovecot/dovecot-ldap.conf.ext
  driver = ldap
}
protocol lda {
  mail_plugins = " sieve"
}
protocol lmtp {
  mail_plugins = " sieve"
}
protocol pop3 {
  pop3_logout_format = top=%t/%p, retr=%r/%b, del=%d/%m, size=%s, in=%i, out=%o
}
local 155.54.211.160/27/27 {
  doveadm_password = <password>
}

On Mon, 2012-07-09 at 10:45 +0200, Angel L. Mateo wrote:
> 	We still have problems with our updated dovecot servers... The problem 
> now is that we are having errors like:
> 
> Jul  9 10:22:02 myotis31 dovecot: lmtp(15431, <user>): Error: Timeout
> (180s) while waiting for lock for transaction log file 
> /var/indexes/<user>/.INBOX/dovecot.index.log
..
> 	maildir are in a nfs storage, but indexes are in local disk. I don't 
> know if the problem could be related with a some "specific"
messages or
> something specific to the user, because we are having this problem only 
> with a few users and the problem repeatedly happens when our mta tries 
> to deliver the queued message.
If you can somewhat easily reproduce this for specific users, maybe you
could strace -tt the lmtp process doing the delivery to see what is
happening? Also, if the .log file is really locked for longer than
180secs, you should see a warning:

Transaction log file %s was locked for %u seconds

You could maybe also decrease the threshold for that warning:

diff -r 56ef4e70b1a9 src/lib-index/mail-transaction-log-file.c
--- a/src/lib-index/mail-transaction-log-file.c Tue Jul 17 15:44:36 2012 +0300
+++ b/src/lib-index/mail-transaction-log-file.c Tue Jul 17 16:09:28 2012 +0300
@@ -386,7 +386,7 @@
                return;
 
        lock_time = time(NULL) - file->lock_created;
-       if (lock_time >= MAIL_TRANSCATION_LOG_LOCK_TIMEOUT) {
+       if (lock_time >= 30) {
                i_warning("Transaction log file %s was locked for %u
seconds",
                          file->filepath, lock_time);
        }