asimap
asimap copied to clipboard
scanner
Deleting a message from a folder caused an unexpected resync failure: mbox shrunk (but this should not have happened)
Something in our EXPUNGE logic broke. It usually works but deleting a message from these two mailboxes caused an issue. Maybe we need to go back and make sure that EXPUNGE is properly blocking other tasks from running? (EXPUNGE happens rarely enough that.. it already should be blocking.)
[2024-09-05 08:43:10,470] INFO:user_server.dump_metrics: stddev duration: 0.014s
[2024-09-05 08:43:12,949] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 67, num new msgs: 1, first new msg: 148, last new msg: 148
[2024-09-05 08:43:13,785] INFO:user_server.new_client: New IMAP client: client-00001718(127.0.0.1:49322)
[2024-09-05 08:43:14,590] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'apricot-admin/daily-reports' has shrunk, from 3123 messages to 3122. Treating it as a new mailbox.
[2024-09-05 08:43:14,930] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 68, num new msgs: 1, first new msg: 149, last new msg: 149
[2024-09-05 08:43:16,099] INFO:user_server.run: Client client-00001693 has logged out
[2024-09-05 08:43:16,100] INFO:user_server.client_done: IMAP Client task done (disconnected): client-00001693
[2024-09-05 08:43:18,502] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'commerce/meh' has shrunk, from 2956 messages to 2955. Treating it as a new mailbox.
a message was deleted from each of these mailboxes. The STORE to mark it deleted happened. The COPY to the Deleted Messages mailbox happened (and that mbox was resync'd), however after (during?) the EXPUNGE when the next mailbox resync was being done, that the mailbox shrunk was unexpected. It should not have been unexpected.
So the EXPUNGE did not properly update the mailbox's msg keys, uids, num messages?
Another example, deleted four messages in one go:
[2024-09-06 08:46:03,982] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Archive', num msgs: 3379, num new msgs: 1, first new msg: 3385, last new msg: 3385
[2024-09-06 08:46:13,647] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 73, num new msgs: 3, first new msg: 154, last new msg: 156
[2024-09-06 08:46:14,845] INFO:user_server.new_client: New IMAP client: client-00002667(127.0.0.1:38500)
[2024-09-06 08:46:15,848] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 76, num new msgs: 1, first new msg: 157, last new msg: 157
[2024-09-06 08:46:15,910] INFO:user_server.run: Client client-00002667 has logged out
[2024-09-06 08:46:15,911] INFO:user_server.client_done: IMAP Client task done (disconnected): client-00002667
[2024-09-06 08:46:17,209] INFO:user_server.new_client: New IMAP client: client-00002668(127.0.0.1:38506)
[2024-09-06 08:46:18,904] INFO:user_server.run: Client client-00002661 has logged out
[2024-09-06 08:46:18,906] INFO:user_server.client_done: IMAP Client task done (disconnected): client-00002661
[2024-09-06 08:46:19,669] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'commerce/meh' has shrunk, from 2956 messages to 2955. Treating it as a new mailbox.
[2024-09-06 08:46:19,677] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'apricot-admin/daily-reports' has shrunk, from 3125 messages to 3122. Treating it as a new mailbox.
I am not sure if this is related or not, but I have now finally caught an issue where it seems we have no longer "SELECTED" a mailbox, and attempted STORE.. but also are spamming SELECT. The STORE was on messages in the INBOX.
[2024-09-10 07:46:16,122] WARNING:client.do_select: client-00000598, mailbox: 'apricot-admin/mail': excessive selects while selected, count: 11
[2024-09-10 07:46:17,089] WARNING:client.do_select: client-00000600, mailbox: 'commerce/fidelity': excessive selects while selected, count: 11
[2024-09-10 07:46:17,265] WARNING:client.do_select: client-00000598, mailbox: 'apricot-admin/mail': excessive selects while selected, count: 11
[2024-09-10 07:46:18,843] WARNING:client.do_select: client-00000598, mailbox: 'apricot-admin/mail': excessive selects while selected, count: 11
[2024-09-10 07:46:21,775] WARNING:client.do_select: client-00000598, mailbox: 'apricot-admin/mail': excessive selects while selected, count: 11
[2024-09-10 07:46:36,618] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:36,961] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:37,322] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:37,682] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:37,880] WARNING:client.do_select: client-00000600, mailbox: 'inbox': excessive selects while selected, count: 11
[2024-09-10 07:46:38,010] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:38,334] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:38,394] WARNING:client.do_select: client-00000600, mailbox: 'inbox': excessive selects while selected, count: 11
[2024-09-10 07:46:38,693] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:38,943] WARNING:client.do_select: client-00000600, mailbox: 'inbox': excessive selects while selected, count: 11
[2024-09-10 07:46:38,954] WARNING:client.command: client-00000600: NO Response: '549.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:38,978] WARNING:client.command: client-00000600: NO Response: '551.8 UID COPY': Client must be in the selected state
[2024-09-10 07:46:39,008] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:39,024] WARNING:client.command: client-00000600: NO Response: '553.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:39,048] WARNING:client.command: client-00000600: NO Response: '555.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:39,070] WARNING:client.command: client-00000600: NO Response: '557.8 UID COPY': Client must be in the selected state
[2024-09-10 07:46:39,344] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:39,507] WARNING:client.command: client-00000600: NO Response: '559.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:39,541] WARNING:client.command: client-00000600: NO Response: '561.8 UID COPY': Client must be in the selected state
[2024-09-10 07:46:39,642] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:39,764] WARNING:client.command: client-00000600: NO Response: '563.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:39,912] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:40,218] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:40,231] WARNING:client.command: client-00000600: NO Response: '565.8 UID COPY': Client must be in the selected state
[2024-09-10 07:46:40,513] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:40,804] WARNING:client.do_select: client-00000601, mailbox: 'z_archives/archive_2016': excessive selects while selected, count: 11
[2024-09-10 07:46:42,305] WARNING:client.command: client-00000600: NO Response: '567.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:43,088] WARNING:client.command: client-00000600: NO Response: '569.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:44,696] WARNING:client.command: client-00000600: NO Response: '571.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:46,109] WARNING:client.command: client-00000600: NO Response: '573.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:47,143] WARNING:client.command: client-00000600: NO Response: '575.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:50,257] WARNING:client.command: client-00000600: NO Response: '577.8 UID STORE': Client must be in the selected state
[2024-09-10 07:46:51,301] WARNING:client.command: client-00000600: NO Response: '579.8 UID STORE': Client must be in the selected state
Another case:
[2024-09-29 23:43:13,894] [email protected] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 88, num new msgs: 1, first new msg: 186, last new msg: 186
[2024-09-29 23:43:16,878] [email protected] INFO:mbox.check_new_msgs_and_flags: Mailbox: 'Deleted Messages', num msgs: 89, num new msgs: 1, first new msg: 187, last new msg: 187
[2024-09-29 23:43:19,612] [email protected] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'inbox' has shrunk, from 187 messages to 185. Treating it as a new mailbox.
[2024-09-29 23:43:20,471] [email protected] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'inbox' has shrunk, from 187 messages to 185. Treating it as a new mailbox.
[2024-09-29 23:43:22,000] [email protected] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'inbox' has shrunk, from 187 messages to 185. Treating it as a new mailbox.
[2024-09-29 23:43:22,017] [email protected] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'inbox' has shrunk, from 187 messages to 185. Treating it as a new mailbox.
[2024-09-29 23:43:22,026] [email protected] WARNING:mbox.check_new_msgs_and_flags: Mailbox: 'inbox' has shrunk, from 187 messages to 185. Treating it as a new mailbox.
[2024-09-29 23:43:26,300] [email protected] INFO:user_server.new_client: New IMAP client: client-00000056(127.0.0.1:40032)
Tenative fix for now is to not expire mailboxes. Error seems to have indeed gone away so the bug was introduced when I added "in use counts" to the mailboxes instead of timer expiry.
Right now leaving expiry for mailboxes off entirely. The MacOS Mail.app is doing a STATUS scan of the server so often that regular expiry was not really being useful at trimming memory use, so let us see how it works if we just leave the mailboxes in memory.