Replication and deleted & really removed folders in Cyrus 2.4.12

[Janne Peltonen]

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 at 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 at 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 at 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 at 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 at helsinki.fi> PGP Key ID: 0x9CFAC88B
Please consider membership of the Hospitality Club (http://www.hospitalityclub.org)