rbox_set_expunge => index rebuild

[jrse]

Describe the bug
In case rbox_mail tries to get the metadata of a recently (old index data) deleted object. get_metadata fails with -2 and mail is set as expunged.

Because the rbox_set_expunge method does a index_refresh, the recently deleted mail may no longer set as as expunged in the index (index entry removed by the delete process). The result of rbox_set_expunge then is, that the index is marked as corrupt and rbox_sync will force a rebuild of the index!

Rebuilding the rbox index, is a really slow process, because it involves a scan for objects on all osds, and what may be worse a lock on the index.

To Reproduce
Steps to reproduce the behavior:

1. Use imaptest with https://github.com/ceph-dovecot/imaptest with e.g. 1000 user and given imap-profile.conf (important is a high number of concurrency)
2. wait for ' Warning: Errorcode: -2 cannot get x_attr(' with tail -f dovecot.log
3. check log for Rebuilding index messages.

Expected behavior

• Because the email is no longer in the object store, a warning with (uid, processid) should be written to log file.
• if a mail gets expunged (removed from storage), a log message with (uid, processid) should be written to log file.
• Mail, because it no longer exist should, in any case be marked as expunged.
• mail_read process exits gracefully, because it detects (mail marked as expunged) that it has read an old entry.

Logfiles, screenshots
Nov 29 02:04:18 imap(t659): Warning: Errorcode: -2 cannot get x_attr(G,G) from object c12919200f3bff5bb5340000d561c877, process 13390
Nov 29 02:04:18 imap(t659): Error: rbox /mnt/cephfs/mail/rbox/t659/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=551
Nov 29 02:04:18 imap(t271): Warning: Errorcode: -2 cannot get x_attr(G,G) from object 799a1d200e3bff5bb5340000d561c877, process 13115
Nov 29 02:04:18 imap(t271): Error: rbox /mnt/cephfs/mail/rbox/t271/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=492
Nov 29 02:04:18 imap(t845): Warning: Errorcode: -2 cannot get x_attr(G,G) from object 19742c1f023bff5b6b2c0000d561c877, process 8662
Nov 29 02:04:18 imap(t845): Error: rbox /mnt/cephfs/mail/rbox/t845/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=473
Nov 29 02:04:18 imap(t845): Warning: rbox /mnt/cephfs/mail/rbox/t845/mailboxes/Drafts/rbox-Mails: Rebuilding index, guid: 1320f2201fc7fd5bf34c0000d561c877 , mailbox_name: Drafts, alt_storage: (null)
Nov 29 02:04:19 imap(t676): Warning: Errorcode: -2 cannot get x_attr(G,G) from object 91528902113bff5bb5340000d561c877, process 13395
Nov 29 02:04:19 imap(t676): Error: rbox /mnt/cephfs/mail/rbox/t676/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=990
Nov 29 02:04:19 imap(t710): Warning: Errorcode: -2 cannot get x_attr(G,G) from object 993ba81f0d3bff5b16560000d561c877, process 5731
Nov 29 02:04:19 imap(t710): Error: rbox /mnt/cephfs/mail/rbox/t710/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=516
Nov 29 02:04:19 imap(t659): Warning: rbox /mnt/cephfs/mail/rbox/t659/mailboxes/Drafts/rbox-Mails: Rebuilding index, guid: 6593b8336bc2fd5b20490000d561c877 , mailbox_name: Drafts, alt_storage: (null)
Nov 29 02:04:19 imap(t676): Warning: rbox /mnt/cephfs/mail/rbox/t676/mailboxes/Drafts/rbox-Mails: Rebuilding index, guid: 96c4c332d9c2fd5b77490000d561c877 , mailbox_name: Drafts, alt_storage: (null)
Nov 29 02:04:19 imap(t413): Warning: Errorcode: -2 cannot get x_attr(G,G) from object 91905b010c3bff5b8d070000d561c877, process 1012
Nov 29 02:04:19 imap(t413): Error: rbox /mnt/cephfs/mail/rbox/t413/mailboxes/INBOX/rbox-Mails: Unexpectedly lost uid=719
Nov 29 02:04:19 imap(t271): Warning: rbox /mnt/cephfs/mail/rbox/t271/mailboxes/Drafts/rbox-Mails: Rebuilding index, guid: ee569

Server (please complete the following information):

• OS: ubuntu
• Ceph Version [luminous]
• Dovecot Version 2.2

Client (please complete the following information):

• used client [imaptest]
• Version [https://github.com/ceph-dovecot/imaptest]

Additional context
The problem will occur, when the read process of a user, tries to read a mail which another user process deletes. Because this is a timing issue, it may take several attempts or hours before the problem occurs.

[jrse]

• tested this with a imaptest running over several hours. No unnecessary index rebuild anymore.