lazy expunge folder delete bug

[Jan-Pieter Cornet]

There's a bug in "folder delete" for lazy expunge, type "1 namespace", as descibed on https://wiki2.dovecot.org/Plugins/Lazyexpunge

When trying to delete a mailbox that still has messages in it, but that has no EXPUNGED/<name> counterpart, the process hangs after the imap "DELETE" command, and the following appears in the log file after a 60s timeout:

Jun 22 15:48:15 userimap6 dovecot: imap(xtra30): Error: Couldn't create mailbox list lock /var/mail/.8d1/index/4/03/xtra30/index/mailboxes.lock: file_create_locked(/var/mail/.8d1/index/4/03/xtra30/index/mailboxes.lock) failed: flock(/var/mail/.8d1/index/4/03/xtra30/index/mailboxes.lock, write-lock) failed: Timed out after 60 seconds (BUG: lock is held by our own process)
Jun 22 15:48:15 userimap6 dovecot: imap(xtra30): Error: lazy_expunge: Couldn't open expunge mailbox: Failed to create mailbox EXPUNGED/Test: Internal error occurred. Refer to server log for more information. [2018-06-22 15:47:15]
Jun 22 15:48:15 userimap6 dovecot: imap(xtra30): Error: Lazy-expunge transaction failed: Internal error occurred. Refer to server log for more information. [2018-06-22 15:47:15]

very quick summage of settings:
----8<-----
mail_plugins = $mail_plugins lazy_expunge
mail_location = mdbox:/var/mail/.8d1/mail/4/03/xtra30:INDEX=/var/mail/.8d1/index/4/03/xtra30/index  ### from userdb
namespace {
   inbox = yes
   list = yes
   prefix =
   separator = /
}
namespace expunged {
   hidden = yes
   inbox = no
   list = no
   prefix = EXPUNGED/
   separator = /
   location = mdbox:/var/mail/.8d1/mail/4/03/xtra30:INDEX=/var/mail/.8d1/index/4/03/xtra30/index:MAILBOXDIR=expunged:LISTINDEX=expunged.list.index:SUBSCRIPTIONS=expunged.subscriptions ### also from userdb
}
plugin {
   lazy_expunge = EXPUNGED/
}
----8<-----
(full doveconf available on request)

State of the account before delete: mailbox "Test" exists, 20 messages in it:

x LIST * *
* LIST (\HasNoChildren \UnMarked \Trash) "/" Trash
* LIST (\HasNoChildren \Marked) "/" Test
* LIST (\HasNoChildren \UnMarked \Junk) "/" Spam
* LIST (\HasNoChildren \UnMarked) "/" Sent
* LIST (\HasNoChildren \UnMarked) "/" Drafts
* LIST (\HasNoChildren) "/" INBOX
x OK List completed (0.009 + 0.000 + 0.008 secs).
x LIST EXPUNGED/* *
x OK List completed (0.001 + 0.000 secs).
x DELETE Test
x NO [SERVERBUG] Internal error occurred. Refer to server log for more information. [2018-06-22 15:47:15] (60.064 + 0.000 + 60.063 secs).

... resulting in the above log lines.

However, if you first delete one message (causing EXPUNGED/Test to be created), and then remove the folder, it works fine:

x SELECT Test
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
* 20 EXISTS
* 2 RECENT
* OK [UNSEEN 1] First unseen.
* OK [UIDVALIDITY 1352910749] UIDs valid
* OK [UIDNEXT 21] Predicted next UID
* OK [HIGHESTMODSEQ 21] Highest
x OK [READ-WRITE] Select completed (0.010 + 0.000 + 0.009 secs).
x FETCH 1:* (FLAGS)
* 1 FETCH (FLAGS ())
[...boring...]
* 20 FETCH (FLAGS (\Recent))
x OK Fetch completed (0.002 + 0.000 + 0.001 secs).
x STORE 1 +FLAGS (\Deleted)
* 1 FETCH (FLAGS (\Deleted))
x OK Store completed (0.011 + 0.000 + 0.010 secs).
x EXPUNGE
* 1 EXPUNGE
x OK Expunge completed (0.131 + 0.000 + 0.130 secs).
X LIST * *
* LIST (\HasNoChildren \UnMarked \Trash) "/" Trash
* LIST (\HasNoChildren \UnMarked) "/" Test
* LIST (\HasNoChildren \UnMarked \Junk) "/" Spam
* LIST (\HasNoChildren \UnMarked) "/" Sent
* LIST (\HasNoChildren \UnMarked) "/" Drafts
* LIST (\HasNoChildren) "/" INBOX
X OK List completed (0.005 + 0.000 + 0.004 secs).
x LIST EXPUNGED/* *
* LIST (\HasNoChildren \Marked) "/" EXPUNGED/Test
x OK List completed (0.002 + 0.000 + 0.001 secs).
x SELECT INBOX
* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
[...INBOX opening msgs...]
x OK [READ-WRITE] Select completed (0.005 + 0.000 + 0.004 secs).
x DELETE Test
x OK Delete completed (0.129 + 0.000 + 0.128 secs).
x LIST * *
* LIST (\HasNoChildren \UnMarked \Trash) "/" Trash
* LIST (\HasNoChildren \UnMarked \Junk) "/" Spam
* LIST (\HasNoChildren \UnMarked) "/" Sent
* LIST (\HasNoChildren \UnMarked) "/" Drafts
* LIST (\HasNoChildren) "/" INBOX
x OK List completed (0.005 + 0.000 + 0.004 secs).
x LIST EXPUNGED/* *
* LIST (\HasNoChildren \Marked) "/" EXPUNGED/Test
x OK List completed (0.003 + 0.000 + 0.002 secs).

Seems the delete opeation locks the mailbox list, and then the expunge create hits the same lock. Is this something we can fix by changing settings? Eg use another location for the expunge lock?

-- 
Jan-Pieter Cornet <johnpc at xs4all.net>
Systeembeheer XS4ALL Internet bv
www.xs4all.nl

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 963 bytes
Desc: OpenPGP digital signature
URL: <https://dovecot.org/pipermail/dovecot/attachments/20180622/546b973e/attachment.sig>