[Dovecot] dovecot-uidlist: Duplicate file entry at line
Hi All, we are experiencing another strange problem after upgrading to 2.0.1 from 1.2.
Many people's client aree-retrieving mail from server due to some problem with dovecot-uidlist file. Looking at log file seem that all file content is sometime duplicated and appended to the and of same file. It look as another process was accesing and trying to modify uidlist table. Our setup has a load balance (dovecot director) and three backend server. All of them use 2.0.1. MTA is a cluster of postfix that deliver mail to load balancer by LMTP.
How can I collect some more information? or, better, solve it?
Regards
Luca
PS: Backend configuration is:
2.0.1: /etc/dovecot/dovecot.conf
OS: Linux 2.6.26-2-686-bigmem i686 Debian 5.0.5
auth_master_user_separator = * auth_verbose = yes disable_plaintext_auth = no mail_location = maildir:~/Maildir mail_plugins = $mail_plugins notify mail_log quota managesieve_notify_capability = mailto managesieve_sieve_capability = comparator-i;octet comparator-i;ascii-casemap fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date spamtest spamtestplus virustest passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid from size quota = maildir:User quota quota_warning = storage=95%% quota-warning.sh 95 %u quota_warning2 = storage=80%% quota-warning.sh 80 %u sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_global_dir = /etc/dovecot/sieve/global/ sieve_global_path = /etc/dovecot/sieve/default.sieve } protocols = imap pop3 lmtp sieve service auth { unix_listener auth-userdb { group = dovecot mode = 0600 user = dovecot } } service director { inet_listener { port = 8100 } } service lmtp { inet_listener lmtp { address = 10.194.1.31 127.0.0.1 ::1 port = 24 } } service managesieve-login { inet_listener sieve { address = 10.194.1.31 127.0.0.1 ::1 port = 4190 } process_min_avail = 0 service_count = 1 } service quota-warning { executable = script /virtual/shared/quota-warning.sh unix_listener quota-warning { user = vmail } user = dovecot } ssl_cert = </etc/ssl/certs/dovecot.pem ssl_key = </etc/ssl/private/dovecot.pem userdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } verbose_proctitle = yes protocol lmtp { mail_plugins = $mail_plugins quota sieve } protocol lda { mail_plugins = $mail_plugins quota } protocol imap { mail_plugins = $mail_plugins quota imap_quota } protocol pop3 { mail_plugins = $mail_plugins quota }
On Thu, 2010-09-02 at 19:21 +0200, Luca Palazzo wrote:
I've heard of some dovecot-uidlist problems, but haven't really figured out anything that could be wrong.. I guess there's no way you can reproduce this? Does happen to same user more than once? How many users is "many"? Does this happen only/mainly to some specific mailboxes (INBOX, Trash)? Does this happen to more than one same user's mailbox at the same time? Does this happen to different users around the same time?
Our setup has a load balance (dovecot director) and three backend server. All of them use 2.0.1.
How did you do it before v2.0?
The maildir code hasn't changed much since v1.2. Hmm. Except that maildir filenames are now tried to be preserved when copying, so copying messages elsewhere and back does sound like it could cause this (although there is code to prevent it)..
Il giorno 03/set/2010, alle ore 16.44, Timo Sirainen ha scritto:
I have the same problem, since migration to 2.0. Mainly it happens on INBOX (well, I’ve only seen this happen on INBOX), but I did not found a way to reproduce it. It happened to the same user more than once. I have 15 users. Only one mailbox a time, well, as I said before it happens only on INBOX and yes, more than one user per time.
I have no load balance, no director.
TIA Andrea Mistrali
On Fri, 2010-09-03 at 16:51 +0200, Andre wrote:
Any idea if those users copy messages around? Or undelete from Trash?
Only one mailbox a time, well, as I said before it happens only on INBOX and yes, more than one user per time.
I mean does it happen to multiple users "at once", like within same second (or close to it)?
Hi Timo, I tried the patch and duplicate uid are always there.
Look at this: Sep 6 10:51:30 10.97.1.33 dovecot: lmtp(29909, xxxxxx@unict.it): save: box=INBOX, uid=133197, msgid=<20100906104944.Q92185@>, size=7414, from= Sep 6 10:51:30 10.97.1.33 dovecot: lmtp(29909, xxxxxx@unict.it): T8gcJIyphEzVdAAA27qniQ: msgid=<20100906104944.Q92185@pongo.fi.infn.it>: saved mail to INBOX Sep 6 10:51:31 10.97.1.33 dovecot: imap(xxxxxx@unict.it): Warning: /virtual1/unict.it/g/xxxxxx//Maildir/dovecot-uidlist: Duplicate file entry at line 883: 1277948239.M332097P873 3.mailcl-mbox1,S=7903,W=8024:2,S (uid 132318 -> 133198) Sep 6 10:51:31 10.97.1.33 dovecot: imap(xxxxxx@unict.it): Warning: /virtual1/unict.it/g/xxxxxx//Maildir/dovecot-uidlist: Duplicate file entry at line 884: 1277952980.M167558P112 43.mailcl-mbox1,S=11228,W=11393:2,S (uid 132319 -> 133199) Sep 6 10:51:31 10.97.1.33 dovecot: imap(xxxxxx@unict.it): Warning: /virtual1/unict.it/g/xxxxxx//Maildir/dovecot-uidlist: Duplicate file entry at line 885: 1277966013.M655255P280 93.mailcl-mbox1,S=23709,W=24249:2,S (uid 132320 -> 133200) Sep 6 10:51:31 10.97.1.33 dovecot: imap(xxxxxx@unict.it): Warning: /virtual1/unict.it/g/xxxxxx//Maildir/dovecot-uidlist: Duplicate file entry at line 886: 1277969233.M852614P116 56.mailcl-mbox1,S=4496,W=4604:2,S (uid 132321 -> 133201) Sep 6 10:51:31 10.97.1.33 dovecot: imap(xxxxxx@unict.it): Warning: /virtual1/unict.it/g/xxxxxx//Maildir/dovecot-uidlist: Duplicate file entry at line 887: 1277970140.M285747P169 43.mailcl-mbox1,S=7601,W=7845:2,RS (uid 132322 -> 133202)
It seems that LMTP process duplicate UID or something related to it. But, duplicate occurs sometime during LMTP delivery and sometime after LMTP delivery with IMAP or POP3.
I hope this helps.
Luca On 09/03/2010 04:59 PM, Timo Sirainen wrote:
On Mon, 2010-09-06 at 11:11 +0200, Luca Palazzo wrote:
Hmmh. See if http://hg.dovecot.org/dovecot-2.0/rev/e2a267b64619 changes the behavior?
Hi Timo and All, please take care of this trace. It seems that dovecot.uidlist's increase its size (8056 from stat and from read and then 14641 with stat) while delivering and then it tries to look for duplicates.
I hope this helps, duplicates problem is becoming big. Can I check or trace something else?
Luca
open("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist", O_RDWR|O_LARGEFILE) = 17 _llseek(17, 0, [0], SEEK_SET) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 pread64(17, "3 V1264536006 N2107 Gc56f442c6771"..., 4096, 0) = 4096 pread64(17, "8340P4605.mailcl-mbox1,S=19935,W="..., 4076, 4096) = 3960 pread64(17, ""..., 116, 8056) = 0 time(NULL) = 1283846418 umask(0133) = 077 time(NULL) = 1283846418 lstat64("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist.lock", 0xbfd07bcc) = -1 ENOENT (No such file or directory) umask(0666) = 0133 lstat64("/virtual1/unict.it/a/account//Maildir/temp.mailcl-mbox2.31697.74d7957105ba8895", 0xbfd07bc4) = -1 ENOENT (No such file or directory) umask(0133) = 0666 open("/virtual1/unict.it/a/account//Maildir/temp.mailcl-mbox2.31697.74d7957105ba8895", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) = 20 umask(0666) = 0133 umask(0133) = 0666 write(20, "31697:mailcl-mbox2"..., 18) = 18 link("/virtual1/unict.it/a/account//Maildir/temp.mailcl-mbox2.31697.74d7957105ba8895", "/virtual1/unict.it/a/account//Maildir/dovecot-uidlist.lock") = 0 unlink("/virtual1/unict.it/a/account//Maildir/temp.mailcl-mbox2.31697.74d7957105ba8895") = 0 fstat64(20, {st_mode=S_IFREG|0644, st_size=18, ...}) = 0 close(20) = 0 lstat64("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist.lock", {st_mode=S_IFREG|0644, st_size=18, ...}) = 0 umask(077) = 0133 stat64("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist", {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 _llseek(17, 0, [0], SEEK_SET) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 pread64(17, ""..., 4096, 8056) = 0 alarm(180) = 0 fcntl64(15, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}, 0xbfd07c64) = 0 alarm(0) = 180 stat64("/virtual1/unict.it/a/account//Maildir/dovecot.index.log", {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0 fstat64(15, {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0 open("/virtual1/unict.it/a/account//Maildir/new", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 20 fstat64(20, {st_mode=S_IFDIR|0700, st_size=1848, ...}) = 0 fstat64(20, {st_mode=S_IFDIR|0700, st_size=1848, ...}) = 0 time(NULL) = 1283846418 getdents64(20, /* 3 entries */, 4096) = 120 getdents64(20, /* 0 entries */, 4096) = 0 close(20) = 0 open("/virtual1/unict.it/a/account//Maildir/cur", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 20 fstat64(20, {st_mode=S_IFDIR|0700, st_size=10240, ...}) = 0 fstat64(20, {st_mode=S_IFDIR|0700, st_size=10240, ...}) = 0 time(NULL) = 1283846418 getdents64(20, /* 29 entries */, 4096) = 2200 getdents64(20, /* 27 entries */, 4096) = 2160 getdents64(20, /* 24 entries */, 4096) = 1912 getdents64(20, /* 21 entries */, 4096) = 1680 getdents64(20, /* 6 entries */, 4096) = 480 getdents64(20, /* 0 entries */, 4096) = 0 close(20) = 0 _llseek(17, 0, [8056], SEEK_END) = 0 _llseek(17, 0, [8056], SEEK_CUR) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=8056, ...}) = 0 write(17, "2145 :1268504260.V811I106f6056M46"..., 6585) = 6585 fdatasync(17) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 time(NULL) = 1283846418 stat64("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist", {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 _llseek(17, 0, [0], SEEK_SET) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 pread64(17, ""..., 4096, 14641) = 0 stat64("/virtual1/unict.it/a/account//Maildir/dovecot-uidlist", {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 _llseek(17, 0, [0], SEEK_SET) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 fstat64(17, {st_mode=S_IFREG|0644, st_size=14641, ...}) = 0 pread64(17, ""..., 4096, 14641) = 0
On 09/06/2010 04:42 PM, Timo Sirainen wrote:
OK, I can reproduce this. It happens only with LMTP, because only then it can do a mailbox sync around the time of mail delivery. It probably also only happens when LMTP delivers the same mail to multiple recipients.
Now I'll just need to figure out how to fix this properly.. The maildir uidlist code is getting pretty ugly.
On Tue, 2010-09-07 at 15:59 +0100, Timo Sirainen wrote:
http://hg.dovecot.org/dovecot-2.0/rev/65b0e7b4eda9 should fix it. Although looks like it's still doing unnecessary extra work.
On Tue, 2010-09-07 at 16:24 +0100, Timo Sirainen wrote:
And http://hg.dovecot.org/dovecot-2.0/rev/c7e1c71c5ec5 fixes the extra work.
Yeah, the patches fix the mail delivery stage. These duplicate errors happen during the next imap/pop3 login. So either wait for a while and in the meanwhile maybe check that the same mailbox won't get the error more than once.
On Tue, 2010-09-07 at 18:36 +0200, Luca Palazzo wrote:
Timo, please also check this output of lmtp process:
stat64("/virtual1/unict.it/d/yyyyyyyy//Maildir/dovecot-uidlist", {st_mode=S_IFREG|0644, st_size=44628, ...}) = 0 _llseek(42, 0, [0], SEEK_SET) = 0 fstat64(42, {st_mode=S_IFREG|0644, st_size=44628, ...}) = 0 fstat64(42, {st_mode=S_IFREG|0644, st_size=44628, ...}) = 0 pread64(42, ""..., 4096, 44628) = 0
the same block is repeatead as time as entries in uidlist file.
Luca
On 09/03/2010 04:59 PM, Timo Sirainen wrote:
participants (4)
-
Andre
-
Andrea Mistrali
-
Luca Palazzo
-
Timo Sirainen