Hi! On Thu, Jan 19, 2012 at 12:54:26PM +0100, Bron Gondwana wrote: > Yeah - ok. So the DELETED item is still in the mailboxes.db, but the files on > disk have been deleted. Can you send your imapd.conf(s) - and any syslog from > the time that the folders got deleted? > > I wonder if cyr_expire is running with the wrong configuration, so it's not > talking to the mupdate server when it removes folders? Apparently, I was just plain wrong about the root cause of the problem; cyr_expire has nothing at all to do with this. What actually happened was that the user deleted the folder, and then, the new folder in the DELETED hierarchy also got immediately deleted: --clip-- [root@pcn2 ~]# grep Deleted.mailbox.*Matkat.2012\\.06-20\\. /var/log/maillog Jan 19 10:36:19 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06-20.Untitled Folder Jan 19 10:36:19 pcn2 i16/imap[2747]: Deleted mailbox DELETED.user.<censored>.BIOMEDICUM.Matkat 2012.06-20.Untitled Folder.4F17D602 --clip-- (but not completely, since there was the trace of it left on the murder backend). There was another, similar case earlier today: --clip-- [jmmpelto@pcn3 ~]$ sudo grep Deleted.mailbox.*<censored2> /var/log/maillog Jan 19 09:21:13 pcn3 i09/imap[4661]: Deleted mailbox DELETED.user.<censored2>.Trash.junk.4F17C45B Jan 19 09:21:13 pcn3 i09/imap[23285]: Deleted mailbox user.<censored2>.Trash.junk --clip-- but in this case, the old folder in the DELETED hierarchy got deleted first, and only then the folder in the normal user hierarchy. And the new folder in the DELETED hierarchy, created by the deletion of the folder in the user hierarchy, got created okay: --clip-- admin.mappi.helsinki.fi> lm DELETED.user.<censored2>.Trash.junk.* DELETED.user.<censored2>.Trash.junk.4F17C465 (\HasNoChildren) --clip-- Notice the different stamp in the end of the folder name, 4F17C465 vs. 4F17C45B - are these timestamps? If so, it appears that for some reason, the folder in the DELETED hierarchy got first created, then deleted, then almost immediately re-created. In the case of the other folder, the re-creation didn't happen. But even in this second case, where the folder did get created again, the ghost of the first DELETED folder (stamped 4F17C45B) was in the mailbox list of the murder backend, causing trouble for replication. What appears to be doing these deletions, looking at the syslog entries, is imapd. And a completely different imapd from the one that deletes the original folders, for that matter. Um. Apparently, what seems to be happening is, an email client is connected here more than once, and the deletion happens simultaneously from two connections at a time o.O Like, first one imapd tries to delete the original folder in the user hierarchy; then another imapd tries to delete it again, while the deletion is in progress; the original imapd can't push the new mailbox in DELETED hierarchy into mupdate master, and deletes it; then the second imapd either succeeds in deleting the folder in the user hierarchy (and creating a new folder in the DELETED hierarchy) or doesn't succeed. Or something similar. Like so: --clip-- [jmmpelto@pcn3 ~]$ sudo egrep 'Jan.19.09.(19|2).*imap.(23285|4661)' /var/log/maillog Jan 19 09:19:57 pcn3 i09/imap[23285]: login: pcn7.mappi.helsinki.fi [128.214.20.213] <censored2> DIGEST-MD5 User logged in Jan 19 09:20:47 pcn3 i09/imap[4661]: login: pcn7.mappi.helsinki.fi [128.214.20.213] <censored2> DIGEST-MD5 User logged in Jan 19 09:21:13 pcn3 i09/imap[4661]: MUPDATE: can't commit mailbox entry for 'DELETED.user.<censored2>.Trash.junk.4F17C45B' Jan 19 09:21:13 pcn3 i09/imap[4661]: Deleted mailbox DELETED.user.<censored2>.Trash.junk.4F17C45B Jan 19 09:21:13 pcn3 i09/imap[23285]: Deleted mailbox user.<censored2>.Trash.junk Jan 19 09:21:13 pcn3 i09/imap[4661]: Remove of supposedly empty directory /var/spool/imap/i09-b/u/DELETED/user/<censored2>/Trash/junk failed: Directory not empty Jan 19 09:21:13 pcn3 i09/imap[4661]: Remove of supposedly empty directory /var/spool/imap/i09-b/u/DELETED/user/<censored2>/Trash failed: Directory not empty Jan 19 09:21:13 pcn3 i09/imap[4661]: Remove of supposedly empty directory /var/spool/imap/i09-b/u/DELETED/user/<censored2> failed: Directory not empty Jan 19 09:21:13 pcn3 i09/imap[4661]: Remove of supposedly empty directory /var/spool/imap/i09-b/u/DELETED/user failed: Directory not empty Jan 19 09:21:13 pcn3 i09/imap[4661]: Remove of supposedly empty directory /var/spool/imap/i09-b/u/DELETED failed: Directory not empty Jan 19 09:25:59 pcn3 i09/imap[4661]: USAGE <censored2> user: 0.039994 sys: 0.110983 --clip-- (and after this, we have the user.<censored2>.Trash.junk existing as DELETED.user.<censored2>.Trash.junk.4F17C465) or so: --clip-- [jmmpelto@pcn2 ~]$ sudo egrep 'Jan.19.10.[1-3].*imap.(4270|2747)[]]' /var/log/maillog Jan 19 10:16:27 pcn2 i16/imap[2747]: login: pcn7.mappi.helsinki.fi [128.214.20.213] <censored> DIGEST-MD5 User logged in Jan 19 10:16:53 pcn2 i16/imap[2747]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:17:17 pcn2 i16/imap[2747]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:17:25 pcn2 i16/imap[2747]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.AACR 03- Jan 19 10:18:49 pcn2 i16/imap[4270]: login: pcn7.mappi.helsinki.fi [128.214.20.213] <censored> DIGEST-MD5 User logged in Jan 19 10:21:25 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:22:32 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:25:45 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.USA 01-2012 Jan 19 10:26:03 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.AACR 03-2012 Jan 19 10:26:15 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.03-2012 AAC Jan 19 10:26:47 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.03-2012 Le Jan 19 10:26:54 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.07-2012 Belf Jan 19 10:27:24 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.07-2012 Bel Jan 19 10:29:30 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:32:28 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:32:36 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.09-2012 Klos Jan 19 10:34:26 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:36:12 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder Jan 19 10:36:12 pcn2 i16/imap[4270]: Remove of supposedly empty directory /var/spool/imap/nkpd/p/user/<censored>/BIOMEDICUM/Matkat 2012/Untitled Folder failed: Directory not empty Jan 19 10:36:12 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.Untitled Folder.Untitled Folder Jan 19 10:36:17 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06- Jan 19 10:36:17 pcn2 i16/imap[4270]: Remove of supposedly empty directory /var/spool/imap/nkpd/p/user/<censored>/BIOMEDICUM/Matkat 2012/06- failed: Directory not empty Jan 19 10:36:17 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06-.Untitled Folder Jan 19 10:36:18 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06-20 Jan 19 10:36:18 pcn2 i16/imap[4270]: Remove of supposedly empty directory /var/spool/imap/nkpd/p/user/<censored>/BIOMEDICUM/Matkat 2012/06-20 failed: Directory not empty Jan 19 10:36:19 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06-20.Untitled Folder Jan 19 10:36:19 pcn2 i16/imap[2747]: MUPDATE: can't commit mailbox entry for 'DELETED.user.<censored>.BIOMEDICUM.Matkat 2012.06-20.Untitled Folder.4F17D602' Jan 19 10:36:19 pcn2 i16/imap[2747]: Deleted mailbox DELETED.user.<censored>.BIOMEDICUM.Matkat 2012.06-20.Untitled Folder.4F17D602 Jan 19 10:36:19 pcn2 i16/imap[2747]: Remove of supposedly empty directory /var/spool/imap/nkpd/u/DELETED/user/<censored> failed: Directory not empty Jan 19 10:36:19 pcn2 i16/imap[2747]: Remove of supposedly empty directory /var/spool/imap/nkpd/u/DELETED/user failed: Directory not empty Jan 19 10:36:19 pcn2 i16/imap[2747]: Remove of supposedly empty directory /var/spool/imap/nkpd/u/DELETED failed: Directory not empty Jan 19 10:36:19 pcn2 i16/imap[2747]: USAGE <censored> user: 0.198970 sys: 0.226966 Jan 19 10:36:40 pcn2 i16/imap[4270]: Deleted mailbox user.<censored>.BIOMEDICUM.Matkat 2012.06-2012 ESHG.Untitled Folder --clip-- ...now, in this case, the imapd process that logged the deletion of the problematic folder was 4270, but the process that complained about being unable to committing a new mailbox entry /and logged deleting the new folder in DELETED hierarchy/ was process 2747, which hadn't logged any intention about deleting the original folder o.O This was the case in which there wasn't any new folder created in the DELETED hierarchy. Also, the original folder doesn't seem to exist any longer in any mailbox list (mupdate master or backend). However, it does appear to be on the disk of the backend, in the user hierarchy (in essence, not moved anywhere). Could there be a mailbox locking issue here or something? --Janne -- Janne Peltonen <janne.peltonen@xxxxxxxxxxx> PGP Key ID: 0x9CFAC88B Please consider membership of the Hospitality Club (http://www.hospitalityclub.org) ---- Cyrus Home Page: http://www.cyrusimap.org/ List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
