Race condition in IMAP NOTIFY for events received NOTIFY_DELAY_MSECS apart

[Guilhem Moulin]

Hi there,

There seem to be a race condition in IMAP NOTIFY: when two events for
the SELECTED mailbox are received soon after one another, sometimes only
the first one is being reported to clients that enabled IMAP NOTIFY.  On
closer look it seems like this is most often reproducible when the delay
between the two events is NOTIFY_DELAY_MSECS (500ms).  This is with
2.3.4.1 from Debian sid.

    $ sed -r 's/^\s*//; s/\s+/ /g' >/tmp/dovecot.conf <<-EOF
		log_path           = /tmp/dovecot.log
		mailbox_list_index = yes
		mail_home          = /dev/shm/dovecot-test/%u
		mail_location      = dbox:~/mail
		ssl                = no
	EOF

(`doveconf -c /tmp/dovecot.conf -n` output enclosed.)

    $ rm -rf /dev/shm/dovecot-test && mkdir -m0700 /dev/shm/dovecot-test
    $ env -i USER=user HOME=/dev/shm/dovecot-test/user PATH=/usr/bin:/bin \
        doveadm -c /tmp/dovecot.conf exec imap
    S: * PREAUTH [CAPABILITY IMAP4rev1 … NOTIFY] Logged in as user
    C: a NOTIFY SET STATUS (SELECTED (MessageNew MessageExpunge FlagChange)) (MAILBOXES (INBOX test) (MessageNew MessageExpunge FlagChange))
    S: * STATUS INBOX (MESSAGES 0 UIDNEXT 1 UIDVALIDITY 1558785754 UNSEEN 0 HIGHESTMODSEQ 1)
    S: a OK NOTIFY completed (0.004 + 0.000 + 0.003 secs).
    S: * STATUS INBOX (MESSAGES 0 UIDNEXT 1 UIDVALIDITY 1558785754 UNSEEN 0 HIGHESTMODSEQ 1)
    C: b SELECT INBOX
    […]
    S: b OK [READ-WRITE] Select completed (0.001 + 0.000 secs).

Now deliver two messages to INBOX with ~500ms in between:

    $ env -i USER=user HOME=/dev/shm/dovecot-test/user PATH=/usr/bin:/bin sh -c \
        'echo -n . | doveadm -c /tmp/dovecot.conf exec dovecot-lda -e -m INBOX; \
         sleep 0.500; \
         echo -n . | doveadm -c /tmp/dovecot.conf exec dovecot-lda -e -m INBOX'

Only the the first message is reported in the above IMAP session:

    S: * 1 EXISTS
    S: * 1 RECENT

An UNSELECT doesn't trigger the notification, but (of course) a NOOP does:

    C: c NOOP
    S: * 2 EXISTS
    S: * 2 RECENT
    S: c OK NOOP completed (0.001 + 0.000 secs).


Similarly, for two flag changes within 0.5s only the first is recorded:

    $ env -i USER=user HOME=/dev/shm/dovecot-test/user PATH=/usr/bin:/bin sh -c \
        'doveadm -c /tmp/dovecot.conf flags add "\\Seen" mailbox INBOX 1; \
         sleep 0.500; \
         doveadm -c /tmp/dovecot.conf flags add "\\Answered" mailbox INBOX 2'

yields a single unsolicited FETCH response:

    S: * 1 FETCH (MODSEQ (4) FLAGS (\Seen \Recent))

AFAICT this is only reproducible in the ‘SELECTED’ mailbox specifier:
after creating a mailbox "test",

    $ env -i USER=user HOME=/dev/shm/dovecot-test/user PATH=/usr/bin:/bin sh -c \
        'echo -n . | doveadm -c /tmp/dovecot.conf exec dovecot-lda -e -m test; \
         sleep 0.500; \
         echo -n . | doveadm -c /tmp/dovecot.conf exec dovecot-lda -e -m test'

yields two unsolicited STATUS responses as expected:

	* STATUS test (MESSAGES 1 UIDNEXT 2 UIDVALIDITY 1558787038 UNSEEN 1 HIGHESTMODSEQ 2)
	* STATUS test (MESSAGES 2 UIDNEXT 3 UIDVALIDITY 1558787038 UNSEEN 2 HIGHESTMODSEQ 3)

(And same thing for two flag updates in the "test" mailbox.)  This is
not specific to INBOX as once "test" is selected the same problem arises.

AFAICT the race is in ‘src/lib-storage/list/mailbox-list-index-notify.c’
which for some reason doesn't acknowledge ST_CHANGED() after inotify_rm_watch(),
but I couldn't get my head around that file.

Cheers,
-- 
Guilhem.
-------------- next part --------------
# 2.3.4.1 (f79e8e7e4): /tmp/dovecot3.conf
# Pigeonhole version 0.5.4 ()
# OS: Linux 4.19.0-3-amd64 x86_64 Debian 10.0 
# Hostname: odin.guilhem.org
log_path = /tmp/dovecot.log
mail_home = /dev/shm/dovecot-test/%u
mail_location = dbox:~/mail
ssl = no
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL: <https://dovecot.org/pipermail/dovecot/attachments/20190525/ceccd5f1/attachment.sig>