@Phylu: I was able to reproduce this bug with the current Windows version 1.9.1-30ef802f, which I have freshly installed yesterday. Its a vanilla install without cloud account (purely local).
The server is a Dovecot IMAP Mailserver running current Debian stable.
Here is what I did:
- Opened Mailspring
- Used my iPhone to send a message to myself (reminder-style), the usual case I do here.
- The Mail appeared in the Inbox, probably due to some IMAP Idle message (so far so good)
- Then I pressed F5 to initiate a mail sync
- At that point, the message disappears from my inbox.
Note, that both a Thunderbird instance and the Apple Mail client on my iPhone still show the mail in the Inbox. I cross-checked this on my server, the mail is still physically present.
Here are the console Logs:
This I got during step 3, line wraps by me:
database-store.ts:203 _executeInBackground took more than 100ms - 188msec (8msec in background):
SELECT `Thread`.`id` FROM `Thread` WHERE `id`
IN (SELECT `id` FROM `ThreadCategory` WHERE `ThreadCategory`.`value`
IN ('LkW1y...cp1ep')
AND `ThreadCategory`.`inAllMail` != 0
ORDER BY `ThreadCategory`.`lastMessageReceivedTimestamp`
DESC LIMIT 200 OFFSET 0)
ORDER BY `Thread`.`lastMessageReceivedTimestamp` DESC
This was logged during Mail sync (steps 4+5), again, line wraps by me:
mailsync-process.ts:323 Sending to mailsync 198a0537 {type: "queue-task", task: ChangeUnreadTask}
mailsync-bridge.ts:197 Sending `wake` to all mailsync workers...
sendSyncMailNow @ mailsync-bridge.ts:197
(anonymous) @ window-event-handler.ts:112
dispatch @ command-registry.ts:62
(anonymous) @ keymap-manager.ts:225
_fireCallback @ C:\Users\torben\AppData\Local\Mailspring\app-1.9.1\resources\app.asar\node_modules\mousetrap\mousetrap.js:616
Mousetrap.self._handleKey @ C:\Users\torben\AppData\Local\Mailspring\app-1.9.1\resources\app.asar\node_modules\mousetrap\mousetrap.js:677
Mousetrap.handleKey @ C:\Users\torben\AppData\Local\Mailspring\app-1.9.1\resources\app.asar\node_modules\mousetrap\mousetrap.js:1008
_handleKeyEvent @ C:\Users\torben\AppData\Local\Mailspring\app-1.9.1\resources\app.asar\node_modules\mousetrap\mousetrap.js:737
mailsync-process.ts:323 Sending to mailsync 198a0537 {type: "wake-workers"}
database-store.ts:203 _executeInBackground took more than 100ms - 207msec (9msec in background):
SELECT `Thread`.`id` FROM `Thread` WHERE `id`
IN (SELECT `id` FROM `ThreadCategory` WHERE `ThreadCategory`.`value`
IN ('LkW1y...cp1ep')
AND `ThreadCategory`.`inAllMail` != 0
ORDER BY `ThreadCategory`.`lastMessageReceivedTimestamp` DESC LIMIT 200 OFFSET 0)
ORDER BY `Thread`.`lastMessageReceivedTimestamp` DESC
The mailsync logs around this look as below. Please not, that the distinction between step 3 and 4/5 is to the best of my knowledge, I’m not 100% sure here.
So, during step 3 we had this:
34656 [2021-05-02 11:23:20.528] [foreground] [info] Idle exited with code 0
34656 [2021-05-02 11:23:20.538] [foreground] [info] syncFolderChangesViaCondstore - INBOX: modseq 355417 to 355418, uidnext 94004 to 94005
34656 [2021-05-02 11:23:20.550] [foreground] [info] syncFolderChangesViaCondstore - Changes since HMODSEQ 355417: 1 changed, 0 vanished
34656 [2021-05-02 11:23:20.589] [foreground] [info] Idling on folder INBOX
34656 [2021-05-02 11:23:21.247] [foreground] [info] Idle exited with code 0
34656 [2021-05-02 11:23:21.258] [foreground] [info] syncFolderChangesViaCondstore - INBOX: modseq 355418 to 355419, uidnext 94005 to 94005
34656 [2021-05-02 11:23:21.268] [foreground] [info] syncFolderChangesViaCondstore - Changes since HMODSEQ 355418: 1 changed, 0 vanished
34656 [2021-05-02 11:23:21.269] [foreground] [info] Idling on folder INBOX
Somewhere in between the two steps I got this:
34656 [2021-05-02 11:23:57.404] [main] [info] [local-4321d339-3201] Running ChangeUnreadTask performLocal:
34656 [2021-05-02 11:23:57.408] [main] [info] [local-4321d339-3201] -- Succeeded. Changing status to `remote`
34656 [2021-05-02 11:23:57.729] [foreground] [info] Idle exited with code 0
34656 [2021-05-02 11:23:57.729] [foreground] [info] [local-4321d339-3201] Running ChangeUnreadTask performRemote:
34656 [2021-05-02 11:23:57.741] [foreground] [info] [local-4321d339-3201] -- Succeeded. Changing status to `complete`
34656 [2021-05-02 11:23:57.753] [foreground] [info] syncFolderChangesViaCondstore - INBOX: modseq 355419 to 355420, uidnext 94005 to 94005
34656 [2021-05-02 11:23:57.764] [foreground] [info] syncFolderChangesViaCondstore - Changes since HMODSEQ 355419: 1 changed, 0 vanished
34656 [2021-05-02 11:23:57.765] [foreground] [info] Idling on folder INBOX
The actual start sync should be this:
34656 [2021-05-02 11:24:00.117] [main] [info] Waking all workers...
34656 [2021-05-02 11:24:00.117] [background] [info] Marking all folders as `busy`
34656 [2021-05-02 11:24:00.128] [foreground] [info] Idle exited with code 0
34656 [2021-05-02 11:24:00.141] [background] [info] Syncing folder list...
34656 [2021-05-02 11:24:00.142] [foreground] [info] syncFolderChangesViaCondstore - INBOX: modseq 355420 to 355420, uidnext 94005 to 94005
34656 [2021-05-02 11:24:00.143] [foreground] [info] Idling on folder INBOX
34656 [2021-05-02 11:24:00.183] [background] [info] syncFolderChangesViaCondstore - INBOX: modseq 355420 to 355420, uidnext 94005 to 94005
34656 [2021-05-02 11:24:00.196] [background] [info] syncFolderChangesViaCondstore - Sent: modseq 2968 to 2969, uidnext 2630 to 2631
34656 [2021-05-02 11:24:00.220] [background] [info] syncFolderChangesViaCondstore - Changes since HMODSEQ 2968: 1 changed, 0 vanished
34656 [2021-05-02 11:24:00.220] [background] [info] - Updating message m7JETirxWYFkNjkJD7NgR813fjTGC46XzCAjcUHr7
34656 [2021-05-02 11:24:00.220] [background] [info] -- UID (94004 to 2630)
34656 [2021-05-02 11:24:00.220] [background] [info] -- FolderID (LkW1y...cp1ep to JmExT...Mf7no)
34656 [2021-05-02 11:24:00.239] [background] [info] syncFolderChangesViaCondstore - Drafts: modseq 2948 to 2948, uidnext 1083 to 1083
34656 [2021-05-02 11:24:00.250] [background] [info] syncFolderChangesViaCondstore - Archives.2021: modseq 643 to 643, uidnext 302 to 302
34656 [2021-05-02 11:24:00.262] [background] [info] syncFolderChangesViaCondstore - Trash: modseq 36515 to 36515, uidnext 28280 to 28280
34656 [2021-05-02 11:24:00.272] [background] [info] syncFolderChangesViaCondstore - Junk: modseq 82064 to 82064, uidnext 43888 to 43888
The folder “Sent” is (as you might expect) the one, where outgoing mails are archived by my Mail Clients.
After that, I’m getting a whole log messages like the following, where modseq from/to and uidnext from/to values are identical, without much mor information than that, for example:
34656 [2021-05-02 11:24:00.707] [background] [info] syncFolderChangesViaCondstore - Z1 data.folder1: modseq 1 to 1, uidnext 65 to 65
34656 [2021-05-02 11:24:00.717] [background] [info] syncFolderChangesViaCondstore - Z1 data.folder2: modseq 1 to 1, uidnext 7 to 7
34656 [2021-05-02 11:24:00.729] [background] [info] syncFolderChangesViaCondstore - Z1 data.folder3: modseq 1 to 1, uidnext 4 to 4
34656 [2021-05-02 11:24:00.739] [background] [info] syncFolderChangesViaCondstore - Z1 data.folder4: modseq 28 to 28, uidnext 21 to 21
… and ending with …
34656 [2021-05-02 11:24:02.800] [background] [info] Sync loop deleting unlinked messages with phase 2.
34656 [2021-05-02 11:24:02.812] [background] [info] Sync loop complete.
Intermixed (probably from multi-threading) I also see the following messages, they appear around folders, that haven’t been touched at least for days, no mail filters access these folders, I only use them for manual archiving:
34656 [2021-05-02 11:24:01.129] [metadataExpiration] [info] Scanning for expired metadata
34656 [2021-05-02 11:24:01.133] [metadataExpiration] [info] -- Will wake for next expiration in 7200sec
34656 [2021-05-02 11:24:02.167] [foreground] [info] Idle exited with code 0
34656 [2021-05-02 11:24:02.178] [foreground] [info] syncFolderChangesViaCondstore - INBOX: modseq 355420 to 355420, uidnext 94005 to 94005
34656 [2021-05-02 11:24:02.178] [foreground] [info] Idling on folder INBOX
34656 [2021-05-02 11:24:02.346] [background] [warning] [SLOW] Transaction=saveFolderStatus > 80ms (148ms, 0 waiting to aquire)
I don’t think that this is related to the issue at hand though.
If you need the unabbreviated logs or other information (I’ve tried to keep the hash codes good enough to correlate them), please send me a PM to torben nehmer net. Same goes for any information you might want to have from the IMAP side of things.
Best regards,
Torben Nehmer