TB128 Send Later is in rare cases triggering a TB drafts folder corruption bug, losing scheduled messages as a result

[jikamens]

According to a user:

TB v128 beta appears to have broken SL v10.4.2.

The SL icon is still visible in the header bar of the compose window but clicking on it, going to File > Send Later or using Ctrl+Shift+Enter produces no reaction.

[DaveHamilton]

SL appears to work for me in TB v128.0esr, but messages just stay in Drafts endlessly and never actually get Sent Later.

And then when I go to them, the message appears blank (or mangled) in TB, but if I go to my email provider's website (Fastmail), I can see them in their entirety and then also send. But obviously...non-optimal.

Edit: using Send Later v10.4.3. Not sure why it hadn't auto-updated to 10.5.1... doing that now.

Edit 2: 10.5.1 is no better. Things just sit in the Drafts folder. Also, I'm noticing that some email has left the drafts folder over the past few days, and gone nowhere, meaning I think I've sent emails, and I haven't. And there's no record (that I can find) of even queuing them up. Ugh.

Edit 3: Ok, here's something interesting. I left the aforementioned test message in my Drafts box. (originally queued on a "send later in 2 minutes" timer). It never sent. Then I launched Thunderbird 129.0b3 on a different Mac and, boom, it saw-and-sent the message, even though it was queued from a different machine. I can confirm that it is now in the Sent folder, and that the message was received on the other end (I sent it to a test account of mine). So this definitely seems like an issue with Send Later and TB v128. I'm not sure I want to move to the beta track on my "main" machine, but... hmmm... disabling Send Later is also non-optimal. :) Hopefully a fix is forthcoming from TB (unless you can find a magic workaround, too ;). Thanks!

[DaveHamilton]

Adding my next edit as a new comment.

With Send Later 10.5.1 and Thunderbird v128.0esr still not working on my main Mac here, I decided I would do one last test, and it worked: I completely removed Send Later, let it delete all of its associated data, quit-and-relaunched Thunderbird, and then re-installed Send Later.

I tried it first with SL's default settings (and it worked), and then I tried it with my preference personalizations (enabling "Send" delays messages by 2 minutes, and disabling Mark scheduled drafts as read). I tested after enabling each of those, and all permutations also led to success.

Seems there was something in my settings or whatever that was causing issues after the TB128 upgrade, and now I think I'm in good shape. But I'll be watching VERY carefully.

[DaveHamilton]

I might have spoken too soon. I just queued up a message, it went and put itself in Drafts with the correct future time-to-send, but the Send Later toolbar doesn't show that it's tracking it. :(

[DaveHamilton]

I haven't fully tested this, but... it sure seems like when I send a message with the Default Identity of any of my accounts, Send Later picks it up. But when I send with any of my other, non-primary/default identities (created using the Manage Identities... button), Send Later ignores those.

One trick... if I queue up three messages with non-default identities and THEN queue up one with my default identity, SL then sees all four. Tagging @jikamens here in case this bit of data is helpful. I hope it is! :)

[DaveHamilton]

OMG it's much worse than I thought. I had queued up four messages, as described in my last note. Send Later appeared to pick up all four (they were in the list), but when it sent them, it destroyed the non-default three and only delivered the one. Those other 3 messages are no longer in Drafts, no longer in Sent, no longer anywhere. No record of their existence that I can find. Sorry for the double tag, @jikamens, but I figure you'd wanna know about this data loss issue.

[jikamens]

At first glance it seems to me that a likely explanation for what you are seeing is that the storage for your Drafts folder in Thunderbird is corrupted. Please try right-clicking on that folder, opening its properties, and clicking the "Repair" button, and if that doesn't solve the problem, we will explore other possibilities.

[DaveHamilton]

At first glance it seems to me that a likely explanation for what you are seeing is that the storage for your Drafts folder in Thunderbird is corrupted. Please try right-clicking on that folder, opening its properties, and clicking the "Repair" button, and if that doesn't solve the problem, we will explore other possibilities.

That does make sense as a likely explanation. I've tested it now on two different Macs, both after Repairing the Drafts folder on each, and the behavior unfortunately remains as described above. I think there's more to troubleshoot here...happy to help!

[jikamens]

Are the missing messages in your Outbox folder under Local Folders? What kind of email accounts do you have (e.g., IMAP, POP3, Exchange, etc.)?

[DaveHamilton]

Are the missing messages in your Outbox folder under Local Folders? What kind of email accounts do you have (e.g., IMAP, POP3, Exchange, etc.)?

I have tested both with a Local Drafts folder as well as an IMAP drafts folder. Same results.

And the issue is twofold:

1. "Queued" messages are neither actually queued nor sent. This seems to affect non-default identities, but I've also seen it affect the default identity.
2. Unsent messages are occasionally just disappearing, though I had one come back 24 hours later, just sitting there in Drafts. This is happening on both clients, but not nearly as consistently as the unsent problem 1 listed above.

My Mac running the TB129 beta works flawlessly with my tests on the same accounts (IMAP Drafts box).

[jikamens]

You didn't actually answer my questions.

Again: Are the missing messages in your Outbox folder under Local Folders?

Again: What kind of email accounts do you have? Note that I didn't ask what kinds of accounts or folders you are using with Send Later. I asked what kinds of accounts you have overall.

And I don't know understand what you mean when you say that messages are "[not] actually queued."

Your last comment above seems to have made things a bit more confusing rather than less. :-/

Also, just to be clear: you're saying that you're not seeing any of these issues in TB129 beta?

This implies one of two things: either there is a Thunderbird bug in 128 that is fixed in 129, or you are using separate profiles for TB128 and TB129 and your TB128 profile is somehow corrupted in a way that is causing Send Later to malfunction.

Can you try creating a new TB128 profile and checking if you are able to reproduce the issue there?

Are you running any other extensions in the profile that is exhibiting this problem? If so, which extensions? Are you running those same extensions in your TB129 profile?

[jikamens]

To be clear, even if there's a bug in TB128 that Send Later is running into, or your TB128 profile is corrupt, I'd still like to try to track that down as much as we can so I can figure out if there's a workaround I can put into the add-on.

[jikamens]

In addition to the test of seeing if you are able to reproduce this in a newly created profile in TB128, I'd also like to capture logs from the profile that's causing problems. Please follow these instructions:

https://extended-thunder.github.io/send-later/#console-logging

On step 5 in the instructions, what I would like you to do is compose a draft, schedule it to be sent with Send Later, type "now" as the send time in the time/date text box to tell Send Later to deliver it the next time it checks for messages to be delivered, wait 60 seconds to give Send Later a chance to do that, and then finish the instructions and email the resulting log file to send-later-support@extended-thunder.org if it's less than 1MB or upload it somewhere and send me a link as described in the instructions. Thanks!

[DaveHamilton]

You didn't actually answer my questions.

Going line-by-line now. Hopefully with more clarity this time. :)

Again: Are the missing messages in your Outbox folder under Local Folders?

No, they are not. I have looked for them, searched for them, nowhere to be found. They're just...gone.

Again: What kind of email accounts do you have? Note that I didn't ask what kinds of accounts or folders you are using with Send Later. I asked what kinds of accounts you have overall.

Fastmail IMAP account.

And I don't know understand what you mean when you say that messages are "[not] actually queued."

When I queue a message for Send Later, it puts it in the appropriate Drafts folder. But (more often than not) the Send Later button in the Mailboxes header is not "badged" with a new/pending-to-be-sent message, and clicking on it yields an empty list.

There are times when it does work as intended, but the majority of the time it does not.

Also, just to be clear: you're saying that you're not seeing any of these issues in TB129 beta?

Correct.

This implies one of two things: either there is a Thunderbird bug in 128 that is fixed in 129, or you are using separate profiles for TB128 and TB129 and your TB128 profile is somehow corrupted in a way that is causing Send Later to malfunction.

I am using TB128 on two Macs, TB129beta on a third Mac. None of my Macs are running BOTH 128 and 129.

Can you try creating a new TB128 profile and checking if you are able to reproduce the issue there?

Happily can and will, but it'll be a few hours at this point. The fact that it's happening the same on two different Macs running TB128 tells me it will probably happen in a new profile, too, but I also completely embrace the troubleshooting process so as to rule out these kinds of presumptions. :)

Are you running any other extensions in the profile that is exhibiting this problem? If so, which extensions? Are you running those same extensions in your TB129 profile?

Only one, and yes, I'm running it in all three places: FileLink provider for Send. That's it.

[DaveHamilton]

Ok. I created a brand new profile on one Mac, connected it to my Fastmail IMAP/SMTP account, and sent a test message. That worked.

The ONLY change I made to TB's defaults here were to tell it (a) to only download the most recent 30 days of messages, and (b) to not download messages larger than 50KB.

Then I added Send Later, changed the default config only to (a) send after 1 minute instead of 10, and (b) mark messages in drafts as unread. Then I queued up a message. That was four minutes ago, and it hasn't sent, nor has the badge shown up in the title bar of the TB window.

Note that I have NOT (yet?) installed multiple Identities here in this new TB profile. There is only one identity.

After five minutes of the first message not being sent, I queued up a second message. This time, the Send Later badge DID appear, but only with a "1" in it (there are two messages in Drafts waiting to be sent, theoretically).

The interesting part, is that the message that shows up in the Send Later list is the FIRST message, not the second.

A minute later, the SECOND message sent. However, the first message is NO LONGER IN DRAFTS. It has been lost, near as I can tell.

What is in Drafts is a message that APPEARS to be the second message, but when I click on it, it's entirely blank in Thunderbird. If I go to Fastmail's web interface and click on it, I see the contents of the second message (the same one that was successfully sent).

So I think we've proven a few things with this test here (but I might be wrong, so please check my logic! :) —

1. This issue/bug is unrelated to multiple identities
2. Some messages are sent while others are not
3. Send Later (with TB128) doesn't always see the entire list of messages waiting to be sent.
4. If there are pending-to-be-sent messages in Drafts and a new message appears, Send Later will (sometimes/always) send the new message and delete the pending message(s?).

One bit that may be relevant: I have three messages in my drafts folder that are truly drafts, in the process of being written, etc. They are not (nor have they ever) been queued to be sent. But perhaps that's relevant for your testing, too, so I mention it.

Hopefully this test/data helps!

[DaveHamilton]

In addition to the test of seeing if you are able to reproduce this in a newly created profile in TB128, I'd also like to capture logs from the profile that's causing problems. Please follow these instructions

Test done and logs sent! I'll note that the message created during the test was also never sent (I let it wait for two minutes just to see if the second pass would grab it. It did not). Hopefully that helps!

[jikamens]

Dave and I have gone back and forth in email a few times trying to troubleshoot this further, and I'm stumped.

The root cause appears to be a TB bug. In particular, messages in Dave's Drafts folder are getting corrupted in TB while they continue to look fine on the server. This happens in both Dave's existing TB profiles and in any new profile that he creates from scratch.

I gather this wasn't happening to him with TB115, and it also is not happening to him with the TB129 beta release. This would seem to suggest that something was fixed after TB128 shipped and the fix hasn't been backported to TB128. If I could pin it down better than that I would ask the TB maintainers to backport the fix, but I've been unable to identify specifically what was fixed to refer them to.

I"m also unable to reproduce this for myself on a MacBook.

According to the Send Later telemetry I've got over 150 people using Send Later on Thunderbird 128, and at least so far, Dave is the only person to report this.

If more people start experiencing this issue then I may be able to gather enough additional data to track it down further, but with Dave being the only person experiencing it, I think I may be at a dead end.

Having said that, I'm going to reach out to Dave privately and ask if he's willing do a screen-share with me and let me play with his Thunderbird a bit to see if I can learn more from a little hands-on time.

[jobisoft]

Hi, this is John from Thunderbird's add-on team.

The ONLY change I made to TB's defaults here were to tell it (a) to only download the most recent 30 days of messages, and (b) to not download messages larger than 50KB.

Could you revert these changes in that test profile and see if that makes a difference? I want to rule out a sync issue between your fastmail server and your drafts folder.

I also would like to ask you, to re-implement these changes, but move your drafts folder to the local folders account (removing any sync issues).

What is the outcome of these tests?

Thanks, John

[jobisoft]

@jikamens : The setTimeout you added to mitigate this must be promisified, otherwise await compactDrafts() is not awaiting the actual compact, but just the trigger. The callback of the setTimeout is awaiting messenger.SL3U.compactFolder, but that is decoupled from compactDrafts(). The easiest approach is to insert an actual delay:

await new Promise(resolve => setTimeout(resolve, 1000));
for (let folder of SendLater.draftsToCompact) {
    SLStatic.debug("Compacting folder:", folder);
    await messenger.SL3U.compactFolder(folder);
}
SendLater.draftsToCompact.length = 0;

I also would be curious, if we can replace compacting-because-of the-gmail-issue altogether by a forced server sync as posted in bug 1909111: https://searchfox.org/comm-central/rev/2560a83e426451a16357264032a95790624d1b10/mail/components/extensions/test/xpcshell/test_ext_messages_move_copy_delete.js#657-668

[jikamens]

> I also would like to ask you, to re-implement these changes, but move your drafts folder to the local folders account (removing any sync issues).

@DaveHamilton will have to comment on the first test you asked him to do, but regarding the one above, we already tested with Drafts moved to Local Folders and everything works fine in that case.

[jikamens]

@jikamens : The setTimeout you added to mitigate this must be promisified, otherwise await compactDrafts() is not awaiting the actual compact, but just the trigger. The callback of the setTimeout is awaiting messenger.SL3U.compactFolder, but that is decoupled from compactDrafts(). The easiest approach is to insert an actual delay:

await new Promise(resolve => setTimeout(resolve, 1000));
for (let folder of SendLater.draftsToCompact) {
    SLStatic.debug("Compacting folder:", folder);
    await messenger.SL3U.compactFolder(folder);
}
SendLater.draftsToCompact.length = 0;

I don't understand what you are saying here. The setTimeout I added delays for 1000ms the execution of the code that calls compactFolder, which was the intent, and it works. With that change @DaveHamilton has confirmed that the problem reliably goes away.

I am aware that the await compactDrafts returns immediately, but it's specifically the call to messenger.SL3U.compactFolder that is causing the corruption issues, and that runs asynchronously in the background after a 100ms delay.

I also would be curious, if we can replace compacting-because-of the-gmail-issue altogether by a forced server sync as posted in bug 1909111: https://searchfox.org/comm-central/rev/2560a83e426451a16357264032a95790624d1b10/mail/components/extensions/test/xpcshell/test_ext_messages_move_copy_delete.js#657-668

I looked at the code you referenced and I do not understand what it is doing or how it is doing it well enough to understand how to integrate what you are suggesting into Send Later.

[jobisoft]

I am aware that the await compactDrafts returns immediately, but it's specifically the call to messenger.SL3U.compactFolder that is causing the corruption issues, and that runs asynchronously in the background after a 100ms delay.

Exactly, that is the important part: await compactsDrafts() is not awaiting the delay and the compact at all. Before the change, it did await the compact.

It is known to be bad practice to mix async/await with non-promisified setTimeout(). It is unexpected, that the call to await compactsDrafts() is not doing what it is literally saying. The code which runs after this call is executed before the compact has been finished (or even started).

As a rule of thumb: You should not have non-promisified setTimeout() calls in async functions. And if you DO, then the behaviour should be clearly documented. For example, the function could be renamed to triggerDraftsCompact() and not be awaited.

This might seem like a minor nit, but it is really the cause of many hard-to-track glitches.

[jikamens]

I'll tell you what: I'll put the code back to acting synchronously when the Thunderbird team has fixed bug that's causing the corruption and making the asynchronous operation necessary. In the meantime, since my change to work around this issue is just that, a temporary workaround, I'm going to make the change as small and limited in scope as possible. Changing a function name that I'll just have to change back later when the workaround is no longer needed would therefore be excessive.

It appears that all you're concerned about regarding this is a semantic issue regarding how I named a function, and I would rather this issue ticket not get bogged down discussing that semantic issue rather than focusing on the real issue which is that Thunderbird is corrupting its local copy of a folder.

The only "glitch" here is that Thunderbird needs to be resilient against both synchronous and asynchronous actions by add-ons.

[DaveHamilton]

The ONLY change I made to TB's defaults here were to tell it (a) to only download the most recent 30 days of messages, and (b) to not download messages larger than 50KB.

Could you revert these changes in that test profile and see if that makes a difference? I want to rule out a sync issue between your fastmail server and your drafts folder.

I could, but it would take a LONG time to sync my Fastmail or my Gmail profile (we tested with both, independently, and got the same results).

I don't think it has anything to do with the 30 days/50KB settings, though, because my primary/default Thunderbird profile has those options disabled (with Thunderbird downloading everything), and that's where I first noticed this problem (on two completely different Macs).

[jobisoft]

@DaveHamilton

I don't think it has anything to do with the 30 days/50KB settings, though, because my primary/default Thunderbird profile has those options disabled (with Thunderbird downloading everything), and that's where I first noticed this problem (on two completely different Macs).

Thanks for your feedback. The test is then not needed, of course. And it looks like you already tested with a local drafts folder, and that worked.

[DaveHamilton]

New information:

This bug is reproducible (by me, anyway) on both 128.0.1esr as well as 129.0b5. I couldn't find an installer for 115 with which to test, though.

The trick to making it happen is to install Send Later plugin (10.5.1), go into Send Later preferences, and uncheck the "Mark scheduled drafts as read" box. Then schedule a message to be sent later and, boom, it's corrupted. Leaving it as the default with that box checked (and schedules drafts marked as read) seems to keep the message uncorrupted.

I tested this in a brand new user account on my Mac, and with brand new profiles for Thunderbird.

Happy to test more, of course.

[jikamens]

I've pushed version 10.5.2 to addons.thunderbird.net with a workaround for this issue. It introduces a one-second delay before the folder compact which seems to prevent the corrupting from occurring. I'm going to leave this ticket open because I hope to eventually be able to remove the workaround.

[jikamens]

This is the Thunderbird bug we're waiting on: https://bugzilla.mozilla.org/show_bug.cgi?id=1909111

[jikamens]

sigh I now have a report of this happening on Windows 10, not just on macOS, and the workaround implemented in v10.5.2 isn't working for them.