Delayed delete oddities

[David Mayo]

We have just started transferring the first mailboxes onto our new Cyrus 
IMAP 2.3.13 server running on Solaris 10. Delayed expunge seems to work 
fine but I've noticed a strange phenomenon with delayed delete on mailboxes.

We have set up cyrus to delete expunged emails and deleted mailboxes 
after 7 days:

   delprune      cmd="cyr_expire -E 3 -D 7 -X 7" at=0400

It appears to be deleting emails 7 days after they have been expunged, 
so this looks fine:

Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 4662 messages from DELETED.user.usera.BUCS.IT 
discussion list.4B2123D3
Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 29 messages from user.xxxxx
Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 63 messages from user.xxxxx.Trash
Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 2 messages from user.xxxxx.aa-lists
Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 26 messages from user.xxxxx.spam
Dec 11 04:00:03 imap-1.bath.ac.uk cyr_expire[29491]: [ID 301543 
mail.info] skiplist: checkpointed /opt/etc/imapd/quotas.db (13 records, 
816 bytes) in 0 seconds
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 36 messages from user.usera.spam
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 427756 
mail.notice] Expunged 5039 out of 82483 messages from 232 mailboxes
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 630590 
mail.notice] Deleted mailbox DELETED.user.xxxxz.Trash.ucu.4B184D30
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 857756 
mail.notice] skiplist: unlock while not locked
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 489633 
mail.notice] Removed 1 deleted mailbox
Dec 11 04:00:05 imap-1.bath.ac.uk cyr_expire[29491]: [ID 730478 
mail.notice] duplicate_prune: pruning back 3 days
Dec 11 04:00:12 imap-1.bath.ac.uk cyr_expire[29491]: [ID 371192 
mail.notice] duplicate_prune: purged 1659 out of 6999 entries

It's just the first entry I'm concerned by:

Dec 11 04:00:00 imap-1.bath.ac.uk cyr_expire[29491]: [ID 956378 
mail.notice] Expunged 4662 messages from DELETED.user.usera.BUCS.IT 
discussion list.4B2123D3

This mailbox was only deleted yesterday:

Dec 10 16:37:39 sauber.bath.ac.uk imap[11321]: [ID 630590 mail.notice] 
Deleted mailbox user.usera.BUCS.IT discussion list

The mailbox was moved to the right area of the IMAP tree but all the 
messages were removed after just one day. The messages in the mailbox 
were not marked for deletion after being moved. Worse still, it hasn't 
even kept the messages on the filesystem:

imap-1 $ ls -la /mail/02/DELETED/user/usera/BUCS/IT\ discussion\ 
list/4B2123D3/
total 21441
drwx------   2 cyrus    cyrus         12 Dec 11 04:00 .
drwx------   3 cyrus    cyrus          3 Dec 10 16:37 ..
-rw-------   1 cyrus    cyrus      27366 Feb 17  2009 4861.
-rw-------   1 cyrus    cyrus       3151 May 31  2009 5007.
-rw-------   1 cyrus    cyrus       2543 Jun 15 10:04 5025.
-rw-------   1 cyrus    cyrus       2396 Jun 15 11:45 5026.
-rw-------   1 cyrus    cyrus       2366 Jul 29 09:46 5084.
-rw-------   1 cyrus    cyrus          4 Dec 11 04:00 cyrus.cache
-rw-------   1 cyrus    cyrus        536 Dec 10 16:37 cyrus.expunge
-rw-------   1 cyrus    cyrus        175 Dec 10 16:37 cyrus.header
-rw-------   1 cyrus    cyrus         96 Dec 11 04:00 cyrus.index
-rw-------   1 cyrus    cyrus    10734041 Dec 11 02:00 cyrus.squat

(squatter is run at 2am, cyr_expire at 4am, which explains the size of 
cyrus.squat)

There were emails newer and older than those ones there, so I'm not sure 
why those 5 were kept. Running unexpunge on the mailbox resulted in this:

imap-1 $ unexpunge -l "DELETED.user.usera.BUCS.IT discussion list.4B2123D3"
UID: 4861
         Size: 27366
         Sent: Tue Feb 17 12:00:00 2009
         Recv: Tue Feb 17 10:47:12 2009
         Expg: Thu Dec 10 16:37:39 2009
Segmentation Fault (core dumped)

[imap-1][/] # pstack /var/tmp/core.unexpunge
core '/var/tmp/core.unexpunge' of 516:  unexpunge -l 
DELETED.user.usera.BUCS.IT discussion list.4B2123D3
  08058317 list_expunged (8046734, 8134898, 5, fea50000) + 186
  080599df main     (3, 8047a5c, 8047a6c) + 941
  08057f84 _start   (3, 8047b58, 8047b62, 8047b65, 0, 8047b9a) + 80

Is the deleted mailbox code considered reliable? Should we be pruning 
these using a different method? I'm happy to supply more information if 
it would lead to this being better understood and/or fixed.

Regards,


Dave
Networks/Systems Administrator, BUCS