[Dovecot] Duplicate Mails downloding issue

Fri Jul 26 15:28:38 EEST 2013

Steffen , 

Cant understand what's happening here.

-------------------------------------------------------------------------------------------------------------------------------------------------------
Jul 26 12:25:37 popserver dovecot: pop3(kavish.karkera at example.com): Error: Couldn't open INBOX: Timeout while waiting for lock

Jul 26 12:25:37 popserver dovecot: pop3(kavish.karkera at 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 at 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 at example.com): Error: Timeout (180s) while waiting for lock for transaction log file /indexes//mail/v3store/example.com/kavish.karkera at example.com/.INBOX/dovecot.index.log

Jul 26 12:42:12 popserver dovecot: imap(kavish.karkera at example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera at 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 at example.com): Connection closed bytes=122/1222

Jul 26 12:45:53 popserver dovecot: imap(kavish.karkera at example.com): Warning: Maildir: Scanning /mail/v3store/example.com/kavish.karkera at 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 at 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 at example.com): Error: Timeout (180s) while waiting for lock for transaction log file /indexes//mail/v3store/example.com/kavish.karkera at example.com/.INBOX/dovecot.index.log

ul 26 12:52:53 popserver dovecot: imap(kavish.karkera at example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera at 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 at example.com): Connection closed bytes=122/1341

Jul 26 12:52:58 popserver dovecot: imap(kavish.karkera at example.com): Warning: Maildir: Scanning /mail/v3store/example.com/kavish.karkera at 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 at example.com): Warning: Maildir /mail/v3store/example.com/kavish.karkera at 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 at example.com): Warning: Transaction log file /indexes//mail/v3store/example.com/kavish.karkera at example.com/.INBOX/dovecot.index.log was locked for 1988 seconds

Jul 26 12:53:18 popserver dovecot: imap(kavish.karkera at example.com): Warning: Our dotlock file /indexes//mail/v3store/example.com/kavish.karkera at 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 at yahoo.com>
To: "dovecot at dovecot.org" <dovecot at 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 at smail.inf.fh-brs.de>
To: Kavish Karkera <kavish.karkera at yahoo.com> 
Cc: "dovecot at dovecot.org" <dovecot at 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 at smail.inf.fh-brs.de>
> To: Kavish Karkera <kavish.karkera at yahoo.com>
> Cc: "dovecot at dovecot.org" <dovecot at 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 at 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 at 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 at 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 at 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-----