Make sure to await all async calls #563

jobisoft · 2023-07-19T09:23:21Z

This tries to deal with the symptoms described on #554.

We need to make sure that .then() callbacks do not spin into their own thread and are not part of the expected execution flow.

It is valid and sometimes more readable syntax to mix await and .then() and I did not remove all of them, but the Promise chain needs to be awaited. I did remove some wrongly nested chains.

I added comments, where I think code could be improved further.

jobisoft · 2023-07-19T09:24:31Z

background.js

-            }
-          );
-
+          // TODO: Not using the return value of saveMessage() ???


The returned saved message is not used. It looked strange to me, any insights?

I don't follow your question entirely.
The assumption of the code here is that the message ID of the newly saved version of the message is identical to the message ID of the previous incarnation of the message. Does that assumption hold true?
If so, then I don't see how it matters that the saved draft is not "used." The point here is to save the message to Drafts for later delivering at the scheduled time. Once the save happens this part of the code no longer has anything it needs to do with the message. Note that the code that does the background send scans all drafts to look for messages to send, so the hand-off occurs by virtue of putting the message into the Drafts folder.
Am I misunderstanding your question?

Ok, if the id of the original draft is not used at all after this call, we are good. But the next two lines re-schedule with the original draft id, not with the saved new draft id, which could be different. A check on the ID will tell you that.

I am just trying to point out edge cases, which may cause some of the observed behaviours.

That's the question I'm asking above. I think @jph-sendlater believed when he wrote this code that the id field he's using here is the message ID field, and that it will be the same in the saved draft as it was in the previous one. Is that wrong, then yeah, I think this is a bug that needs to be fixed.

I will try to address this.

I need help, I think this piece of code has multiple issues.

let originalMsg = await messenger.SL3U.findAssociatedDraft(window.id).then( m => m ? messenger.messages.getFull(m.id) : null ); if (originalMsg) { SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id); // Check if original message has x-send-later headers if (originalMsg.headers.hasOwnProperty("x-send-later-at")) { let { preferences, scheduleCache } = await messenger.storage.local.get( { preferences: {}, scheduleCache: {} } ); // Re-save message (drops x-send-later headers by default // because they are not loaded when editing as draft). messenger.compose.saveMessage(tab.id, {mode: "draft"}).then( () => { SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id); SendLater.updateStatusIndicator(); } );

The originalMessage is not a MessageHeader but a MessagePart. It does not have an id member, so the four lines manipulating the MsgCache do not seem to do anything useful.

Why is the manipulation repeated after the message has been saved? That seems not necessary, is it?

I updated the PR and now use the correct msgId and removed the superfluous update of the *scheduledMsgCache maps.

I think it would improve performance slightly to put back the code that updates the two caches after the message is saved, but using the correct id for the newly saved draft rather than the old id. I don't think it hurts too much not to do it -- Send Later will just pick up that draft in the next scan and add it to the cache in possiblySendMessage.

I know this is probably out-of-scope for this PR, but it's silly that there are two different caches. There should be just be one cache, a JavaScript dictionary whose keys are message IDs and values are either true for scheduled or false for unscheduled.

Also, as far as I can tell, right now messages that have been deleted aren't ever being removed from the caches, so that's a memory leak if TB is kept running for a long time.

I really do not understand that piece of code. This is the current version:

SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id); // Check if original message has x-send-later headers if (originalMsg.headers.hasOwnProperty("x-send-later-at")) { let { preferences, scheduleCache } = await messenger.storage.local.get({ preferences: {}, scheduleCache: {} }); // Re-save message (drops x-send-later headers by default // because they are not loaded when editing as draft). messenger.compose.saveMessage(tab.id, {mode: "draft"}).then( () => { SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id); SendLater.updateStatusIndicator(); } );

So in the first two lines we do:

SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id);

and in the then() callback we do again:

SLTools.scheduledMsgCache.delete(originalMsg.id); SLTools.unscheduledMsgCache.add(originalMsg.id); SendLater.updateStatusIndicator();

That is exactly the same, the cache is not reverted or anything in the second step, we just delete the same entry from the scheduledMsgCache map (which is not there anymore = no op) and we add the same entry to the unscheduledMsgCache map (which is already there = no op).

It really is not doing anything. Or am I missing something? We definitely should elaborate, what these caches are used for and try to simplify them.

@jperryhouts : Do you have time to help us understand what these caches are for?

background.js

jobisoft · 2023-07-19T09:32:30Z

background.js

-                SLStatic.debug(
-                  "Comparing", rcvdHdr, "to", draftHdr,
-                  inReplyTo, "?=", `<${draftHdr.headerMessageId}>`
+        let rcvdMsg = await messenger.messages.getFull(rcvdHdr.id);


Is there a fear, that the call to getFull() could block the loop? Can we then move the entire body of the loop into an async function, which for each message is properly awaited and throw the returned Promise into an Promise.all()?

@jph-sendlater would have to comment on why he wrote the code the way he did, and @jobisoft would know better than I whether it's possible for messenger.messages.getFull to block, but to the extent that I understand what's going on here, I think the change you propose seems reasonable.
One caveat: if getFull could potentially trigger message downloading from the server, then is it a good idea to set off a bunch of those in parallel? Seems like it could cause a spike in network traffic, and also, in my experience, TB sometimes gets a bit unhappy when a bunch of things are all trying to download messages from an IMAP server at the same time. It might therefore be safer to keep the current behavior of processing the messages one by one instead of sticking them all in separate promises and processing them in parallel?

It is the opposite. The original code is firing off all operations in the for loop in parallel. My change sequentialized the first getFull() request. What I have not yet sequentialized is the call to SLTools.forAllDrafts(), that is still scheduled for later async execution without waiting for each to have been finished before the next one is started.

I now await the call to SLTools.forAllDrafts() below as well.

Waiting on feedback from @jph-sendlater for his opinion on the method, before resolving this conversation. I personally feel it is safer to have all run sequentially.

background.js

jikamens · 2023-07-26T20:48:12Z

@jobisoft I added a minor commit to your branch (and therefore to this PR) which fixes #529. Please take a look.

utils/tools.js

arndissler

There are still calls with a missing await:

messenger.storage.local.set
messenger.compose.sendMessage
messenger.composeAction.openPopup
messenger.composeAction.setPopup
messenger.browserAction.setBadgeText
messenger.browserAction.enable
messenger.messageDisplayAction.setBadgeText
SendLater.updateStatusIndicator
SendLater.setQuitNotificationsEnabled
…

As one consequence, SLStatic.nofail must be made async and awaited in SendLater.disable and there are still some calls left in the mainLoop where that needs to be awaited.

While there should be enough time for all calls to finish between two cycles (60 seconds), it's cleaner to await all calls where necessary to avoid unwanted side effects.

jikamens · 2023-08-07T19:39:02Z

messenger.messageDisplayAction.setBadgeText

@arndissler I don't see this used anywhere in the code. Did you mean messenger.messageDisplayAction.enable?

Fix a logic error in the loop intended to interate over all drafts. The logic error was causing the loop to only examine the first page of results from `messenger.messages.list` and therefore only the first 100 drafts in each drafts folder. Fixes #529.

jikamens · 2023-08-07T19:50:26Z

@arndissler made a bunch more changes. Please take me a look and let me know if you think this is good to merge.

When disabling the add-on because it failed to initialize properly, instead of just firing off a bunch of promises which will execute in random order based on whenever the JS engine decides to fulfill each one, execute them all sequentially. This eliminates a bunch of unnecessary nondeterminism which could cause intermittent issues we would need to debug, and it also means we will know reliably that the disable steps, some of which may depend on earlier steps, happen in order.

Send Later allows other extensions to get and set its preferences via the `getPreferences` and `setPreferences` actions. Unfortunately, the former was broken because it was attempting to use the JavaScript `filter` operator on on Object when it only works on Arrays. This is now fixed.

After converting the compose action click handler to an async function, the first time the compose action button is clicked it doesn't work, and an error is logged that the popup can only be opened from a user input handler, which is weird because it _is_ being opened from a user input handler. Having said that, simplifying the code by not unnecessarily setting and clearing the popup file makes this problem go away, and this change doesn't hurt anything else, so let's go with that.

background.js

arndissler

Great work so far – two glitches were excellently spotted and fixed (the missing last page for the message lists and the .filter on object props).

There are still some calls that needs to be await'ed:

all calls to messenger.quitter.*
one call to messenger.messages.update
messenger.SL3U.setLogConsoleLevel
messenger.SL3U.setLegacyPref
messenger.SL3U.getLegacyPref
messenger.SL3U.setDispositionState

While the implementation of messenger.columnHandler.setPreference is marked as async, it doesn't contain async code and are not await'ed anywhere. This can cause side effects, as APIs are "promisified", AFAIK, but this should be okay-ish for this method, as it only sets some lookup prefs in a Map.

1) I don't understand why there are two custom column handlers in the experiments directory, but it appears at some point the column handling was switched from customColumn* to legacyColumn*, which changed the argument types for `messenger.columnHandler.setColumnVisible`, but the code in `background.js` wasn't updated to reflect that change. Now it has been, so the Send Later column is now properly enabled and disabled. 2) If the Drafts folder is the currently displayed folder when Thunderbird starts up, the Send Later column is now properly enabled and made visible if it's supposed to be.

Remove an unnecessary console debug log message that's two verbose. Change several console log calls to SLStatic log calls so they'll get filtered by the configured log level.

You can't add the header row update listener before you've initialized the expanded header row!

jikamens · 2023-08-07T22:57:03Z

@arndissler did more cleanup, fixed more bugs, take another look

arndissler

While the latest changes are a good step forward, there are still multiple calls to async functions or functions that return promises, that are not await'ed and can cause unforeseeable side effects.

While not awaiting calls to messenger.window.close, messenger.runtime.openDefaultBrowser and similar, I think it's crucial to await calls to (and not limited to):

While there's no evidence, it's possible that the non-awaited calls cause errors that we haven't spotted yet.

jikamens · 2023-08-09T10:13:27Z

While the latest changes are a good step forward, there are still multiple calls to async functions or functions that return promises, that are not await'ed and can cause unforeseeable side effects.

While not awaiting calls to messenger.window.close, messenger.runtime.openDefaultBrowser and similar, I think it's crucial to await calls to (and not limited to):
* [`SendLater.doSendNow`](https://github.com/jobisoft/send-later/blob/f042f65c8e768cb2acbefb154c925a40abd5ceda/background.js#L1136)

* [`SendLater.doPlaceInOutbox`](https://github.com/jobisoft/send-later/blob/f042f65c8e768cb2acbefb154c925a40abd5ceda/background.js#L1141)

* [`SendLater.scheduleSendLater`](https://github.com/jobisoft/send-later/blob/f042f65c8e768cb2acbefb154c925a40abd5ceda/background.js#L1150)
While there's no evidence, it's possible that the non-awaited calls cause errors that we haven't spotted yet.

I'm going to merge this and fix those on main.

Make sure to await all async calls

334ed5c

jobisoft commented Jul 19, 2023

View reviewed changes

background.js Outdated Show resolved Hide resolved

jobisoft commented Jul 19, 2023

View reviewed changes

background.js Show resolved Hide resolved

jobisoft commented Jul 19, 2023

View reviewed changes

background.js Show resolved Hide resolved

jikamens mentioned this pull request Jul 22, 2023

send later seems to ignore throttleDelay #503

Closed

jobisoft added 4 commits July 23, 2023 18:08

return Promise/false in message listener

8bbfb3f

await SLTools.forAllDrafts() in onNewMailReceivedListener

912f92a

Add comments

64ed5aa

Use correct id in *scheduledMsgCache maps

029ad53

jobisoft commented Jul 27, 2023

View reviewed changes

utils/tools.js Show resolved Hide resolved

arndissler requested changes Aug 1, 2023

View reviewed changes

jikamens added 2 commits August 7, 2023 15:47

await all calls to messenger.storage.local.set

0e36c14

jikamens force-pushed the await-all-async branch from e8fcf29 to 0f7daa3 Compare August 7, 2023 19:49

jikamens requested a review from arndissler August 7, 2023 19:50

jikamens force-pushed the await-all-async branch from 0f7daa3 to 5cbfc18 Compare August 7, 2023 19:55

jikamens added 6 commits August 7, 2023 16:01

await calls to messenger.compose.sendMessage and scheduleSendLater

caf5ee3

await all calls to messenger.composeAction.{set,open}Popup

6c63814

await calls to messenger.browserAction.*

9a8f723

await calls to messenger.messageDisplayAction.enable

72575a8

await calls to updateStatusIndicator and setQuitNotificationsEnabled

1127416

jikamens force-pushed the await-all-async branch from 5cbfc18 to 1127416 Compare August 7, 2023 20:04

jikamens added 2 commits August 7, 2023 16:19

arndissler reviewed Aug 7, 2023

View reviewed changes

background.js Show resolved Hide resolved

arndissler requested changes Aug 7, 2023

View reviewed changes

jikamens added 5 commits August 7, 2023 18:33

Add more missing awaits

5f41b54

Clean up some logging

45dc4c4

Remove an unnecessary console debug log message that's two verbose. Change several console log calls to SLStatic log calls so they'll get filtered by the configured log level.

Delete unnecessary whitespace

eab1b04

Fix expanded header row display

f042f65

You can't add the header row update listener before you've initialized the expanded header row!

arndissler requested changes Aug 9, 2023

View reviewed changes

jikamens merged commit 9638f7c into Extended-Thunder:master Aug 9, 2023
2 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make sure to await all async calls #563

Make sure to await all async calls #563

jobisoft commented Jul 19, 2023

jobisoft Jul 19, 2023

jikamens Jul 22, 2023

jobisoft Jul 22, 2023

jikamens Jul 22, 2023

jobisoft Jul 22, 2023

jobisoft Jul 23, 2023

jobisoft Jul 23, 2023

jikamens Jul 26, 2023

jobisoft Jul 27, 2023 •

edited

Loading

jobisoft Jul 27, 2023

jobisoft Jul 19, 2023

jikamens Jul 22, 2023

jobisoft Jul 22, 2023

jobisoft Jul 23, 2023

jobisoft Jul 23, 2023

jikamens commented Jul 26, 2023

arndissler left a comment

jikamens commented Aug 7, 2023

jikamens commented Aug 7, 2023

arndissler left a comment

jikamens commented Aug 7, 2023

arndissler left a comment

jikamens commented Aug 9, 2023

Make sure to await all async calls #563

Make sure to await all async calls #563

Conversation

jobisoft commented Jul 19, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jobisoft Jul 27, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jikamens commented Jul 26, 2023

arndissler left a comment

Choose a reason for hiding this comment

jikamens commented Aug 7, 2023

jikamens commented Aug 7, 2023

arndissler left a comment

Choose a reason for hiding this comment

jikamens commented Aug 7, 2023

arndissler left a comment

Choose a reason for hiding this comment

jikamens commented Aug 9, 2023

jobisoft Jul 27, 2023 •

edited

Loading