Race condition in IMAP NOTIFY for events received NOTIFY_DELAY_MSECS apart

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.