Mail sent using "Send later" never leaves Thunderbird

[padelt]

Pinned note from @jperryhouts about the current status of this issue:

At long last it looks like we have a promising solution for the bug, which is available in the latest release version (8.4.4 as of this comment).

If you are experiencing this bug, please give that release version a try and post here if you are still having problems. I hope to have this version available via addons.thunderbird.net as soon as possible.

---

Running on Thunderbird 78.2.2 (32-Bit). When I compose a message, I have the "Später Senden" (Sent Later) button on the top right. Clicking it show the expected UI: The mail is saved to the drafts folder as expected. I cannot find the column for the "send time" in the Drafts folder of two different mail servers (a hosted one by Hosteurope and on self-hosted Dovecot): When I look in the headers of the draft mail, I see this (redacted some values):

FCC: imap://user%40domain.name.net@domain.name.net/Sent
X-Identity-Key: id2
X-Account-Key: account3
BCC: my-default-bcc@domain.name.net
From: User Name <info@domain.name.net>
Subject: My Subject
To: Destination User <user@destination.com>
References: <XXX@destination.com>
Message-ID: <YYY@domain.name.net>
X-Send-Later-At: 2020-09-24T09:51:00+02:00
X-Send-Later-Recur: none
X-Enigmail-Draft-Status: N00200
Date: Thu, 24 Sep 2020 09:50:27 +0200
X-Mozilla-Draft-Info: internal/draft; vcard=0; receipt=0; DSN=0; uuencode=0;
 attachmentreminder=0; deliveryformat=4
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101
 Thunderbird/78.2.2
MIME-Version: 1.0
In-Reply-To: <XXX@destination.com>
Content-Type: text/html; charset=utf-8
Content-Language: de-DE
Content-Transfer-Encoding: 8bit

Problem is: The mail never leaves Thunderbird. It just sits there. "Never" means: I have let it sit for 12-24h and it is still there.

The error console (ctrl+shift+j): further down:

I tried disabling Enigmail and restarting Thunderbird. Also tried disabling OpenPGP for the accounts. Neither made a difference.

Is there anything I can do to help diagnosing/debugging/fixing this?

[padelt]

Digging some more, I came accross log entries that might have a relevant error message ("Could not get full message contents"):

aMsgHdr is null MimeMessage.jsm:185
    MsgHdrToMimeMessage resource:///modules/gloda/MimeMessage.jsm:185
    getFull chrome://messenger/content/parent/ext-messages.js:208
    getFull chrome://messenger/content/parent/ext-messages.js:206
    getFull self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    InterpretGeneratorResume self-hosted:1151
    AsyncFunctionNext self-hosted:693
ERROR [SendLater]: Could not get full message contents Error: An unexpected error occurred static.js:15:13
    logger moz-extension://49ca89d2-8ede-472f-aa9f-4a99a43bcb89/utils/static.js:15
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMsgMessageService.streamMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/gloda/MimeMessage.jsm :: MsgHdrToMimeMessage :: line 233"  data: no] 2 MimeMessage.jsm:233:16
    MsgHdrToMimeMessage resource:///modules/gloda/MimeMessage.jsm:233
    getFull chrome://messenger/content/parent/ext-messages.js:208
    getFull chrome://messenger/content/parent/ext-messages.js:206
    getFull self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    AsyncFunctionNext self-hosted:693

[jperryhouts]

The Drafts folder column is on my to-do list. I'll hopefully finish that soon, because it's apparently a bigger problem than I expected for people.

As for the other problem, it looks like something is preventing Send Later from reading its draft message. This may be related to #15 which remains a mystery to me.

One clue might come from this Thunderbird bug which references an old Stack Overflow thread showing a similar error when accessing a shared IMAP account from two machines simultaneously. That seems unlikely if you experienced identical behavior on two separate servers, but is there a chance you have two computers both accessing these accounts at once?

[padelt]

Hey @jperryhouts , thank you for your answer and work on Send Later!

The bug you mentioned could have been caused by an IMAP server not handling another one connection coming in while trying to read the mail. That's pure speculation of course.

I tried some more: Putting Thunderbird in offline mode, then preparing a mail to be sent later, then going into online mode seems to have triggered sending, but then that mail is stuck in the "outbox"(?) with a strange error in a popup from the (otherwise working) SMTP server complaining about policy violations - maybe from missing headers?!

Anyway, then I went to the console and tried this:

messenger = Cc["@mozilla.org/messenger;1"].createInstance(Ci.nsIMessenger);
messenger.msgHdrFromURI("imap://user%40domain.name@mail.server.name:993/fetch%3EUlD%3E.Sent%3E10016")
Uncaught 
Exception
​
columnNumber: 0
​
data: null
​
filename: "debugger eval code"
​
lineNumber: 1
​
location: XPCWrappedNative_NoHelper { QueryInterface: QueryInterface(), filename: Getter, name: Getter, … }
​
message: "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMessenger.msgHdrFromURI]"
​
name: "NS_ERROR_FAILURE"
​
result: 2147500037
​
stack: "@debugger eval code:1:11\ngetEvalResult@resource://devtools/server/actors/webconsole/eval-with-debugger.js:231:24\nexports.evalWithDebugger@resource://devtools/server/actors/webconsole/eval-with-debugger.js:162:14\nevaluateJS@resource://devtools/server/actors/webconsole.js:1134:38\nevaluateJSAsync/<@resource://devtools/server/actors/webconsole.js:1028:29\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:103:22\n"
​
<prototype>: ExceptionPrototype { toString: toString(), name: Getter, message: Getter, … }

The URI I copied from the title of the "source view" of an actual message.

Then I poked around and got to this:

uri = messenger.getMsgUriAtNavigatePos(0);
"imap-message://user%40domain.name@mail.server.name/Sent#10016"
messenger.msgHdrFromURI("imap-message://user%40domain.name@mail.server.name/Sent#10016")
XPCWrappedNative_NoHelper { folder: Getter, messageKey: Getter & Setter, flags: Getter & Setter, getUint32Property: getUint32Property(), recipients: Getter & Setter, ccList: Getter & Setter, getStringProperty: getStringProperty(), label: Getter & Setter, author: Getter & Setter, getProperty: getProperty(), … }

So this URI didn't work: imap://user%40domain.name@mail.server.name:993/fetch%3EUlD%3E.Sent%3E10016 but this works: imap-message://user%40domain.name@mail.server.name/Sent#10016

The only thing I can deduce from that is that there is a way to access the mail headers using this message URI, but maybe it helps or inspires some thought.

Could you add some debugging information in the code path leading to this issue so I can somehow help diagnose this?

[jperryhouts]

It's interesting that the message is working after being saved in offline mode. I'm not sure how to piece it all together at the moment. The behaviors you're seeing are associated with seemingly independent pieces of code.

For reference, the sequence of send later operations looks something like the following:

1. Schedule a message by adding special headers to the message being composed, and then saving it as a draft. This seems to be working fine, since you were able to see the message show up in Drafts, and it had the correct x-send-later-... headers.
2. Periodically, check for scheduled messages, and actually perform the send operation if necessary. This involves:
   • Loop over all folders to find ones tagged for drafts
   • Loop over all messages in each drafts folder, and check its headers for x-send-later-at (reading these headers seems to be the source of the original error)
   • If the send-later headers are present, then evaluate whether the message is due for sending.
3. If a message is ready to be sent, then a complicated sequence of things happens:
   • A new message is constructed, the original message's headers and content are copied over (minus the x-send-later ones),
   • That message is dropped into the outbox,
   • Thunderbird is notified to actually perform the send operation on anything in the outbox.

Part 2 is entirely implemented using the modern style Thunderbird extension API, which never interacts directly with any IMAP URI's, because it should be agnostic to the account backend. Part 1 and 3 involve workarounds using "experiments" that bypass the API because it is missing key features. Specifically, modifying headers, saving to drafts, and initiating a send are not yet part of the official API.

Part 2 is the piece that may be affected by the bug I mentioned before. Unfortunately, the extension API is still very immature, and has been really buggy, which affects important functionality. It surprises me that scheduling the draft in offline mode makes a difference, since part 1 seems to be working anyway.

My only thought at the moment is that maybe Send Later actually executes step 2 (and 3) while you're still in offline mode, it could drop the message into the outbox, and tell Thunderbird to send it, but Thunderbird cannot because it is still offline. That wouldn't explain the SMTP error, but it would at least explain how the message can get through steps 2 and 3 in some cases but not others.

[padelt]

Not sure if I'm even going in the right direction, but I just tried compressing and/or repairing the msf-file of the Draft folder. This gave me an unexpected error (that most certainly has nothing to do with Send Later):

15:12:40.277 2020-09-30 15:12:40    gloda.index_msg ERROR   Exception while attempting to mark message with gloda state afterdb commit [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMsgDBHdr.getUint32Property]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource:///modules/gloda/IndexMsg.jsm :: _commitCallback :: line 159"  data: no]
Log4moz.jsm:766
    append resource:///modules/gloda/Log4moz.jsm:766
    log resource:///modules/gloda/Log4moz.jsm:416
    error resource:///modules/gloda/Log4moz.jsm:424
    _commitCallback resource:///modules/gloda/IndexMsg.jsm:178
    handleCompletion resource:///modules/gloda/GlodaDatastore.jsm:63
    editFolder chrome://messenger/content/folderPane.js:3098
    oncommand chrome://messenger/content/messenger.xhtml:1
15:12:40.277 2020-09-30 15:12:40    gloda.index_msg ERROR   Exception while attempting to mark message with gloda state afterdb commit [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMsgDBHdr.getUint32Property]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource:///modules/gloda/IndexMsg.jsm :: _commitCallback :: line 159"  data: no]

Then I deleted the only, very old (~1 year) message from the Drafts folder and did it again -> no error. Put in a draft and did it again -> no error.

Then I added a message to be sent later and... a different error!

15:35:15.629 INFO [SendLater]: Sending message <00b075d9-1e97-4569-b0d7-8cd19a258b20@domain.name>. static.js:15:13
15:35:15.719
/\nX-Identity-Key:\s*(\S+)/i.exec(...) is null sl3u.js:329
    sendRaw jar:file:///D:/Thunderbird/zh7ot1a7.default/extensions/jph@extended-thunder.org.xpi!/experiments/sl3u.js:329
    sendRaw self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    AsyncFunctionNext self-hosted:693

The first two lines of the message:

X-Identity-Key: id12
X-Account-Key: account31

That regex expects the X-Identity-Key to not be on the first line. If it is on the second line, it works:

c1 = "X-Identity-Key: id12\nX-Account-Key: account31\n"
c2 = "X-Account-Key: account31\nX-Identity-Key: id12\n"
/\nX-Identity-Key:\s*(\S+)/i.exec(c1)
null
/\nX-Identity-Key:\s*(\S+)/i.exec(c2)
Array [ "\nX-Identity-Key: id12", "id12" ]

Changing the regex like this seems to fix it (in the console):

/(?:^|\n)X-Identity-Key:\s*(\S+)/i.exec(c1)
Array [ "X-Identity-Key: id12", "id12" ]

/(?:^|\n)X-Identity-Key:\s*(\S+)/i.exec(c2)
Array [ "\nX-Identity-Key: id12", "id12" ]

[jperryhouts]

Thank you for tracking that down. That regex logic was inherited from the legacy code, because it's easier to replace \nkey: old value -> \nkey: new value without requiring a special case when the header happens to be the first line, as you experienced here. Presumably a ^ would serve the same purpose, but there's a long comment in the legacy code about why it was implemented this way so I didn't change it. Anyhow, that should be fixed in #24

I also fixed the date-time formatting as mentioned in #18 which might help with some of the problems you've been experiencing (hopefully will fix the SMTP rejection at the very least). I still don't know what to think of this failure code: 0x80004005 (NS_ERROR_FAILURE), but maybe those bug fixes will make a difference somehow.

Give the new version a try, and let me know if it changes anything for you.
https://github.com/Extended-Thunder/send-later/raw/master/release/send_later-8.0.5-tb.xpi

[jperryhouts]

I was just in touch with another user who had the same error, and the newest release seems to have solved it for him. I don't know why exactly, but it could be that the 0x80004005 error is not the problem here at all. I'm hoping that the 8.0.5 release does the trick somehow.

[padelt]

I am now on 78.3.2 (32-Bit) and that did not solve the problem for me. Experimenting some more I found that repeatedly repairing/compacting the folder did something. Nothing reproducible though. Things I also tried that didn't make an obvious difference:

• recreating the drafts folder
• installing the English (US) version of Thunderbird
• installing the 64-Bit version of Thunderbird Yet, sometimes it works. I will keep watching it.

[polhenarejos]

I updated to 8.0.7 and the problem still persists. Thunderbird 78.3.3. The only message I got in the console is ERROR [SendLater]: Error: An unexpected error occurred static.js:15:13 Uncaught (in promise) Error: An unexpected error occurred

[jperryhouts]

Since this has been hard to reproduce for me, I'm not positive this will solve the problem, but I discovered a problem with the way Thunderbird indexes messages that could cause this behavior in certain cases.

For me, it only happened if I scheduled a message, then edited and re-scheduled it. The message would go back into the Drafts folder with the new headers, but Thunderbird would not index it (or would not make the properly indexed version available to extensions), presumably because the message ID hadn't changed. Hopefully that behavior is fixed by #43.

The update is available in release v8.0.9 along with other minor bugfixes.

[jperryhouts]

In the latest release (8.0.15), I have imported most of the code for sending messages directly from the legacy branch. The only significant change that has is in cases where the outbox is triggered more than once in a row. In prior beta versions (<=8.0.12) that may have only triggered a single send operation.

The result of that would be that if you scheduled four messages to send at the same time, three of them may end up stuck in the outbox until the next time a message is sent by send later.

I'm not sure that really describes this bug, but it could be related. There are also a number of other bug fixes in 8.0.13 that should improve reliability in general.

[jperryhouts]

I took down the previous release after two bug reports (which were unrelated to that release, as it turns out), but the latest version has lots of improvements that I really hope will improve reliability of the send function, in addition to lots of other miscellaneous improvements. I'm hoping that the latest beta release is the final beta release before this goes live on addons.thunderbird.net, so let me know if this bug still exists.

Thanks again for bearing with be during this transition.

[pat-vu]

I have the same issue as described by Padelt on Sept 24 on the top pf this thread, i.e., the mail is saved to the drafts folder as expected but is never sent.

I just upgraded to Thunderbird 78 a couple of days ago, installed the latest beta release of SEndLater today, and also restored a few archives mails in the local directories with the BackUp toolbox (all previous folders were restored without problems).

Is there something else I can / should do ?

[jperryhouts]

All I know at this time is that there is something preventing Thunderbird from reading messages in those folders. I am increasingly convinced that it is related to Thunderbird bug 1623685.

If that is the case, it would only cause problems via the Thunderbird extension API -- e.g. I would bet that you do see the schedule appear in the send later column within the Drafts folder, which bypasses the proper API.

If that is the case it's hard to do anything about it right now. Ideally Thunderbird would address that bug, but since they don't seem to be working on it I might have to roll a custom "experiment" function to get around this. If this is completely blocking Send Later from working for some users that's a high priority for me.

I plan to release the current beta branch to production this week, which will not include any such fix, but this will be next on my agenda when that is out.

[pat-vu]

Thanks!

Yes indeed I do see the schedule in the send later column within the Drafts folder.

And also this is for an account on office365.

Thanks again for your efforts.

---- Jonathan Perry-Houts a écrit ----

All I know at this time is that there is something preventing Thunderbird from reading messages in those folders. I am increasingly convinced that it is related to Thunderbird bug 1623685https://bugzilla.mozilla.org/show_bug.cgi?id=1623685.

If that is the case, it would only cause problems via the Thunderbird extension API -- e.g. I would bet that you do see the schedule appear in the send later column within the Drafts folder, which bypasses the proper API.

If that is the case it's hard to do anything about it right now. Ideally Thunderbird would address that bug, but since they don't seem to be working on it I might have to roll a custom "experiment" function to get around this. If this is completely blocking Send Later from working for some users that's a high priority for me.

I plan to release the current beta branch to production this week, which will not include any such fix, but this will be next on my agenda when that is out.

— You are receiving this because you commented. Reply to this email directly, view it on GitHubhttps://github.com/Extended-Thunder/send-later/issues/16#issuecomment-721387682, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ART23EEWYPTXDNG3NFT4CTLSOBZ5FANCNFSM4RX7RTJQ.

[jperryhouts]

There appears to be movement on this on the Thunderbird side! But the developers need help tracking down the problem since they are also unable to reproduce this behavior in version 78.

@padelt or anyone else, would you be willing to help the Thunderbird devs track this down? Github won't let me post .xpi files in comments, but there's a dummy addon that one of the TB devs posted to the bugzilla report which just dumps selected messages to console using the affected API. If you could test that out and send some debug logs either here or via Bugzilla it could really help accelerate this.

[jobisoft]

I can read & comment here as well, so if you do not want to get a bugzilla account just for this, that will be fine.

@jperryhouts : You can post zip files, which can be installed in TB directly. The XPI suffix is just cosmetics.

[jobisoft]

Here is that test add-on:

messageDisplay.zip

[padelt]

Sure, I'd be glad to help. I installed the plugin and now see in the Error Console that opening/clicking a message leads to two console entries:

08:13:17.481 Message displayed in tab 1: [Extended-Thunder/send-later] Mail sent using "Send later" never leaves Thunderbird (#16) background.js:2:11
08:13:17.502 Object { contentType: "message/rfc822", headers: {…}, partName: "", size: 1611, parts: (1) […] }

I could also copy the whole object, but that would need heavy cleaning to not expose private information publicly. If you are interested in the detailed objects, I can also send it to you via email unredacted.

After the initial mail above, I created several drafts with and without send later settings and clicked on them. No immediate errors were logged. Here is a (redacted) example of clicking a draft mail in my work account:

08:14:56.324 Message displayed in tab 1: Draft WITH SendLater background.js:2:11
08:14:56.339
{…}
contentType: "message/rfc822"
headers: {…}
​​bcc: Array [ "REMOVED@EMAIL.DOMAIN.PERSONAL" ]
​​"content-language": Array [ "en-US" ]
​​"content-transfer-encoding": Array [ "8bit" ]
​​"content-type": Array [ "text/plain; charset=utf-8; format=flowed" ]
​​date: Array [ "Thu, 5 Nov 2020 08:14:41 +0100" ]
​​from: Array [ "OWN NAME <EMAILUSER@WORK.DOMAIN>" ]
​​"message-id": Array [ "<c2d19a62-899d-214e-82b1-62e83152f714@WORK.DOMAIN>" ]
​​"mime-version": Array [ "1.0" ]
​​subject: Array [ "Draft WITH SendLater" ]
​​to: Array [ "OWN NAME <EMAILUSER@WORK.DOMAIN>" ]
​​"user-agent": Array [ "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101 Thunderbird/78.4.0" ]
​​"x-account-key": Array [ "account31" ]
​​"x-identity-key": Array [ "id12" ]
​​"x-mozilla-draft-info": Array [ "internal/draft; vcard=0; receipt=0; DSN=0; uuencode=0; attachmentreminder=0; deliveryformat=4" ]
​​"x-send-later-at": Array [ "Thu, 05 Nov 2020 10:14:40 +0100" ]
​​"x-send-later-recur": Array [ "none" ]
​​<prototype>: Object { … }
partName: ""
parts: (1) […]
0: Object { body: "\r\n-- \r\REMOVED\r\n\r\n", contentType: "text/plain", partName: "1", … }
length: 1
<prototype>: Array []
size: 301
<prototype>: Object { … }

I have tried to reproduce the problem of this issue twice and it did not come up. Those mails were sent as expected.

While composing two drafts, it generated the following errors. Sending later worked though:

11:28:07.919 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:28:07.947 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:28:25.090 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:28:25.121 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:28:35.047 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
11:28:35.974
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMsgMessageService.streamMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/gloda/MimeMessage.jsm :: MsgHdrToMimeMessage :: line 233"  data: no] 2 MimeMessage.jsm:233:16
    MsgHdrToMimeMessage resource:///modules/gloda/MimeMessage.jsm:233
    getFull chrome://messenger/content/parent/ext-messages.js:208
    getFull chrome://messenger/content/parent/ext-messages.js:206
    getFull self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    AsyncFunctionNext self-hosted:693
11:28:35.981 Uncaught (in promise) Error: An unexpected error occurred undefined
11:28:35.982
ERROR [SendLater]: Error: An unexpected error occurred static.js:29:13
    logger moz-extension://647e3a1e-933c-47f2-886c-f86e50118320/utils/static.js:29
11:28:36.816
Uncaught (in promise) TypeError: schedule.recur is undefined
    attachListeners moz-extension://647e3a1e-933c-47f2-886c-f86e50118320/ui/popup.js:375
popup.js:375:11
    attachListeners moz-extension://647e3a1e-933c-47f2-886c-f86e50118320/ui/popup.js:376
    AsyncFunctionNext self-hosted:693
11:28:38.385
TypeError: browser is null
BrowserElementParent.jsm:81:21
    receiveMessage resource://gre/actors/BrowserElementParent.jsm:81
11:28:40.290 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:28:40.318 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:28:43.512
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMsgMessageService.streamMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/gloda/MimeMessage.jsm :: MsgHdrToMimeMessage :: line 233"  data: no] 2 MimeMessage.jsm:233:16
    MsgHdrToMimeMessage resource:///modules/gloda/MimeMessage.jsm:233
    getFull chrome://messenger/content/parent/ext-messages.js:208
    getFull chrome://messenger/content/parent/ext-messages.js:206
    getFull self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    AsyncFunctionNext self-hosted:693
11:28:43.514 Uncaught (in promise) Error: An unexpected error occurred undefined
11:28:49.645 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
11:28:50.838
TypeError: browser is null
BrowserElementParent.jsm:81:21
    receiveMessage resource://gre/actors/BrowserElementParent.jsm:81
11:28:55.860
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMsgMessageService.streamMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/gloda/MimeMessage.jsm :: MsgHdrToMimeMessage :: line 233"  data: no] 3 MimeMessage.jsm:233:16
    MsgHdrToMimeMessage resource:///modules/gloda/MimeMessage.jsm:233
    getFull chrome://messenger/content/parent/ext-messages.js:208
    getFull chrome://messenger/content/parent/ext-messages.js:206
    getFull self-hosted:844
    result resource://gre/modules/ExtensionParent.jsm:996
    withPendingBrowser resource://gre/modules/ExtensionParent.jsm:602
    result resource://gre/modules/ExtensionParent.jsm:996
    callAndLog resource://gre/modules/ExtensionParent.jsm:958
    recvAPICall resource://gre/modules/ExtensionParent.jsm:995
    InterpretGeneratorResume self-hosted:1151
    AsyncFunctionNext self-hosted:693
11:28:55.866 Uncaught (in promise) Error: An unexpected error occurred undefined
11:29:06.776 DEBUG [SendLater]: Entering function SendLaterHeaderView.columnHandlerObserver.observe static.js:29:13
11:29:06.777 INFO [SendLater]: Adding column handler for sendlater-colXSendLaterAt static.js:29:13
11:29:06.777 DEBUG [SendLater]: Leaving function SendLaterHeaderView.columnHandlerObserver.observe static.js:29:13

Later tests showed some (maybe unrelated) errors:

11:35:21.716 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:35:21.756 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:35:36.608 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
11:35:39.468 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:35:39.496 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:35:51.859 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
11:35:57.462 WebExtensions: Binding to send later events like a barnicle. sl3u.js:909
11:35:57.494 window.controllers/Controllers is deprecated. Do not use it for UA detection. blank
11:36:59.191
GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 72ms]

11:36:59.191
GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 80ms]

11:38:02.568
GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 27ms]

11:38:02.568
GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 19ms]

11:40:36.140 WebExtensions: Saving message to C:\Users\pa\AppData\Local\Temp\tempMsg7.eml sl3u.js:124
11:40:36.149 WebExtensions: [SendLater]: Entering CopyUnsentListener.QueryInterface sl3u.js:666
11:40:36.150 WebExtensions: [SendLater]: Returingn copyServiceListener.QueryInterface 
Object { _sendUnsentMsgs: true, localFile: XPCWrappedNative_NoHelper }
sl3u.js:669
11:40:36.858 WebExtensions: Failed to delete C:\Users\pa\AppData\Local\Temp\tempMsg7.eml.Trying again with waitAndDelete. sl3u.js:685
11:40:36.859 WebExtensions: Successfully copied message to outbox. sl3u.js:691
11:40:36.859 WebExtensions: Triggering send unsent messages. sl3u.js:693
11:40:36.861 WebExtensions: Saving message to C:\Users\pa\AppData\Local\Temp\tempMsg8.eml sl3u.js:124
11:40:36.866 WebExtensions: [SendLater]: Entering CopyUnsentListener.QueryInterface sl3u.js:666
11:40:36.866 WebExtensions: [SendLater]: Returingn copyServiceListener.QueryInterface 
Object { _sendUnsentMsgs: true, localFile: XPCWrappedNative_NoHelper }
sl3u.js:669
11:40:37.576 WebExtensions: Failed to delete C:\Users\pa\AppData\Local\Temp\tempMsg8.eml.Trying again with waitAndDelete. sl3u.js:685
11:40:37.577 WebExtensions: Successfully copied message to outbox. sl3u.js:691
11:40:37.578 WebExtensions: Triggering send unsent messages. sl3u.js:693
11:40:37.590 WebExtensions: Successfully deleted queued C:\Users\pa\AppData\Local\Temp\tempMsg7.eml sl3u.js:32
11:40:37.831 WebExtensions: Successfully deleted queued C:\Users\pa\AppData\Local\Temp\tempMsg8.eml sl3u.js:32
11:40:37.889 WebExtensions: Entering function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStartSending sl3u.js:293
11:40:37.889 WebExtensions: Leaving function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStartSending sl3u.js:296
11:40:38.587 WebExtensions: Deferring sendUnsentMessages sl3u.js:102
11:40:38.968 WebExtensions: Entering function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStopSending sl3u.js:293
11:40:38.969 WebExtensions: Entering function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStartSending sl3u.js:293
11:40:38.969 WebExtensions: Leaving function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStartSending sl3u.js:296
11:40:38.969
2020-11-05 11:40:38 sendLaterModule ERROR   onStartSending called with zero messages

Log4moz.jsm:766
    append resource:///modules/gloda/Log4moz.jsm:766
    log resource:///modules/gloda/Log4moz.jsm:416
    error resource:///modules/gloda/Log4moz.jsm:424
    onStartSending resource:///modules/activity/sendLater.jsm:169
    onStopSending jar:file:///D:/Thunderbird/zh7ot1a7.default/extensions/sendlater3@kamens.us.xpi!/experiments/sl3u.js:342
11:40:38.969 2020-11-05 11:40:38    sendLaterModule ERROR   onStartSending called with zero messages

11:40:38.969
TypeError: this._copyProcess is null
sendLater.jsm:233:13
    onMessageSendProgress resource:///modules/activity/sendLater.jsm:233
    onStopSending jar:file:///D:/Thunderbird/zh7ot1a7.default/extensions/sendlater3@kamens.us.xpi!/experiments/sl3u.js:342
11:40:38.976 WebExtensions: Entering function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStopSending sl3u.js:293
11:40:38.976 WebExtensions: Leaving function: Sendlater3Backgrounding.sendUnsentMessagesListener.onStopSending 2 sl3u.js:296
11:43:53.800
GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 63ms]

If you need more/other information, please let me know!

[jobisoft]

Can someone point me to the getFull() call in the source of the add-on, which triggers this error? From the trace I was not able to find it.

[jperryhouts]

I believe it is here: https://github.com/Extended-Thunder/send-later/blob/a354842d20343f8a3cadcf84f5b253ed7db7e382/background.js#L159

Send Later performs a loop periodically which first finds all draft folders, then loop over each message in each drafts folder and opens it with getFull to inspect the headers. The process of inspecting each message happens in an asynchronous function call, so maybe multiple simultaneous getFull calls is the culprit? I'm just spitballing here, I'm still not fully awake today.

@padelt Thank you for the testing. The last set of error messages you saw are unrelated, and are fixed in the latest main branch. They're harmless though as far as I can tell.

[padelt]

With lots of ugly instrumentation I could find out: https://github.com/Extended-Thunder/send-later/blob/8.0.15-rc2/background.js#L159 In this situation id is 1. I'm pretty sure it is called from here: https://github.com/Extended-Thunder/send-later/blob/8.0.15-rc2/background.js#L72 message is this (redacted):

{
  "id": 1,
  "date": "2020-11-05T10:28:21.000Z",
  "author": "USER NAME<email@address>",
  "recipients": [
    "USER NAME<email@address>"
  ],
  "ccList": [],
  "bccList": [
    "somewhere@example.com"
  ],
  "subject": "Simple draft",
  "read": false,
  "flagged": false,
  "junk": false,
  "junkScore": 0,
  "folder": {
    "accountId": "account31",
    "name": "Drafts",
    "path": "/Drafts",
    "type": "drafts"
  },
  "tags": []
}

message contains reasonable data, but the id with value 1 seems really strange since it is used for browser.messages.getFull(1). The message with that ID seems to come from here via browser.messages.list(drafts): https://github.com/Extended-Thunder/send-later/blob/8.0.15-rc2/background.js#L69

BTW: How do more knowledgeable people than me debug such a situation? Is there no easy way to see the caller of a callback..?

[jperryhouts]

The way Thunderbird makes those id's is weird. They reset per folder per session, so I'm pretty sure a message ID of 1 isn't unusual.

[padelt]

Well if they are per folder and per session, where is that information in the call to getFull? If it is in browser.messages, I‘d suggest a race condition in Thunderbird. Maybe I see that problem because I have multiple Accounts and multiple Drafts folders. While debugging I‘ve seen really confusing asynchronous calls to the various functions. If reading a message list and acting upon the embedded message IDs needs to not be „interrupted“ by, say, another message list read (of another folder) to be consistent, then the current behavior would somehow make sense. Then synchronizing the process (one folder after the other) would help.

[jobisoft]

That is some nice written code you got there.

As I have understood those message IDs, they are globally unique (but not persistent). So you do not need to worry about folders and accounts.

I will try to create an add-on using some of your code to reproduce the error.

What I saw is, that sometimes you await your SendLater.forAllDrafts() and sometime you don't. Do not know if that is intended. Here for example

https://github.com/Extended-Thunder/send-later/blob/a354842d20343f8a3cadcf84f5b253ed7db7e382/background.js#L87

The function markDraftsRead() will return before all messages are marked. Your main loop does the same.

That results in a lot of (pseudo) parallel requests. Could be related, even though the API should be able to cope with that.

John

[padelt]

John, just to be sure: Not my code. Just a fan and user of SendLater.

Really hope you can shed some light into this. If I can somehow help, I‘d be happy to!

[jperryhouts]

The "asynchronous" code (and all javascript) should be completely thread safe, but if there's something internal to Thunderbird that doesn't like responding to multiple getFull requests at once I could see that causing trouble.

When I initially wrote the forAllDrafts(callback) function it was meant to be run asynchronously, because the calling function usually didn't care about the result of the callback. But there are some cases where it actually does matter, like counting how many drafts have send-later headers, so in those cases the calling function will await the results. But even in those cases, it will execute the callback asynchronously and then wait for all the promises to resolve, rather than processing each one sequentially.

Changing that to await each callback function in sequence would be fine if that fixes this bug, since I don't think those API calls are performance bottlenecks or anything. But if that is the problem here this wouldn't really be a solution, since there could still be other extensions awaiting getFull requests which could cause the same behavior.

[jobisoft]

This is exactly what I want to try: a) strip down your add-on to have a clean way to reproduce the error b) see if serializing the calls fixes the error (with only that add-on installed) c) understand why

I will report back.

[jperryhouts]

Great. Thank you! Let me know if there's anything I can do to help.

[jperryhouts]

I switched Send Later to prefer pseudo-sequential logic in places where it loops over messages. This should prevent it from requesting multiple getFull() api calls in very close succession. I also switched from getFull to getRaw in several places to avoid unnecessary MIME parsing, and reduce the number of API calls over all.

It of course does not prevent other plugins from using those api's, but if that really is the source of the problem then this should help mitigate its effects.

These changes are part of the latest beta release (v8.0.16).

[jperryhouts]

93 removes all remaining uses of getFull, in favor of getRaw and basic regular expression parsing. If the culprit is indeed something about getFull, this will definitely solve the bug, and if the bug persists we'll know we've been off base with that.

~~I plan to release 8.0.17 this evening, including that patch, but you can test it out with this updated package: send_later-8.0.16-tb.zip~~

Update This actually introduced more noise to the debug log, even though I think it stabilized things a bit. I'm working right now on patching that up to quiet things down a little.

~~Update 2: I fixed some of that debug log noise. This package is up to date: send_later-8.0.16-tb.zip~~

Update 3: The 8.1.0 release candidate is now the most up to date.

[rollopack]

Same problem here with Thunderbird 78.4.0 and a fresh installation 8.0.16. With the update2 zip the column appear and the plugin work :-)

[PeterCodar]

I can https://github.com/Extended-Thunder/send-later/issues/91#issuecomment-723916818 confirm: The column appears and the plugin works now with your newest Update 2. Great work.

[jobisoft]

@padelt : I stripped down the add-on to a brute force draft scanner. I am looping 1000 times over all draft folders and call getFull for each message without waiting for the promise to finish. With 6 mails in draft, I had about 6000 parallel pending calls.

Would you give it a spin? It will autostart the test right after install and put something like this to the console:

21:19:01.005 Start background.js:61:11
21:19:01.055 Stop background.js:65:11
21:19:12.191 1 : 8 1000 background.js:57:69
21:19:12.461 2 : 8 1000 background.js:57:69
21:19:12.735 5 : 5 1000 background.js:57:69
21:19:13.037 6 : 8 1000 background.js:57:69
21:19:13.369 7 : 8 1000 background.js:57:69
21:19:13.591 8 : 8 1000 background.js:57:69

The numbers before the colon are message ids, the number after the colon the message size. brute-force-getfull.zip

[padelt]

@jobisoft I installed your brute-force-getfull.zip. It made Thunderbird unresponsive for several seconds (I guess that is expected). There are 4 draft mails in 4 different accounts. First run looked like this:

08:56:10.037 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 24ms]

08:56:10.037 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 24ms]

08:56:11.340 Start background.js:61:11
08:56:11.384 Stop background.js:65:11
08:57:00.239 DEBUG [SendLater]: Entering main loop. static.js:39:13
08:57:00.691 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
08:57:01.960 124 : 553 1000 background.js:57:69
08:57:02.227 [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMsgMessageService.streamMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource:///modules/gloda/MimeMessage.jsm :: MsgHdrToMimeMessage :: line 236"  data: no] 1000 MimeMessage.jsm:236:16
08:57:04.129 Uncaught (in promise) Error: An unexpected error occurred undefined
08:57:04.129 Uncaught (in promise) Error: An unexpected error occurred undefined
.... a total of exactly 1000 of these lines were here ....
08:57:04.141 Uncaught (in promise) Error: An unexpected error occurred undefined
08:57:04.141 Uncaught (in promise) Error: An unexpected error occurred undefined
08:57:04.141 Uncaught (in promise) Error: An unexpected error occurred undefined
08:57:05.802 Got message 124 on attempt 1 background.js:21:19
08:57:06.781 1 : 553 1000 background.js:57:69
08:57:08.333 126 : 144 1000 background.js:57:69
08:57:09.458 Got message 125 on attempt 1 background.js:21:19
08:57:09.465 Got message 1 on attempt 1 background.js:21:19
08:57:09.468 Got message 126 on attempt 1 background.js:21:19

For another run, I cleaned the error log and disabled Send Later. Then 3 runs of the cycle disable getFullTest, enable getFullTest, wait for completion. The last run was started in 09:07:00 +/- 2s.

09:00:49.434 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 78ms]

09:00:49.434 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 67ms]

09:00:59.956 DEBUG [SendLater]: AddonListener.resetSession: who - onDisabling static.js:39:13
09:00:59.957 DEBUG [SendLater]: Entering function SendLaterHeaderView.onUnload static.js:39:13
09:00:59.958 DEBUG [SendLater]: Leaving function SendLaterHeaderView.onUnload static.js:39:13
09:00:59.959 WebExtensions: [SendLater]: Beginning close function sl3u.js:1049
09:00:59.963 WebExtensions: [SendLater]: Extension removed. Goodbye world. sl3u.js:1076
09:01:00.035 sendRemoveListener on closed conduit sendlater3@kamens.us.14 ConduitsChild.jsm:108
09:01:00.424 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 25ms]

09:01:00.424 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 16ms]

09:01:15.876 Start background.js:61:11
09:01:15.926 Stop background.js:65:11
09:02:05.741 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 26ms]

09:02:05.741 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 25ms]

09:02:06.814 124 : 553 1000 background.js:57:69
09:02:07.617 125 : 255 1000 background.js:57:69
09:02:09.148 1 : 553 1000 background.js:57:69
09:02:09.591 126 : 144 1000 background.js:57:69
09:03:44.897 Start background.js:61:11
09:03:44.946 Stop background.js:65:11
09:04:36.043 124 : 553 1000 background.js:57:69
09:04:36.830 125 : 255 1000 background.js:57:69
09:04:38.327 1 : 553 1000 background.js:57:69
09:04:38.764 126 : 144 1000 background.js:57:69
09:05:41.810 Start background.js:61:11
09:05:41.861 Stop background.js:65:11
09:06:33.213 124 : 553 1000 background.js:57:69
09:06:34.021 125 : 255 1000 background.js:57:69
09:06:35.531 1 : 553 1000 background.js:57:69
09:06:35.954 126 : 144 1000 background.js:57:69
09:06:59.881 Start background.js:61:11
09:06:59.931 Stop background.js:65:11
09:07:50.669 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 41ms]

09:07:50.670 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 59ms]

09:07:51.852 124 : 553 1000 background.js:57:69
09:07:52.681 125 : 255 1000 background.js:57:69
09:07:54.317 1 : 553 1000 background.js:57:69
09:07:54.771 126 : 144 1000 background.js:57:69
09:08:18.537 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 28ms]

09:08:18.541 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 24ms]

Then I disabled getFullTest, cleaned the error log, enabled Send Later and on 09:09:50 I enabled getFullTest again. Another run at 09:11:20.

09:09:09.006 Webconsole context has changed
09:09:09.191 Starting Send Later version 8.0.16. background.js:622:17
09:09:09.207 Webconsole context has changed
09:09:09.352 Error writing response to: getStyleSheets Actor.js:174:21
09:09:09.353 Error while calling actor 'stylesheets's method 'getStyleSheets' can't access dead object Actor.js:91:13
09:09:09.353 get ownerWindow@resource://devtools/server/actors/stylesheets.js:275:5
form@resource://devtools/server/actors/stylesheets.js:446:1
write@resource://devtools/shared/protocol/types.js:363:32
types.addArrayType/write/<@resource://devtools/shared/protocol/types.js:220:33
write@resource://devtools/shared/protocol/types.js:220:16
write@resource://devtools/shared/protocol/Response.js:102:22
write@resource://devtools/shared/protocol/Response.js:53:29
sendReturn@resource://devtools/shared/protocol/Actor.js:172:38
Actor.js:96:15
09:09:09.374 Got message 124 on attempt 1 background.js:21:19
09:09:09.383 Got message 125 on attempt 1 background.js:21:19
09:09:09.392 Got message 1 on attempt 1 background.js:21:19
09:09:09.397 Got message 126 on attempt 1 background.js:21:19
09:09:09.401 INFO [SendLater]: Claimed 0 scheduled messages. static.js:39:13
09:09:09.405 WebExtensions: notifyStorageLocal: START - extension:sendlater3@kamens.us:storage-local sl3u.js:912
09:09:09.407 WebExtensions: [SendLater]: onLoadWindow, inject script utils/moment.min.js sl3u.js:952
09:09:09.408 WebExtensions: [SendLater]: onLoadWindow, inject script utils/static.js sl3u.js:952
09:09:09.410 WebExtensions: [SendLater]: onLoadWindow, inject script experiments/headerView.js sl3u.js:952
09:09:09.413 WebExtensions: Entering function: Sendlater3Backgrounding.addMsgSendLaterListener sl3u.js:293
09:09:09.414 WebExtensions: Leaving function: Sendlater3Backgrounding.addMsgSendLaterListener sl3u.js:296
09:09:09.415 DEBUG [SendLater]: Registering window listeners static.js:39:13
09:09:09.416 Got i18n locales from extension 
Object { getMessage: getMessage() }
static.js:846:15
09:09:09.417 DEBUG [SendLater]: Entering function SendLaterHeaderView.onLoad static.js:39:13
09:09:09.418 WebExtensions: notifyStorageLocal.Observer: extension:sendlater3@kamens.us:ready sl3u.js:906
09:09:09.418 DEBUG [SendLater]: Entering function SendLaterHeaderView.storageLocalObserver.observe static.js:39:13
09:09:09.418 DEBUG [SendLater]: StorageLocalMap: 
Map(46) { versionNumber → "8.0.16", checkTimePref → 1, checkTimePref_isMilliseconds → false, quickOptions1Label → "in 5 minutes", quickOptions1funcselect → "Delay", quickOptions1Args → "5", quickOptions2Label → "in 30 minutes", quickOptions2funcselect → "Delay", quickOptions2Args → "30", quickOptions3Label → "in 2 hours", … }
static.js:39:13
09:09:09.420 DEBUG [SendLater]: Leaving function SendLaterHeaderView.storageLocalObserver.observe static.js:39:13
09:09:09.421 DEBUG [SendLater]: Entering function SendLaterHeaderView.InitializeOverlayElements static.js:39:13
09:09:09.422 DEBUG [SendLater]: Leaving function SendLaterHeaderView.InitializeOverlayElements static.js:39:13
09:09:09.422 DEBUG [SendLater]: Leaving function SendLaterHeaderView.onLoad static.js:39:13
09:09:09.536 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:09:09.593 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:09:09.614 Got message 124 on attempt 1 background.js:21:19
09:09:09.620 Got message 125 on attempt 1 background.js:21:19
09:09:09.627 Got message 1 on attempt 1 background.js:21:19
09:09:09.631 Got message 126 on attempt 1 background.js:21:19
09:09:50.333 Start background.js:61:11
09:09:50.385 Stop background.js:65:11
09:10:41.061 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:10:41.448 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:10:42.372 124 : 553 1000 background.js:57:69
09:10:43.215 125 : 255 1000 background.js:57:69
09:10:44.647 Got message 124 on attempt 1 background.js:21:19
09:10:44.726 1 : 553 1000 background.js:57:69
09:10:45.154 126 : 144 1000 background.js:57:69
09:10:45.473 Got message 125 on attempt 1 background.js:21:19
09:10:45.478 Got message 1 on attempt 1 background.js:21:19
09:10:45.480 Got message 126 on attempt 1 background.js:21:19
09:11:20.230 Start background.js:61:11
09:11:20.284 Stop background.js:65:11
09:12:09.723 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:12:10.127 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:12:11.362 124 : 553 1000 background.js:57:69
09:12:12.154 125 : 255 1000 background.js:57:69
09:12:13.593 Got message 124 on attempt 1 background.js:21:19
09:12:13.665 1 : 553 1000 background.js:57:69
09:12:14.098 126 : 144 1000 background.js:57:69
09:12:14.454 Got message 125 on attempt 1 background.js:21:19
09:12:14.459 Got message 1 on attempt 1 background.js:21:19
09:12:14.464 Got message 126 on attempt 1 background.js:21:19
09:12:46.895 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 85ms]

09:12:46.904 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 68ms]

After this, I added a draft to be sent later.

I stopped Thunderbird and started it again. After it came up, I repeated disabling and enabling getFullTest at around 09:19:15. Result:

09:16:31.282 Successfully loaded OpenPGP library rnp.dll from C:\Program Files (x86)\Mozilla Thunderbird\rnp.dll RNPLib.jsm:49:13
09:16:31.500 public keys: 26, secret keys: 2 RNPLib.jsm:264:15
09:17:21.196 Starting Send Later version 8.0.16. background.js:622:17
09:17:22.738 Uncaught (in promise) Error: An unexpected error occurred undefined
09:17:22.738 Uncaught (in promise) Error: An unexpected error occurred undefined
.... a total of 236 of these lines was here ....
09:17:22.738 Uncaught (in promise) Error: An unexpected error occurred undefined
09:17:22.738 Uncaught (in promise) Error: An unexpected error occurred undefined
09:17:22.784 5 : 144 1000 background.js:57:69
09:17:22.959 Got message 1 on attempt 1 background.js:21:19
09:17:23.016 1604996243016  addons.webextension.<unknown>   WARN    Loading extension 'null': Reading manifest: Warning processing legacy: An unexpected property was found in the WebExtension manifest.
09:17:23.450 2147500037 ext-messages.js:233
09:17:23.452 getRaw failed on attempt 1 for message 2. Will try again. background.js:28:21
09:17:23.453 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:23.495 [Exception... "Component returned failure code: 0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH)"  location: "JS frame :: resource://gre/modules/L10nRegistry.jsm :: L10nRegistry.loadSync :: line 658"  data: no] L10nRegistry.jsm:658:19
09:17:23.811 [Exception... "Component returned failure code: 0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH)"  location: "JS frame :: resource://gre/modules/L10nRegistry.jsm :: L10nRegistry.loadSync :: line 658"  data: no] L10nRegistry.jsm:658:19
09:17:23.811 [Exception... "Component returned failure code: 0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH)"  location: "JS frame :: resource://gre/modules/L10nRegistry.jsm :: L10nRegistry.loadSync :: line 658"  data: no] L10nRegistry.jsm:658:19
09:17:24.505 Successfully loaded OTR library libotr-5.dll from C:\Program Files (x86)\Mozilla Thunderbird\libotr-5.dll OTRLib.jsm:43:13
09:17:26.760
InvisibleToDebugger: Error {  }
event-emitter.js:241:21
09:17:26.888
InvisibleToDebugger: Error {  }
event-emitter.js:241:21
09:17:27.041 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
09:17:27.218 Webconsole context has changed
09:17:27.222 2147500037 ext-messages.js:233
09:17:27.225 getRaw failed on attempt 2 for message 2. Will try again. background.js:28:21
09:17:27.229 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:27.413 Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”). panel.js:78:24
09:17:30.248 2147500037 ext-messages.js:233
09:17:30.264 getRaw failed on attempt 3 for message 2. Will try again. background.js:28:21
09:17:30.267 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:33.267 Unhandled IRC message:
:dacia.oftc.net 309 xx NickServ :is a Network Service irc.jsm:864
09:17:33.829 2147500037 ext-messages.js:233
09:17:33.830 getRaw failed on attempt 4 for message 2. Will try again. background.js:28:21
09:17:33.831 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:36.701 2147500037 ext-messages.js:233
09:17:36.703 Giving up on message. Too many retries. 2 background.js:25:21
09:17:36.710 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:36.712 WARN [SendLater]: claimDrafts.forAllDrafts failed. Unable to get raw message contents. 
Object { id: 2, date: Date Tue Nov 10 2020 08:55:45 GMT+0100 (Central European Standard Time), author: "REDACTED", recipients: (1) […], ccList: [], bccList: (1) […], subject: "Test 2", read: false, flagged: false, junk: false, … }
static.js:39:13
09:17:37.499 Got message 3 on attempt 1 background.js:21:19
09:17:37.594 Got message 4 on attempt 1 background.js:21:19
09:17:37.601 Got message 5 on attempt 1 background.js:21:19
09:17:37.604 INFO [SendLater]: Claimed 0 scheduled messages. static.js:39:13
09:17:37.607 WebExtensions: notifyStorageLocal: START - extension:sendlater3@kamens.us:storage-local sl3u.js:912
09:17:37.609 WebExtensions: [SendLater]: onLoadWindow, inject script utils/moment.min.js sl3u.js:952
09:17:37.610 WebExtensions: [SendLater]: onLoadWindow, inject script utils/static.js sl3u.js:952
09:17:37.626 WebExtensions: [SendLater]: onLoadWindow, inject script experiments/headerView.js sl3u.js:952
09:17:37.631 Got i18n locales from extension 
Object { getMessage: getMessage() }
static.js:846:15
09:17:37.632 WebExtensions: Entering function: Sendlater3Backgrounding.addMsgSendLaterListener sl3u.js:293
09:17:37.632 WebExtensions: Leaving function: Sendlater3Backgrounding.addMsgSendLaterListener sl3u.js:296
09:17:37.633 DEBUG [SendLater]: Registering window listeners static.js:39:13
09:17:37.637 WebExtensions: notifyStorageLocal.Observer: extension:sendlater3@kamens.us:ready sl3u.js:906
09:17:37.637 DEBUG [SendLater]: Entering function SendLaterHeaderView.onLoad static.js:39:13
09:17:37.637 DEBUG [SendLater]: Entering function SendLaterHeaderView.storageLocalObserver.observe static.js:39:13
09:17:37.638 DEBUG [SendLater]: StorageLocalMap: 
Map(46) { versionNumber → "8.0.16", checkTimePref → 1, checkTimePref_isMilliseconds → false, quickOptions1Label → "in 5 minutes", quickOptions1funcselect → "Delay", quickOptions1Args → "5", quickOptions2Label → "in 30 minutes", quickOptions2funcselect → "Delay", quickOptions2Args → "30", quickOptions3Label → "in 2 hours", … }
static.js:39:13
09:17:37.638 DEBUG [SendLater]: Leaving function SendLaterHeaderView.storageLocalObserver.observe static.js:39:13
09:17:37.638 DEBUG [SendLater]: Entering function SendLaterHeaderView.InitializeOverlayElements static.js:39:13
09:17:37.639 DEBUG [SendLater]: Leaving function SendLaterHeaderView.InitializeOverlayElements static.js:39:13
09:17:37.639 DEBUG [SendLater]: Leaving function SendLaterHeaderView.onLoad static.js:39:13
09:17:37.642 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:17:37.706 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:17:37.788 Got message 1 on attempt 1 background.js:21:19
09:17:37.910 2147500037 ext-messages.js:233
09:17:37.911 getRaw failed on attempt 1 for message 2. Will try again. background.js:28:21
09:17:37.912 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:41.600 2147500037 ext-messages.js:233
09:17:41.604 getRaw failed on attempt 2 for message 2. Will try again. background.js:28:21
09:17:41.607 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:46.215 2147500037 ext-messages.js:233
09:17:46.217 getRaw failed on attempt 3 for message 2. Will try again. background.js:28:21
09:17:46.219 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:17:54.018 2147500037 ext-messages.js:233
09:17:54.021 getRaw failed on attempt 4 for message 2. Will try again. background.js:28:21
09:17:54.025 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:01.133 2147500037 ext-messages.js:233
09:18:01.134 Giving up on message. Too many retries. 2 background.js:25:21
09:18:01.139 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:01.140 WARN [SendLater]: possiblySendMessage failed. Unable to get raw message contents. 
Object { id: 2, date: Date Tue Nov 10 2020 08:55:45 GMT+0100 (Central European Standard Time), author: "REDACTED", recipients: (1) […], ccList: [], bccList: (1) […], subject: "Test 2", read: false, flagged: false, junk: false, … }
static.js:39:13
09:18:01.154 Got message 3 on attempt 1 background.js:21:19
09:18:01.157 Got message 4 on attempt 1 background.js:21:19
09:18:01.162 Got message 5 on attempt 1 background.js:21:19
09:18:12.758 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 76ms]

09:18:12.759 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 76ms]

09:18:37.652 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:18:37.711 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:18:37.765 Got message 1 on attempt 1 background.js:21:19
09:18:38.079 2147500037 ext-messages.js:233
09:18:38.081 getRaw failed on attempt 1 for message 2. Will try again. background.js:28:21
09:18:38.083 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:44.781 2147500037 ext-messages.js:233
09:18:44.782 getRaw failed on attempt 2 for message 2. Will try again. background.js:28:21
09:18:44.784 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:50.227 2147500037 ext-messages.js:233
09:18:50.229 getRaw failed on attempt 3 for message 2. Will try again. background.js:28:21
09:18:50.240 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:53.142 2147500037 ext-messages.js:233
09:18:53.143 getRaw failed on attempt 4 for message 2. Will try again. background.js:28:21
09:18:53.144 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:58.072 2147500037 ext-messages.js:233
09:18:58.073 Giving up on message. Too many retries. 2 background.js:25:21
09:18:58.076 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:18:58.077 WARN [SendLater]: possiblySendMessage failed. Unable to get raw message contents. 
Object { id: 2, date: Date Tue Nov 10 2020 08:55:45 GMT+0100 (Central European Standard Time), author: "REDACTED", recipients: (1) […], ccList: [], bccList: (1) […], subject: "Test 2", read: false, flagged: false, junk: false, … }
static.js:39:13
09:18:58.088 Got message 3 on attempt 1 background.js:21:19
09:18:58.090 Got message 4 on attempt 1 background.js:21:19
09:18:58.095 Got message 5 on attempt 1 background.js:21:19
09:19:15.770 Start background.js:61:11
09:19:15.825 Stop background.js:65:11
09:20:03.737 GEThttp://detectportal.firefox.com/success.txt?ipv4
[HTTP/1.1 200 OK 19ms]

09:20:03.738 GEThttp://detectportal.firefox.com/success.txt?ipv6
[HTTP/1.1 200 OK 31ms]

09:20:04.093 DEBUG [SendLater]: Entering main loop. static.js:39:13
09:20:04.447 DEBUG [SendLater]: Next main loop iteration in 1 minute. static.js:39:13
09:20:05.329 1 : 553 1000 background.js:57:69
09:20:06.094 2 : 0 1000 background.js:57:69
09:20:07.777 Got message 1 on attempt 1 background.js:21:19
09:20:07.841 3 : 553 1000 background.js:57:69
09:20:08.054 4 : 301 1000 background.js:57:69
09:20:08.583 5 : 144 1000 background.js:57:69
09:20:09.187 2147500037 ext-messages.js:233
09:20:09.189 getRaw failed on attempt 1 for message 2. Will try again. background.js:28:21
09:20:09.190 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:20:11.910 2147500037 ext-messages.js:233
09:20:11.913 getRaw failed on attempt 2 for message 2. Will try again. background.js:28:21
09:20:11.917 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13
09:20:18.318 2147500037 ext-messages.js:233
09:20:18.320 getRaw failed on attempt 3 for message 2. Will try again. background.js:28:21
09:20:18.322 WARN [SendLater]: Unable to fetch message 2. Error: Error reading message 2 static.js:39:13

[jobisoft]

@padelt : Thanks for your test! Can you disable the original send later add-on during those tests (and maybe all other add-ons)? So we can see if this is really a clean reproduction add-on?

[jobisoft]

Oh wait, I just saw that you did disable send later. So my brute force works without error?

[padelt]

@jobisoft I think it works! Besides some stuff after starting (most likely related to Send Later) I don't see errors or exceptions around getFullTest in the log.

The last few tries to send using Send Later worked, too. I will have a close eye on it.

[jobisoft]

That means the bug we see is not purely related to getFull. Just to recap: I try to isolate what is causing the errors you see/saw using send later. The brute force test add-on is producing a lot of parallel getFull calls and it does not fail. But we want(!) the add-on to fail to know what is actually causing the error you saw, so it can be fixed in core.

This is independent of the current version of send later, which seems not to trigger the error anymore.

I will work on a new version of the test add-on. Thanks for your help!

[jobisoft]

@padelt : Which version was the last one, where you could reproduce the error? 8.0.16 rc3 ?

[jperryhouts]

I've gotten vague unhelpful bug reports via email that seem to confirm that this is not fixed in 8.1.0, in which I've removed all getFull calls. But again, I have no idea if it's the same bug or what, just anecdotal at this point.

[padelt]

@padelt : Which version was the last one, where you could reproduce the error? 8.0.16 rc3 ?

@jobisoft Can't reliably answer that, sorry.

I will work on a new version of the test add-on. Thanks for your help!

Let me know if I can help with that! I don't track Bugzilla (and have no user there), but feel free to ping me via the email in my Github profile or (if that makes sense) in this issue of course.

[bilbo911]

Same issue here: Send Later emails remain in Drafts indefinitely (except after restart, when unsent queued messages are sent) Thunderbird 78.4.3, Mac OS 10.15.6.

[jobisoft]

Which version of Send Later?

[jperryhouts]

Same issue here: Send Later emails remain in Drafts indefinitely (except after restart, when unsent queued messages are sent) Thunderbird 78.4.3, Mac OS 10.15.6.

@bilbo911 Are you saying they are making it into your outbox, but then not being queued to send? That would be a different issue.

[padelt]

Not sure this belongs here and with a big warning that I might be "seeing ghosts": Has anyone seen messages sent using SendLater, that just disappear when scheduled? I just had a case where I am 99,99% sure I sent a mail "5min later" and since it was a discussion thread I noticed that the recipient did not seem to have gotten it. My mails always go out with a BCC to another mailbox I control so I can check what actually left the sending MTA and what didn't. In this case, the sent mail didn't appear there too.

It might be my own "user error" and I cannot replicate it (and I have tried - a lot), so I am just asking here: Anyone experienced something like this?

[glilienthal]

I am seeing the same problem. TB 78, latest beta (8.2.1). (cf issue #139 ) Windows 10. Is there anything I can do to help isolating the error? (experienced user, but no idea about TB coding.)

[BramMeehan]

Getting this issue — where an email scheduled to Send Later — just sits in Drafts. Thunderbird 78.5.0 on an iMac running Catalina 10.15.7, Dreamhost is my mail provider. It's a brand-new install of everything — just had to have the hard drive replaced, so building the system from scratch.

[jikamens]

@jperryhouts I think it would be helpful for you to add an update to the beginning of the description of this issue (i.e., all the way at the top of this page, where people will see it first), explaining the current status and specifically what people can do to help debug it, in terms of providing information here. There are a lot of comments here so it's difficult to find that information buried in them.

[pat-vu]

Hello

same issues for me too with the latest SendLater beta and an imap Outlook account that used to work: mails are saved in Drafts as they should but never leave!

On 11/23/2020 7:46 PM, BramMeehan wrote:

Getting this issue — where an email scheduled to Send Later — just sits in Drafts. Thunderbird 78.5.0 on an iMac running Catalina 10.15.7, Dreamhost is my mail provider. It's a brand-new install of everything — just had to have the hard drive replaced, so building the system from scratch.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/Extended-Thunder/send-later/issues/16#issuecomment-732353905, or unsubscribe https://github.com/notifications/unsubscribe-auth/ART23EFKNQTDNEIUBK4WHYDSRKUYFANCNFSM4RX7RTJQ.