IMAP client hangs in IMAP IDLE if SELECT consumed EXISTS response notifying about new messages #4926
Description
I am debugging a test timeout in test_qr_join_chat_with_pending_bobstate_issue4894.
Accounts have the following addresses:
ac1: [email protected]
ac2: [email protected]
ac3: [email protected]
ac4: [email protected]
In GitHub Actions log ac1 sent vg-auth-required, but ac2 received it only when interrupted by the 300-second test timeout:
2023-11-04T04:33:01.7383430Z 34.24 [events-ac1] INFO src/mimefactory.rs:1067: sending secure-join message 'vg-auth-required' >>>>>>>>>>>>>>>>>>>>>>>>>
...
2023-11-04T04:33:01.7571550Z 303.53 [events-ac2] INFO src/receive_imf.rs:159: Received message has Message-Id: Mr.MBBBxZ6Xk-p.TEyzaEX4vzG@***
2023-11-04T04:33:01.7574060Z 303.53 [events-ac2] INFO src/securejoin.rs:290: >>>>>>>>>>>>>>>>>>>>>>>>> secure-join message 'vg-auth-required' received
I have collected rawlogs from Dovecot setup. Dovecot saves rawlogs in separate .in and .out files with timestamps, so they can be merged with:
sort -sn <(sed 's/ / C: /' [email protected]/*.in) <(sed 's/ / S: /' cat [email protected]/*.out)
If we search for Mr.MBBBxZ6Xk-p Message-ID in ac2 logs, its prefetch is preceded by IDLE:
1699072004.249377 S: + idling
1699072006.518674 S: * 2 EXISTS
1699072006.518719 S: * 2 RECENT
1699072006.678799 C: DONE
1699072006.678908 S: A0022 OK Idle completed (2.430 + 2.429 + 2.429 secs).
1699072006.839034 C: A0023 UID FETCH 22:* (UID INTERNALDATE RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-
SETUP-MESSAGE)])
1699072006.839246 S: * 2 FETCH (UID 22 INTERNALDATE "04-Nov-2023 05:26:46 +0100" RFC822.SIZE 4957 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CH
AT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {175}
...
1699072006.839376 S: A0023 OK Fetch completed (0.001 + 0.000 secs).
1699072007.000716 C: A0024 UID FETCH 22 (FLAGS BODY.PEEK[])
1699072007.001707 S: * 2 FETCH (UID 22 FLAGS (\Recent) BODY[] {4957}
...
1699072007.002198 S: A0024 OK Fetch completed (0.002 + 0.000 secs).
1699072007.169973 C: A0025 UID STORE 22 +FLAGS (\Deleted)
1699072007.170931 S: * 2 FETCH (UID 22 MODSEQ (53) FLAGS (\Deleted \Recent))
1699072007.171040 S: A0025 OK Store completed (0.001 + 0.000 secs).
1699072007.331267 C: A0026 CLOSE
1699072007.332841 S: A0026 OK Close completed (0.002 + 0.000 + 0.001 secs).
1699072007.492660 C: A0027 SELECT "INBOX" (CONDSTORE)
1699072007.508207 S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
1699072007.508252 S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
1699072007.508273 S: * 2 EXISTS
1699072007.508292 S: * 1 RECENT
1699072007.508311 S: * OK [UNSEEN 1] First unseen.
1699072007.508330 S: * OK [UIDVALIDITY 1699071837] UIDs valid
1699072007.508349 S: * OK [UIDNEXT 24] Predicted next UID
1699072007.508368 S: * OK [HIGHESTMODSEQ 55] Highest
1699072007.508397 S: A0027 OK [READ-WRITE] Select completed (0.016 + 0.000 + 0.015 secs).
1699072007.668686 C: A0028 UID FETCH 1:* (FLAGS) (CHANGEDSINCE 51)
1699072007.668869 S: * 2 FETCH (UID 23 FLAGS (\Recent) MODSEQ (55))
1699072007.669083 S: A0028 OK Fetch completed (0.001 + 0.000 secs).
1699072007.829278 C: A0029 IDLE
1699072007.829452 S: + idling
1699072107.839394 S: * OK Still here
1699072227.849150 S: * OK Still here
...
1699072274.916708 C: A0030 GETQUOTAROOT "INBOX"
1699072274.916973 S: * QUOTAROOT INBOX "User quota"
1699072274.917002 S: * QUOTA "User quota" (STORAGE 9 102400)
1699072274.917022 S: A0030 OK Getquotaroot completed (0.001 + 0.000 secs).
1699072275.077620 C: A0031 UID FETCH 23:* (UID INTERNALDATE RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])
1699072275.078129 S: * 2 FETCH (UID 23 INTERNALDATE "04-Nov-2023 05:26:47 +0100" RFC822.SIZE 3454 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {175}
1699072275.078252 S: From: <[email protected]>
1699072275.078252 S: Message-ID: <[email protected]>
1699072275.078252 S: References: <[email protected]>
1699072275.078252 S: Chat-Version: 1.0
1699072275.078252 S:
1699072275.078273 S: )
1699072275.078474 S: A0031 OK Fetch completed (0.001 + 0.000 secs).
The client prefetched, fetched and deleted the message with UID 22, closed the INBOX to expunge the message, then reopened the INBOX with (CONDSTORE) to sync flags. In response to SELECT UIDNEXT is 24 and the number of messages in EXISTS is 2 again after being 2 before and we deleted one of the messages. So the message with UID 23 arrived somewhere between CLOSE and reopen.
There is no unsolicited EXISTS notification that would normally interrupt IDLE because EXISTS 2 was sent as a response to SELECT "INBOX" (CONDSTORE). It is impossible to tell from this EXISTS alone if there are new messages we need to look for with prefetch as in-between other client might have even deleted all messages and put two completely new messages in the INBOX. Selecting folder has always a chance to consume EXISTS notification in this way as in this case it is considered to be a part of SELECT response rather than an unsolicited response.
The client was even notified of UID 23 getting a \Recent flag, but because it was in the process of looking for \Seen flags, \Recent was simply ignored. We cannot use this signal to skip next idle because \Recent can be cleared at any time by another device selecting the folder.
At least in this case we can notice that UIDNEXT has advanced to 24 so we know to look for UID 23 which we have never seen. If we use UIDNEXT to notice new messages and skip IDLE, we need to also need to use STATUS workaround for servers which do not send UIDNEXT immediately (#4562), i.e. do what select_with_uidvalidity does. I would not care about UIDVALIDITY changes though, if the server changes UIDVALIDITY while the client is online without killing a connection, it shouldn't.
If we are going to possibly use STATUS workaround after SELECT and may shuffle "flag synchronization" and other tasks around, I am considering to just always run the STATUS command once before going IDLE and checking if UIDNEXT has advanced more than we expect. Sending an additional STATUS command is a bit of overhead, but it will not limit the throughput of a busy bot receiving a constant stream of messages during peak load because it will not even consider going IDLE until there are no messages. However, this approach will be very robust to any changes to the patterns of selecting and closing folders in other parts of our IMAP code, we will not even rely on unsolicited EXISTS responses at all except as an optimization to skip STATUS if we know something arrived.
Sidenote: I also don't like that we reselect the INBOX folder with (CONDSTORE) when the INBOX folder is already selected. We should probably just always select with (CONDSTORE) if it is supported to avoid reselecting, but this is an optimization.