1791796 - [Experiment] [Intermittent] The Windows Native Notification is not consistently displayed when using the natural way to trigger it

Status: RESOLVED WORKSFORME

(Firefox :: Messaging System, defect)

Description

[Carmen Fat [:cfat] - Ecosystem QA]

Attachment: Logs from Browser Console.jpg

[Notes]:

• Until now, we were able to trigger the notification only 3 times:
  -> once on Tuesday when updated Nightly from 105.0a1 to 106.0a1
  -> twice on Wednesday when updated Beta from 105.0b7 to 106.0b2

[Affected versions]:

• Firefox Beta 105.0b2 (Build ID: 20220920185943)
• Firefox Nightly 106.0a1

[Affected platforms]:

• Windows 10 x64
• Windows 11 x64

[Prerequisites]:

• Access the “Background Tasks Profiles” folder and delete the contents of the sub-folders (e.g. of sub-folder “c:/Users/username/AppData/Roaming/Mozilla/Firefox/Background Tasks Profiles/v2a5r77u.MozillaBackgroundTask-6F193CCC56814779-backgroundupdate”).
• Set the System Date 28 days in the past.

[Steps to reproduce]:

1. Download and install Firefox Beta 105.0bx build.
2. Open Firefox Beta 105.0bx build and navigate to the about:config page.
3. Set the following preferences:

• messaging-system.rsexperimentloader.collection_id = nimbus-preview
• nimbus.debug = true

4. Close Firefox Beta 105.0bx.
5. Change the System Date to present.
6. Observe what happens next.

[Expected result]:

• The Windows Native Notification is displayed.

[Actual result]:

• The Windows Native Notification is not displayed.

[Additional notes]:

• The status of the Firefox Background Update task from the Task Schedule is “The operation completed successfully. (0x0)”.
• Here is a screen recording with the issue.
• Attached are the logs displayed in the Browser Console after opening Firefox myself.
• Please let me know if additional details are needed.

Comment 1

[Nick Alexander :nalexander [he/him]]

Hi Carmen -- this is working as expected. Sorry to not set expectations correctly here!

Let me explain. In the experiment recipe JSON, I've set:

  "frequency": {
    "lifetime": 3
  },

which is (correctly, it appears) capping the number of times the notification is displayed to you. If you look in about:support at the update folder, you should see a backgroundupdate.moz_log file. In it, I expect you'll see a message like:

     93:2022-09-01 16:11:34.256000 UTC - [Parent 25444: Main Thread]: D/Dump [Backstage.Dump]    filtered because capped

That's the Firefox Messaging System telling us that it would have displayed the notification, but the lifetime limit (of 3) was hit.

I'm going to close this as WORKSFORME; we can re-open if the logging is not conclusive. Sorry for the mixup!

Comment 2

[Nick Alexander :nalexander [he/him]]

Oh -- I forgot to say how to reset the lifetime limit: delete the background task profile contents again (just like in the Prerequisites section). That'll make you appear as a new user with a new lifetime limit.

Comment 3

[Carmen Fat [:cfat] - Ecosystem QA]

Thank you for the explanation. I think the information I wrote in the Notes section might be a bit confusing (apologies for this), so please let me detail it a bit.

I was trying to trigger the notification several times each day starting Monday:

• On Monday I didn’t manage to trigger it even though I did the same steps as in the video several times (~5-6 times with new Firefox profiles), including deleting the contents of the Background Tasks sub-folders before each try.
• On Tuesday I managed to trigger it once using Nightly, however for the next tries (~10 times) with the exact same steps, I wasn’t able to trigger it anymore.
• On Wednesday I managed to trigger it twice using Beta, but again, for the following tries, I wasn’t able to trigger it again.

For every single try, I used the exact same steps from the Description of the report, meaning that I deleted the contents of the Background Tasks Profile sub-folders each time before installing the browser.

Since deleting the contents of the Background Tasks Profile sub-folders counts as resetting the lifetime limit, shouldn’t that mean that the Notification must be displayed each time when continuing with the steps to trigger it, just as seen in the video?

Did I understand the logic incorrectly (independent of the lifetime limit)?

• delete sub-folder (cap is reset) -> perform steps from the report -> notification is shown (repeat as many times as necessary)

I have reproduced the behavior from the Description today as well, but this time, I have noticed 2 outcomes:
After following the exact steps from the Description, I opened several Beta profiles and checked the versions:

• For some profiles, the browser did not update and remained the original version of 105.0b7. The logs from the backgroundupdate.moz_log file can be found here.
• For other profiles, the browser did update from 105.0b7 to 106.0b2. I have also saved the logs for these cases here.

Please let me know if you need additional information or if anything I wrote here doesn’t make sense, or should be done differently. Thank you for taking the time to respond and provide additional details.

Comment 4

[Nick Alexander :nalexander [he/him]]

Carmen -- it seems there are at least two things happening:

1. sometimes, you don't see the notifications
2. sometimes, the background task doesn't appear to update Firefox successfully

For 1: In the partial logs that you provide, I see instances where the targeting doesn't match -- presumably due to actually running Firefox, perhaps from launching from the toast notification. You can edit the targeting.snapshot.json file in the default browsing profile to change the targeting dates and versions more easily than changing the system clock and re-installing, etc. It's not definitive but that does suggest that things are working as expected -- which can be counter-intuitive.

These log lines look like:

2022-09-22 13:57:56.699000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump] console.debug: RSLoader: 
2022-09-22 13:57:56.699000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump]   Testing targeting expression:
2022-09-22 13:57:56.699000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump]   ('app.shield.optoutstudies.enabled'|preferenceValue) && (version|versionCompare('106.*') <= 0) && ((experiment.slug in activeExperiments) || ((
    (
        (
            os.isWindows
            &&
            (os.windowsVersion >= 10)
        )
        &&
        (
            (
                ((defaultProfile|keys)|length == 0)
            )
            ||
            (
                ((currentDate|date - defaultProfile.currentDate|date) / 86400000 >= 28)
                &&
                (firefoxVersion > defaultProfile.firefoxVersion)
            )
        )
        &&
        isBackgroundTaskMode
    )
    ) && (version|versionCompare('106.!') >= 0)))
2022-09-22 13:57:56.704000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump] console.debug: RSLoader: 
2022-09-22 13:57:56.705000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump]   nalexander-backgroundmessage-test1 did not match due to targeting

For 2: Again, in the partial logs that you provide, I see that the system is checking for updates, seeing one, and starting the download. It might take a while for that to complete; the task will exit and check the next time it is run to see if Windows (via BITS) has completed the download. So it might take a few task runs for the update to actually "take".

These log lines look like:

2022-09-22 13:57:55.141000 UTC - [Parent 19804: Main Thread]: D/Dump [Backstage.Dump]   _attemptBackgroundUpdate: Download in progress. Exiting task while download transfers

If you can repro this with a video and the complete log files, that will help. As it stands, I'm not particularly concerned by what I see: there are many moving parts here and the test procedure is a good deal more complicated than the expected flow for "regular" lapsed Firefox users. Thanks for all of your time and effort testing this!

Comment 5

[Carmen Fat [:cfat] - Ecosystem QA]

Thank you Nick for providing the information. I still continue to reproduce the behavior with the steps from the Description, but I have also used the targeting.snapshot.json file to edit the targeting date. I have filmed all the steps here (hopefully they were correct) and I saved the Browser Console logs here. The logs from the backgroundupdate.moz_log file can also be found here. Please let me know if there are other logs I should search for and provide if necessary.

Would the internet speed have any influence on the background updates and showing the notification? It's a long shot, but it wouldn't be the first odd behavior I come across because of this reason.

Comment 6

[Nick Alexander :nalexander [he/him]]

(In reply to Carmen Fat [:cfat] - Ecosystem QA from comment #5)

Thank you Nick for providing the information. I still continue to reproduce the behavior with the steps from the Description, but I have also used the targeting.snapshot.json file to edit the targeting date. I have filmed all the steps here (hopefully they were correct) and I saved the Browser Console logs here. The logs from the backgroundupdate.moz_log file can also be found here. Please let me know if there are other logs I should search for and provide if necessary.

Would the internet speed have any influence on the background updates and showing the notification? It's a long shot, but it wouldn't be the first odd behavior I come across because of this reason.

Carmen -- thanks for the excellent reproduction and logs. There are two parts to the targeting:

1. the currentDate, which I see you changing to a month in the past
2. the firefoxVersion, which the logs reveal was 106

"firefoxVersion":106

The targeting checks both:

('app.shield.optoutstudies.enabled'|preferenceValue) && (version|versionCompare('106.*') <= 0) && ((experiment.slug in activeExperiments) || ((
    (
        (
            os.isWindows
            &&
            (os.windowsVersion >= 10)
        )
        &&
        (
            (
                ((defaultProfile|keys)|length == 0)
            )
            ||
            (
                ((currentDate|date - defaultProfile.currentDate|date) / 86400000 >= 28)
                &&
                (firefoxVersion > defaultProfile.firefoxVersion)
            )
        )
        &&
        isBackgroundTaskMode
    )
    ) && (version|versionCompare('106.!') >= 0)))
2022-09-26 14:49:13.039000 UTC - [Parent 9188: Main Thread]: D/Dump [Backstage.Dump] console.debug: RSLoader: 
2022-09-26 14:49:13.039000 UTC - [Parent 9188: Main Thread]: D/Dump [Backstage.Dump]   nalexander-backgroundmessage-test1 did not match due to targeting

I'm sorry that this isn't more clear in the instructions: I see my comment says "to change the targeting dates and versions" but does not the exact changes clear. If you bump that down to 105 in addition to changing the date, hopefully we'll be back on track.

Side note: the Nimbus team intends to add details on why targeting did not succeed (and not just when it failed due to a bad expression, etc) which will eventually make this easier to debug.

Thanks again for the clear reproduction!

Comment 7

[Carmen Fat [:cfat] - Ecosystem QA]

While investigating this behavior, we actually managed to find other steps (that are a bit different compared to the ones in the Description) that help us trigger more reliably the notification. I have just sent an update to the sign-off on email (changing its quality status from Red - Don't Ship to Yellow, Ship it conditionally, since on one Windows 10 machine out of three we still have trouble with reliably triggering it).

I am writing down the new steps that helped us constantly trigger the notification on the other 2 machines (in case we will still need them in the future):

1. Move date in the past ( at least 28 days).
2. Delete the Background Update folder contents.
3. Install Beta 105.
4. Open Beta with a new profile.
5. Discard updates from downloading from the about:preferences page.
6. Change the following pref:

• messaging-system.rsexperimentloader.collection_id to nimbus-preview

7. Recheck automatic updates and close the browser.
8. Move time to the current date.
9. Open Task Scheduler.
10. Run the specific Beta task and wait for the loading icon to disappear.
11. End the task and then re-run it.
12. Repeat step 11 until the notification is displayed.

Thank you Nick for your patience and for providing all this helpful information.