Steffen ,
Cant understand what's happening here.
Jul 26 12:25:37 popserver dovecot: pop3(kavish.karkera@example.com): Error: Couldn't open INBOX: Timeout while waiting for lock
Jul 26 12:25:37 popserver dovecot: pop3(kavish.karkera@example.com): Couldn't open INBOX top=0/0, retr=0/0, del=0/0, size=0
Jul 26 12:39:02 popserver dovecot: imap-login: Login: user=kavish.karkera@example.com, method=PLAIN, rip=1.38.25.83, lip=121.241.242.35, mpid=27197, TLS, session=<L9JM0WTiPgABJhlT>
Jul 26 12:42:12 popserver dovecot: imap(kavish.karkera@example.com): Error: Timeout (180s) while waiting for lock for transaction log file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot.index.log
Jul 26 12:42:12 popserver dovecot: imap(kavish.karkera@example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot-uidlist.lock was modified (1374822548 vs 1374822714), assuming it wasn't overridden (kept it 180 secs)
Jul 26 12:42:12 popserver dovecot: imap(kavish.karkera@example.com): Connection closed bytes=122/1222
Jul 26 12:45:53 popserver dovecot: imap(kavish.karkera@example.com): Warning: Maildir: Scanning /mail/v3store/example.com/kavish.karkera@example.com/Maildir/new took 1543 seconds (13 readdir()s, 13 rename()s to cur/, why=0x10)
Jul 26 12:49:11 popserver dovecot: imap-login: Login: user=kavish.karkera@example.com, method=PLAIN, rip=1.38.25.83, lip=121.241.242.35, mpid=26747, TLS, session=<tqCL9WTiOgABJhlT>
Jul 26 12:52:53 popserver dovecot: imap(kavish.karkera@example.com): Error: Timeout (180s) while waiting for lock for transaction log file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot.index.log
ul 26 12:52:53 popserver dovecot: imap(kavish.karkera@example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot-uidlist.lock was modified (1374823189 vs 1374823271), assuming it wasn't overridden (kept it 180 secs)
Jul 26 12:52:53 popserver dovecot: imap(kavish.karkera@example.com): Connection closed bytes=122/1341
Jul 26 12:52:58 popserver dovecot: imap(kavish.karkera@example.com): Warning: Maildir: Scanning /mail/v3store/example.com/kavish.karkera@example.com/Maildir/new took 425 seconds (14 readdir()s, 14 rename()s to cur/, why=0x10)
Jul 26 12:53:18 popserver dovecot: imap(kavish.karkera@example.com): Warning: Maildir /mail/v3store/example.com/kavish.karkera@example.com/Maildir: Synchronization took 1988 seconds (0 new msgs, 0 flag change attempts, 0 expunge attempts)
Jul 26 12:53:18 popserver dovecot: imap(kavish.karkera@example.com): Warning: Transaction log file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot.index.log was locked for 1988 seconds
Jul 26 12:53:18 popserver dovecot: imap(kavish.karkera@example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera@example.com/.INBOX/dovecot-uidlist.lock was modified (1374821406 vs 1374823373), assuming it wasn't overridden (kept it 1988 secs)
AND MAILS HAVE DOWNLOADED AGAIN.
it wouls be helpfull if you eloborate thsi logs in more detail. so we coluld resolve this ongoing issue.
We have 3 POP/IMAP Servers, running as load balancers through DNS round robin.
Dovecot version server 1 = 2.1.12 Dovecot version server 2 = 2.1.15 Dovecot version server 3 = 2.1.13
Mails and Indexes are stored over NFS and we do have these setting enabled
mail_nfs_storage = yes # Mail index files also exist in NFS. Setting this to yes requires # mmap_disable=yes and fsync_disable=no. mail_nfs_index = yes
Regards, Kavish Karkera
From: Kavish Karkera kavish.karkera@yahoo.com To: "dovecot@dovecot.org" dovecot@dovecot.org Sent: Thursday, 25 July 2013 9:18 PM Subject: Re: [Dovecot] Duplicate Mails downloding issue
Got it ...Thanks a ton Steffen. :)
Regards, Kavish Karkera
From: Steffen Kaiser skdovecot@smail.inf.fh-brs.de To: Kavish Karkera kavish.karkera@yahoo.com Cc: "dovecot@dovecot.org" dovecot@dovecot.org Sent: Thursday, 25 July 2013 8:03 PM Subject: Re: [Dovecot] Duplicate Mails downloding issue
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 25 Jul 2013, Kavish Karkera wrote:
Thanks Steffen for the valuable knowledge. Need to know futher that, how could this lead to mails to get re-downloaded. ??
Because Dovecot detects that the UID list is erroreous and therefore rebuilts it. To prevent data loss, either the complete list of messages or just the conflicting ones [the messages that had been delivered in parallel and caused the while problem] do appear as new to the clients.
From: Steffen Kaiser skdovecot@smail.inf.fh-brs.de To: Kavish Karkera kavish.karkera@yahoo.com Cc: "dovecot@dovecot.org" dovecot@dovecot.org Sent: Thursday, 25 July 2013 5:54 PM Subject: Re: [Dovecot] Duplicate Mails downloding issue
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 25 Jul 2013, Kavish Karkera wrote:
Jul 23 15:34:51 popserver dovecot: pop3(14949_kavish): Warning: Locking transaction log file /indexes//mail/v3store/example.com/14949_kavish/.INBOX/dovecot.index.log took 133 seconds
some process keeps the INBOX locked, but does not touch the file, so it looks like a stale lock.
Jul 23 15:34:51 popserver dovecot: pop3(kavish@example.com): Error: Broken file /indexes//mail/v3store/example.com/14949_kavish/.INBOX/dovecot-uidlist line 180: UIDs not ordered (10156 >= 10156)
Therefore some other process had broken the lock and had appended a message.
Jul 23 15:35:01 popserver dovecot: pop3(kavish@example.com): Error: utime(/indexes//mail/v3store/example.com/kavish/.INBOX/dovecot-uidlist.lock) failed: No such file or directory
Jul 23 15:35:11 popserver dovecot: pop3(kavish@example.com): Error: utime(/indexes//mail/v3store/example.com/kavish/.INBOX/dovecot-uidlist.lock) failed: No such file or directory
then the former process(es) finish and try to clean up, but the "some other process" already deleted the lock file.
Jul 23 15:35:21 popserver dovecot: pop3(kavish@example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish/.INBOX/dovecot-uidlist.lock was deleted (kept it 30 secs)
So you have to check your system why a process, that as locked INBOX, is stalled for more than 120min.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUfEY6F3r2wJMiz2NAQICHwf9HJG66UAHGJp1nT8Ql31n1Bk1KWb+wAhA p2nReYZVSbzZOJM84Dkw8xLu3WoHzFxFEIS+CJc7xGtaeWGrwrTik6d7LKjwI9gf HCun1rq9VzfS85sHvn1owVJxMnUrA3YcY90aQZ6SWHNwvrdmmqqIPhQdGx7xc3En N1jJ0wPEd9hbJyi+2MScZt0WxKuRR+Wpkl14gO6ZPcX95uONGzLcSTs071rAXT+c 6RWLxn2jhruk4qUIm+PGnHkwXTnKL2Dqfladj4/ybxTRn2hgNldK8w4piUwwPWIn HW/hN+sDM/hlRtyu0zHVfiFC7MES6s0JonzwDlOKAFt9dUUG4Mcr9Q== =mar+ -----END PGP SIGNATURE-----
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUfE3PV3r2wJMiz2NAQKdzAf9HY90QTSszIhaz7pMHYbQBMMU4XEiNBFU 3beZQLuZpYrw1aKr8xJB87DWcfyeULRgiEdWs6uSWgpYnmXYSBjDWV16HYW6+pY8 LTWr1tSY6AzUOxypx8GZfwQFhAmntwfFpoi/JiU8tDnEx2e1W44+V9hzDS4Kfy9i MQDDHRCOZL0cArAQ1DleXrQGnKY/Haa3clBfR72E/UdnGWzuGYxpORbHe9VUK8IP XrNUX1vV6RuS/cxg0/kLoVHk+0YAJCOk9kT2r2t9ZRSxSFHdzm8L/nTnQAgB+ZCR H9lNQxzi6UsRV8hT5mazMmIctW4BQsrJELV/5iWNoMDNxrYVH3Cqlg== =i01T -----END PGP SIGNATURE-----