[LBBS-116] net_imap: Untagged responses should be flushed before tagged response
When deleting a message from INBOX in evergreen, the IMAP client and server lose synchronization:
2025-09-14 12:24:33 evergreen.c:802 [__poll_input] Translating input 330 to KEY_DL
2025-09-14 12:24:33 imap.c:2956 [client_idle_stop] Stopping IDLE...
2025-09-14 12:24:33 imap.c:3621 [client_move] => MOVE 2187 Trash
2025-09-14 12:24:33 evergreen.c:1926 [client_menu] Redrawing folder/message/status pane
2025-09-14 12:24:33 evergreen.c:1426 [redraw_windows] Recreating and rerendering all windows
2025-09-14 12:24:33 messages.c:469 [__get_msg] menu.c:411 - Found message index 0
2025-09-14 12:24:33 imap.c:2925 [client_idle_start] Starting IDLE...
2025-09-14 12:24:33 imap.c:2902 [client_flush_pending_output] Flushing output '* 63 EXPUNGE
'
2025-09-14 12:24:48 imap.c:2943 [client_idle_start] WARNING: Failed to start IDLE: unknown
2025-09-14 12:24:48 evergreen.c:2876 [main] --------------- Ending session -1 ---------------
It appears this is due to net_imap sending an untagged EXPUNGE between commands, which is not allowed, per RFC 3501 5.3.
[2025-09-14 12:24:33.163] DEBUG[484503]: imap_client.c:198 imap_poll: IMAP poll returned 1 for main IMAP client
[2025-09-14 12:24:33.163] DEBUG[484503]: net_imap.c:5010 handle_client: 0x7f28387f5870 => DONE
[2025-09-14 12:24:33.163] DEBUG[484503]: net_imap.c:4434 imap_process: Received IDLE termination
[2025-09-14 12:24:33.164] DEBUG[484503]: net_imap.c:4018 idle_stop: 0x7f28387f5870 <= 12 OK IDLE terminated
[2025-09-14 12:24:33.164] DEBUG[484503]: net_imap.c:5010 handle_client: 0x7f28387f5870 => 13 UID MOVE 2187 Trash
[2025-09-14 12:24:33.165] DEBUG[484503]: mod_mail.c:1230 mailbox_get_next_uid: Assigned UIDNEXT 1942 (UIDVALIDITY 1734297474) - current max UID: 1942
[2025-09-14 12:24:33.166] DEBUG[484503]: mod_mail.c:1736 maildir_move_msg_filename: Renamed /home/bbs/maildir/1/cur/1757253677066778,S=758,U=2187,M=5315:2,Sa -> /home/bbs/maildir/1/.Trash/cur/1757253677066778,S=758,U=1942,M=61:2,Sa
[2025-09-14 12:24:33.166] DEBUG[484503]: mod_mail.c:236 mailbox_dispatch_event: Dispatching mailbox event 'MessageNew' (maildir: /home/bbs/maildir/1/.Trash)
[2025-09-14 12:24:33.166] DEBUG[484503]: net_imap.c:477 generate_mailbox_name: maildir /home/bbs/maildir/1/.Trash => 'Trash'
[2025-09-14 12:24:33.167] DEBUG[484503]: mod_mail.c:1232 mailbox_get_next_uid: Current max UID: 1942
[2025-09-14 12:24:33.167] DEBUG[484503]: net_imap.c:366 __imap_send_update_log: 676: 0x7f28387f5870 <= * STATUS "Trash" (MESSAGES 38 UIDNEXT 1943 UNSEEN 0 HIGHESTMODSEQ 60)
[2025-09-14 12:24:33.168] DEBUG[484503]: mod_mail.c:1232 mailbox_get_next_uid: Current max UID: 1942
[2025-09-14 12:24:33.168] DEBUG[484503]: imap_server_flags.c:375 translate_maildir_flags: Flags for 1757253677066778,S=758,U=2187,M=5315:2,Sa have changed to 'Sa' due to location/permission change
[2025-09-14 12:24:33.169] DEBUG[484503]: net_imap.c:2211 handle_move: 0x7f28387f5870 <= 13 OK [COPYUID 1734297474 2187 1942] MOVE completed
[2025-09-14 12:24:33.174] DEBUG[484503]: mod_mail.c:1472 maildir_indicate_expunged: Current position is 55075
[2025-09-14 12:24:33.176] DEBUG[484503]: mod_mail.c:1484 maildir_indicate_expunged: Added 2187/5315 to expunge log
[2025-09-14 12:24:33.178] DEBUG[484503]: mod_mail.c:1489 maildir_indicate_expunged: Updated HIGHESTMODSEQ to 5315
[2025-09-14 12:24:33.180] DEBUG[484503]: mod_mail.c:236 mailbox_dispatch_event: Dispatching mailbox event 'MessageExpunge' (maildir: /home/bbs/maildir/1)
[2025-09-14 12:24:33.182] DEBUG[484503]: net_imap.c:477 generate_mailbox_name: maildir /home/bbs/maildir/1 => 'INBOX'
[2025-09-14 12:24:33.184] DEBUG[484503]: net_imap.c:376 __imap_send_update_log: 606: 0x7f28387f5870 <= * 63 EXPUNGE
[2025-09-14 12:24:33.186] DEBUG[484503]: mod_mail.c:1232 mailbox_get_next_uid: Current max UID: 2187
[2025-09-14 12:24:33.263] DEBUG[484503]: net_imap.c:5010 handle_client: 0x7f28387f5870 => 14 IDLE
[2025-09-14 12:24:33.264] DEBUG[484503]: net_imap.c:4127 flush_updates: 0x7f28387f5870 <= * STATUS "Trash" (MESSAGES 38 UIDNEXT 1943 UNSEEN 0 HIGHESTMODSEQ 60)
[2025-09-14 12:24:33.270] DEBUG[484503]: socket.c:1555 __bbs_poll_interrupt: poll returned 0 on fd 51
[2025-09-14 12:24:33.270] DEBUG[484503]: readline.c:173 bbs_readline: bbs_poll_read returned 0
[2025-09-14 12:24:33.271] DEBUG[484503]: net_imap.c:4198 handle_idle: 0x7f28387f5870 <= + idling
[2025-09-14 12:24:33.271] DEBUG[484503]: imap_client.c:150 imap_poll: Polling 13 fds for IMAP session 0x7f28387f5870 (for 45s)
[2025-09-14 12:24:41.675] DEBUG[449141]: socket.c:1555 __bbs_poll_interrupt: poll returned 0 on fd 4
[2025-09-14 12:24:47.251] DEBUG[484503]: imap_client.c:205 imap_poll: IMAP poll returned 1 for remote IMAP client Other Users.riseup
[2025-09-14 12:24:47.253] DEBUG[484503]: net_imap.c:4304 handle_idle: Received during IDLE: * OK Still here
[2025-09-14 12:24:47.253] DEBUG[484503]: imap_client.c:150 imap_poll: Polling 13 fds for IMAP session 0x7f28387f5870 (for 31s)
[2025-09-14 12:24:48.289] DEBUG[484503]: imap_client.c:198 imap_poll: IMAP poll returned 1 for main IMAP client
[2025-09-14 12:24:48.289] DEBUG[484503]: net_imap.c:5010 handle_client: 0x7f28387f5870 => 15 LOGOUT
[2025-09-14 12:24:48.289] DEBUG[484503]: net_imap.c:4434 imap_process: Received IDLE termination
[2025-09-14 12:24:48.290] DEBUG[484503]: net_imap.c:4018 idle_stop: 0x7f28387f5870 <= 14 OK IDLE terminated
[2025-09-14 12:24:48.291] DEBUG[484368]: system.c:287 waitpidexit: Process 484502 (evergreen) exited, status 255
[2025-09-14 12:24:48.291] DEBUG[484368]: system.c:311 waitpidexit: Command failed (255 - Unknown error 255): evergreen
The issue here isn't that it's been flushed in realtime (since it's for the current connection that did the delete), but rather that the EXPUNGE is being issued between commands, rather than within the MOVE.
That being said, fixing that does not fix evergreen from crashing - I wonder if libetpan is confused by something or there is another issue here:
[2025-09-14 12:52:07.981] DEBUG[485248]: net_imap.c:377 __imap_send_update_log: 607: 0x7f28387f5870 <= * 62 EXPUNGE
[2025-09-14 12:52:07.982] DEBUG[485248]: mod_mail.c:1232 mailbox_get_next_uid: Current max UID: 2187
[2025-09-14 12:52:07.983] DEBUG[485248]: net_imap.c:2223 handle_move: 0x7f28387f5870 <= 13 OK [COPYUID 1734297474 2186 1943] MOVE completed
[2025-09-14 12:52:08.092] DEBUG[485248]: net_imap.c:5026 handle_client: 0x7f28387f5870 => 14 IDLE
[2025-09-14 12:52:08.093] DEBUG[485248]: net_imap.c:4131 flush_updates: 0x7f28387f5870 <= * STATUS "Trash" (MESSAGES 39 UIDNEXT 1944 UNSEEN 0 HIGHESTMODSEQ 60)
[2025-09-14 12:52:08.098] DEBUG[485248]: socket.c:1555 __bbs_poll_interrupt: poll returned 0 on fd 51
[2025-09-14 12:52:08.098] DEBUG[485248]: readline.c:173 bbs_readline: bbs_poll_read returned 0
[2025-09-14 12:52:08.099] DEBUG[485248]: net_imap.c:4211 handle_idle: 0x7f28387f5870 <= + idling
2025-09-14 12:52:07 evergreen.c:802 [__poll_input] Translating input 330 to KEY_DL
2025-09-14 12:52:07 imap.c:2956 [client_idle_stop] Stopping IDLE...
2025-09-14 12:52:07 imap.c:3621 [client_move] => MOVE 2186 Trash
2025-09-14 12:52:08 evergreen.c:1926 [client_menu] Redrawing folder/message/status pane
2025-09-14 12:52:08 evergreen.c:1426 [redraw_windows] Recreating and rerendering all windows
2025-09-14 12:52:08 messages.c:469 [__get_msg] menu.c:411 - Found message index 0
2025-09-14 12:52:08 imap.c:2925 [client_idle_start] Starting IDLE...
2025-09-14 12:52:23 imap.c:2943 [client_idle_start] WARNING: Failed to start IDLE: unknown
2025-09-14 12:52:23 evergreen.c:2876 [main] --------------- Ending session -1 ---------------
A related problem in evergreen is if we go to the trash and move a message to the inbox, the client freezes - if we hit 'm' to try to move another message, nothing happens, and after the libetpan timer expires, the client exits.
Note: Both the delete issue and the moved issue seem to be caused by an untagged STATUS being sent when we being IDLE, as they are resolved by the fix for [LBBS-116].
You must be