1830725 - Synchronous `nsWindowsPackageManager::GetCampaignId` blocks main thread for many seconds on MSIX builds as part of TelemetryStartup

Status: RESOLVED FIXED

(Firefox :: Installer, defect, P1)

Description

[equeim]

Steps to reproduce:

1. Install Firefox from Microsoft Store
2. Launch it

OS is WIndows 11 with latest updates.
This does not happen when Firefox is installed from Mozilla website.

Actual results:

Empty window with grey placeholder UI displayed for about 10 seconds, with busy cursor. Then it unfreezes.

Expected results:

Firefox is launched without delays.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Firefox::Installer' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 2

[Robin Steuber (they/them) [:bytesized]]

Hello, thank you for filing a bug.

Unfortunately, I can't reproduce this problem. If you follow the same steps again, are you able to reproduce it consistently? If so, could you please collect a startup profile of the problem occurring so that we can investigate what is taking your browser so long to start up?

1. Open the start menu. Search for and open "Edit Environment Variables for your Account"
2. Click the "New..." button under the "User variables for <username>" section.
3. Enter MOZ_PROFILER_STARTUP in the "Variable name" field and 1 in the "Variable value" field and click "Ok"
4. Click "Ok" on the "Environment Variables" window.
5. Open the Microsoft Store.
6. Find, install, and launch Firefox.
7. When Firefox has started, quickly navigate to profiler.firefox.com, and click "+ enable Firefox Profiler Menu" Button.
8. There should be a popup appearing near the top-right (otherwise click the profiler icon), click "Capture".
9. After a few seconds transferring the data, and then getting symbols, you should end up on the profiler web page with your startup profile.
10. Click "Upload Local Profile", you can hide some private data if you wish, then click "Upload".
    This should give a URL starting with "share.firefox.dev", which can be shared here or privately.
11. Before you close Firefox, navigate to about:support. In the "Environment Variables" section, make sure that it lists MOZ_PROFILER_STARTUP with a value of 1. If it doesn't, the variable may not have been set properly or Firefox may not have picked it up for some reason.

Afterwards, reopen the "Environment Variables" windows that you opened in step 1, select the MOZ_PROFILER_STARTUP variable and click the "Delete" button. Then click "Ok".

Comment 3

[equeim]

https://share.firefox.dev/3AMxIB4

Comment 4

[Robin Steuber (they/them) [:bytesized]]

Awesome, thank you!

It looks like the first 7ish seconds of startup are nearly entirely taken up in this (abbreviated) function stack:

nsWindowsPackageManager::GetCampaignId()
EnsureMTA::EnsureMTA()
SyncDispatchToPersistentThread()
WaitForSingleObjectEx()

I think that this corresponds to this WaitForSingleObjectEx call. I assume that it would show the lambda function as part of the stack if it were this call, though I don't have much experience looking at stacks with lambda functions, so I'm not entirely sure.

So I'm hoping that an MSCOM peer might be able to shine some light on what's going on here?

Comment 5

[James Teh [:Jamie]]

It looks like this is stuck waiting for something in the nsWindowsPackageManager::GetCampaignId runnable, whether that's one of the async COM calls (which really shouldn't block by definition) or the WaitForSingleObject call inside that runnable. Note that the runnable runs on the background persistent MTA thread, so you wouldn't see that lambda in this main thread. My guess is that this async call is just taking a long time for some reason. I don't think this is an ipc/mscom issue, but rather an issue in the COM components used here.

It might be useful to get a profile including the "COM MTA" thread so we can see the stack for that thread.

I wonder if there's some way we can do this campaign id stuff async in Firefox. The API is probably async for a good reason - I guess Microsoft knew it could be slow - but we're trying to use it sync.

Comment 6

[Nick Alexander :nalexander [he/him]]

This allows to attribute MSIX builds, but that is a capability we've not used to date. It's used in a single JS context which, luckily, is asynchronous, so it would be possible to make it async: https://searchfox.org/mozilla-central/rev/e6cb503ac22402421186e7488d4250cc1c5fecab/browser/components/attribution/AttributionCode.sys.mjs#362.

nrishel: you know something about these details, and about making a Promise-y interface. How hard is that for a Windows API call? Is this an intern task (with your guidance), or ...?

Comment 7

[Nick Rishel [:nrishel]]

At first blush it sounds fairly straight forward: offload work to a blockable marked Runnable that is run off the main thread, and pass a promise into said Runnable which is later resolved on the main thread Runnable.

Comment 8

[Nick Rishel [:nrishel]]

P3 S3 just to have this marked, but will discuss if this should be higher priority/severity in our next weekly.

Comment 9

[Monica Chiorean]

Nick, can we mark issue as New since investigation is on progress on it? Thank you?

Comment 10

[Michael Hughes]

I'm working on this right now.

Comment 11

[Michael Hughes]

Attachment: Bug 1830725: Synchronous `nsWindowsPackageManager::GetCampaignId` blocks main thread for many seconds

Made GetCampaignId asynchronous to not block anything.

Comment 14

[Solway]

coming from bug 1855389. note this is still a issue in version 118.
Should this telemetry be disabled if a GPO is set to disable telemetry?

Comment 15

[Gian-Carlo Pascutto [:gcp]]

Should this telemetry be disabled if a GPO is set to disable telemetry?

As pointed out here: https://bugzilla.mozilla.org/show_bug.cgi?id=1855389#c5, this seems to happens before we're at the state where those settings are known.

Comment 16

[Alessio Placitelli [:Dexter]]

Hey :yannis, moving this back to the Installer component as this problem is not about the telemetry system, but rather about a data point collected by Installer.

Comment 17

[Yannis Juglaret [:yannis]]

There are users experiencing this issue these days here and here. Are we still making progress or are we blocked? If this needs more time, could we consider removing this code from release builds while we fix it, assuming that the comment below still holds?

(In reply to Nick Alexander :nalexander [he/him] from comment #6)

This allows to attribute MSIX builds, but that is a capability we've not used to date.

(Edit: Sorry for the accidental extra component change here)

Comment 18

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1756209

Comment 19

[Michael Hughes]

(In reply to Yannis Juglaret [:yannis] from comment #17)

There are users experiencing this issue these days here and here. Are we still making progress or are we blocked? If this needs more time, could we consider removing this code from release builds while we fix it, assuming that the comment below still holds?

(In reply to Nick Alexander :nalexander [he/him] from comment #6)

This allows to attribute MSIX builds, but that is a capability we've not used to date.

(Edit: Sorry for the accidental extra component change here)

So the fix is done and I'm attempting to test it.

For more info: testing is very involved. I need permission to use our MS Azure account, which took hours yesterday. And even with the permissions, we still have to track down why I don't have access to the product I need to. Once that's done, I'll have to upload a build, wait 2+ hours for MS to approve that, download it, and run it on a VM or in the Windows Sandbox to confirm.

I'm working on it today. Rolling anything back would also require testing, which would require the same process.

Comment 20

[Michael Hughes]

For anyone to test this, there are the following scenarios to confirm: 1) not signed into the Store with an account on Windows 10, 2) signed into the Store with an account on Windows 10, 3) not signed into an account on Windows 11, 4) signed into an account on Windows 11. Scenario 5 is to test that things work when a campaign Id was not specified at all.

For all of the scenarios, if you test this before it has landed in the Store on the official Firefox entry, you'll need a link to the Firefox Nightly store entry. Please message me on Slack to get that. Once have that...

Scenario 1 (Win 10, not signed in):

Ensure you are not signed in to the Windows Store, possibly on a fresh, new VM, on Windows 10
Install Firefox Nightly through the link provided through Slack
Open the Browser Console
Run the following:

let wpm = Cc["@mozilla.org/windows-package-manager;1"].getService(Ci.nsIWindowsPackageManager)
await wpm.campaignId()

Expected resulted: wpm.campaignId should be ""

If the result is "bug1830725campaigntest" that's fine too. Older versions of Windows 10 will not report the campaignId, newer versions will.

Scenario 2 (Win 10, with an account):

Sign into the Microsoft Store with an account that has never installed Firefox Nightly through the Store before, on Windows 10.
Install Firefox Nightly through the link provided through Slack
Open the Browser Console
Run the following:

let wpm = Cc["@mozilla.org/windows-package-manager;1"].getService(Ci.nsIWindowsPackageManager)
await wpm.campaignId()

Expected resulted: wpm.campaignId should be "bug1830725campaigntest"

Scenario 3 (Win 11, not signed in):

Ensure you are not signed in to the Windows Store, possibly on a fresh, new VM, on Windows 11
Install Firefox Nightly through the link provided through Slack
Open the Browser Console
Run the following:

let wpm = Cc["@mozilla.org/windows-package-manager;1"].getService(Ci.nsIWindowsPackageManager)
await wpm.campaignId()

Expected resulted: wpm.campaignId should be "bug1830725campaigntest"

Scenario 4 (Win 11, signed in):

Sign into the Microsoft Store with an account that has never installed Firefox Nightly through the Store before, on Windows 11. This might have to be a completely clean install of Windows 11 / VM, as Microsoft caches the values aggressively.
Install Firefox Nightly through the link provided through Slack
Open the Browser Console
Run the following:

let wpm = Cc["@mozilla.org/windows-package-manager;1"].getService(Ci.nsIWindowsPackageManager)
await wpm.campaignId()

Expected resulted: wpm.campaignId should be "bug1830725campaigntest"

Scenario 5 (Win 10 or 11, signed in or not signed in):

Remove the cid=bug1830725campaigntest from the url provided through Slack
Install Firefox Nightly through the link with the cid portion
Open the Browser Console
Run the following:

let wpm = Cc["@mozilla.org/windows-package-manager;1"].getService(Ci.nsIWindowsPackageManager)
await wpm.campaignId()

Expected resulted: wpm.campaignId should be ""
To reproduce that, you might need to use a fresh install of Windows, as the campaign id is aggressively cached.

Comment 21

[Michael Hughes]

As per the above comment, the fix for this is done and I've confirmed myself that it works. It will be landed as soon as I get the right permissions to land code changes, or someone else on my team lands it (hopefully either is shortly).

Comment 22

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1756209

Comment 23

[Dianna Smith [:diannaS] - on Leave, back on August 9th]

any updates on this landing?

Comment 24

[Michael Hughes]

It's pending review. Hoping to land it in the next day or two.

Comment 25

[Alexandru Trif, Desktop QA [:atrif]]

Hello! Here are the results after testing using steps from comment 20:

Scenario 1 (W10 and no MS store account):

• A. Fresh Win10 VM install (before Windows update; V:22H2 OS:19045.2965) -> running the command shows a completely blank result: ""

• B. Fresh Win10 VM install (after windows update; V:22H2 OS: 19045.3636) -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

Scenario 2 (W10 and MS store account in store):

• A. Fresh Win10 VM install (before windows update; V:22H2 OS:19045.2965) -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

• B. Fresh Win10 VM install (after windows update; V:22H2 OS: 19045.3636) -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

Scenario 3 (W11 and no MS store account):

• A. Windows 11 23H2 (22621.22428) fresh VM install - I was initially signed into the MS store due to Microsoft requesting an account upon installing Windows 11 and then signed out from the MS store and followed the steps from scenario 3 -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

• B. Fresh Win11 22H2 VM install - installed Win 11 by blocking Windows account creation on install
  -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

Scenario 4 (W11 and newly created MS store account in store):

• A. Fresh and Snapshot VM Windows 11 23H2 (22621.22428) and 22H2 (updated to 22621.2428) -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

Scenario 5 (build link without the “cid” part):

1. Fresh/Snapshot W1123H2 signed in and 22H2 not signed in -> running the command shows: "bug1830725campaigntest&msstoresignedin=true"

2. Fresh Win10 VM install (after windows update; V:22H2 OS: 19045.3636 -> running the command shows: "bug1830725campaigntest&msstoresignedin=true”

General notes:

• testing was performed only on VMs
• we also used the Snapshot VM feature in some cases to restore the Windows VM after the installation was performed
• Firefox Nightly could not be opened only after installing Latest supported Visual C++ Redistributable
• new Microsoft accounts were created when needed
• scenarios 1,2,3,4 were tested with cid=bug1830725campaigntest and scenario 5 without the cid=bug1830725campaigntest.
• this version of Firefox nightly is slower compared to other Windows applications.

If more information is needed please let us know. Thank you!

Comment 26

[Michael Hughes]

Thank you for running through all that. The results are as expected with the exception of scenario 5.
I’d like to find a valid test scenario that proves out the cid being reported as blank in win11. I’ll try to repro that myself.

The build I submitted to test in the store was built in debug and was expected to run slow. My changes will not affect performance when landed.

Comment 27

[Michael Hughes]

The only way I can figure out how to reliably get a blank CID is to use a non-VM. Even a fresh, new virtual machine, run from my local machine, resulted in a cached campaign id.

To confirm that the campaign id was not reported when the url for the store is missing the cid field, I launched a new instance on Azure of Windows 11 and then used the link, installed Firefox, and repeated the steps to get the campaign id in the console. In that instance, it appeared as blank.

I'm going to land this now. It's been thoroughly tested at this point.

Comment 28

[Solway]

Is this still waiting to be applied?
I was hoping 120 had the fix...
It's crazy waiting 10secs for Firefox to open. Only reason we are using the store version is for ease of intune deployment.

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/416268cc8a36
Synchronous `nsWindowsPackageManager::GetCampaignId` blocks main thread for many seconds r=bytesized,nrishel

Comment 30

[Norisz Fay [:noriszfay]]

Backed out for causing bc failures on browser_AttributionCode_telemetry.js

Backout link

Push with failures

Failure log

There's also a tier 2 perma Windows MinGW bustage. Failure log here

Comment 31

[Markus Stange [:mstange]]

(In reply to James Teh [:Jamie] from comment #5)

It might be useful to get a profile including the "COM MTA" thread so we can see the stack for that thread.

I think so too.

Can someone who sees this capture another profile? Please follow the instructions from comment 2, with one adjustment: In addition to setting the MOZ_PROFILER_STARTUP environment variable to 1, also set the MOZ_PROFILER_STARTUP_FILTERS variable to GeckoMain,MTA . Thanks!

Comment 32

[Markus Stange [:mstange]]

Andrew, see comment 31, it would be very interesting if we could get another profile with additional information.

Comment 33

[Solway]

Added both environment variables and launched firefox
here's a profile. I have 2 extensions (bitwarden and ublock) and its got policies applied from company admx.
https://share.firefox.dev/482t40n

can test on other PCs, or VM's if required.

Comment 34

[Michael Hughes]

Removing the needs info on this for me. I need to figure out what broke, fix it, and then reland this. Hopefully soon.

Comment 35

[Markus Stange [:mstange]]

(In reply to Solway from comment #33)

Added both environment variables and launched firefox
here's a profile. I have 2 extensions (bitwarden and ublock) and its got policies applied from company admx.
https://share.firefox.dev/482t40n

Thank you! This shows that the delay is not the waiting for the MTA thread to become available; it's waiting for the synchronous running of the lambda that calls GetStoreProductForCurrentAppAsync, which blocks on this WaitForSingleObject call: https://searchfox.org/mozilla-central/rev/1a63fee6c2a8ea6846f6f16b85edeb6d19fc9f23/toolkit/system/windowsPackageManager/nsWindowsPackageManager.cpp#207
And that WaitForSingleObject call is removed by the patch in this bug. Great!

Comment 36

[BugBot [:suhaib / :marco/ :calixte]]

There is an r+ patch which didn't land and no activity in this bug for 2 weeks.
:mhughes, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit BugBot documentation.

Comment 37

[Robin Steuber (they/them) [:bytesized]]

I'll leave this for mhughes to answer.

Comment 38

[Michael Hughes]

I'm working on this. Again.

Comment 39

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f7c78cadff5d
Synchronous `nsWindowsPackageManager::GetCampaignId` blocks main thread for many seconds r=nrishel

Comment 40

[Iulian Moraru]

Backed out for causing bc failures on browser_AttributionCode_telemetry.js. And this also caused Bug 1872933.(which will be closed because of this backout).

• Push with failures

• Failure log

• Backout link

[task 2024-01-03T22:41:00.570Z] 22:41:00     INFO - TEST-PASS | browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js | Shouldn't be able to get a result if the file doesn't exist - {} deepEqual {} - 
[task 2024-01-03T22:41:00.570Z] 22:41:00     INFO - Leaving test bound test_parse_error
[task 2024-01-03T22:41:00.571Z] 22:41:00     INFO - Entering test bound test_read_error
[task 2024-01-03T22:41:00.571Z] 22:41:00     INFO - Buffered messages finished
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - TEST-UNEXPECTED-FAIL | browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js | expected counts should match for BROWSER_ATTRIBUTION_ERRORS at index 0 - 0 == 1 - {"filename":"resource://testing-common/TelemetryTestUtils.sys.mjs","name":"assertHistogram","sourceId":615,"lineNumber":353,"columnNumber":16,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js","name":"test_read_error","sourceId":614,"lineNumber":100,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":567,"lineNumber":1138,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":567,"lineNumber":1210,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":567,"lineNumber":1352,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":567,"lineNumber":1127,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":592,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_read_error@chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:100:22\nasync*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"assertHistogram@resource://testing-common/TelemetryTestUtils.sys.mjs:353:16\ntest_read_error@chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:100:22\nasync*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - Stack trace:
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - resource://testing-common/TelemetryTestUtils.sys.mjs:assertHistogram:353
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:test_read_error:100
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:handleTask:1138
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1210
[task 2024-01-03T22:41:00.577Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1352
[task 2024-01-03T22:41:00.578Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1127
[task 2024-01-03T22:41:00.578Z] 22:41:00     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2024-01-03T22:41:00.578Z] 22:41:00     INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - TEST-UNEXPECTED-FAIL | browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js | unexpected counts should be zero for BROWSER_ATTRIBUTION_ERRORS at index 1 - 1 == 0 - {"filename":"resource://testing-common/TelemetryTestUtils.sys.mjs","name":"assertHistogram","sourceId":615,"lineNumber":359,"columnNumber":16,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js","name":"test_read_error","sourceId":614,"lineNumber":100,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":567,"lineNumber":1138,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":567,"lineNumber":1210,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":567,"lineNumber":1352,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":567,"lineNumber":1127,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":592,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_read_error@chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:100:22\nasync*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"assertHistogram@resource://testing-common/TelemetryTestUtils.sys.mjs:359:16\ntest_read_error@chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:100:22\nasync*handleTask@chrome://mochikit/content/browser-test.js:1138:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1127:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - Stack trace:
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - resource://testing-common/TelemetryTestUtils.sys.mjs:assertHistogram:359
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochitests/content/browser/browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js:test_read_error:100
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:handleTask:1138
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1210
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1352
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1127
[task 2024-01-03T22:41:00.584Z] 22:41:00     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2024-01-03T22:41:00.585Z] 22:41:00     INFO - TEST-PASS | browser/components/attribution/test/browser/browser_AttributionCode_telemetry.js | unexpected counts should be zero for BROWSER_ATTRIBUTION_ERRORS at index 2 - 0 == 0 - 

Comment 41

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cfe5c8e2684f
Synchronous `nsWindowsPackageManager::GetCampaignId` blocks main thread for many seconds r=nrishel

Comment 42

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/cfe5c8e2684f

Comment 43

[Alexandru Trif, Desktop QA [:atrif]]

Hello! Should we perform some additional testing here? If yes, should we test scenarios from comment 20 again? Thank you!

Comment 44

[Michael Hughes]

(In reply to Alexandru Trif, Desktop QA [:atrif] from comment #43)

Hello! Should we perform some additional testing here? If yes, should we test scenarios from comment 20 again? Thank you!

Yes please! Best way to test is with the released build.

Comment 45

[Alexandru Trif, Desktop QA [:atrif]]

I spoke with Michael on Slack and this cannot yet be tested because we need a Firefox 123 release build on the Microsoft store. He also said that maybe it will provide a custom-build in the Microsoft store. Clearing ni? until we can start testing here.

Comment 46

[Alexandru Trif, Desktop QA [:atrif]]

Tested with Firefox 124.0a1 (2024-02-06) using the link provided from Slack as follows:

Scenario 1 (W10 and no MS store account):

• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 2 (W10 and newly created MS store account):

• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX with cid -> running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 3 (Win 11, not signed in):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 4 (Win 11, signed in):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 5 (build link without the “cid” part):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX without cid -> Running the snippet shows:
  ""
• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX without cid and without MS account -> running the snippet 2 times on new different VMs and I got: "bug1830725campaigntest&msstoresignedin=true" once and then "whatever_the_campaign_id_should_be&msstoresignedin=true"

We then tried on another two different machines and we got these results:

• Fresh VM install Windows 10x64 22H2 (no cid and no MS account) 19045.3803> installed Firefox MSIX -> running the snippet shows “”. We updated to build 19045.3996 and still got an empty result as previous after running the snippet
• Fresh VM install Windows 10x64 22H2 (no cid and no MS account) on another PC (different from previous two) and updated to 19045.3930> installed Firefox MSIX -> running the snippet shows: ""

I repeated Scenario 1 (W10 and no MS store account with cid included in the link) on the pc where I got a good result on scenario 5 and I received "". We have different results across different machines for some reason.
Also It seems that for scenario 5 on one machine we got unexpected results, but we then got expected results on another machine on Windows 10x64. Are these results expected? Thank you!

Comment 47

[Bogdan Maris, Desktop Test Engineering]

I also tested all the scenarios from comment 20 on both Windows 10 and Windows 11 on VMs and I can confirm that I received all the expected results for scenarios 1 to 5.

Comment 48

[Michael Hughes]

(In reply to Alexandru Trif, Desktop QA [:atrif] from comment #46)

Tested with Firefox 124.0a1 (2024-02-06) using the link provided from Slack as follows:

Scenario 1 (W10 and no MS store account):

• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 2 (W10 and newly created MS store account):

• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX with cid -> running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 3 (Win 11, not signed in):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 4 (Win 11, signed in):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX with cid -> Running the snippet shows: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario 5 (build link without the “cid” part):

• Fresh VM install Windows 11x64 23H2 updated to build 22631.3085, installed Firefox 124.0a1 MSIX without cid -> Running the snippet shows:
  ""
• Fresh VM install Windows 10x64 22H2 updated to build 19045.3996, installed Firefox 124.0a1 MSIX without cid and without MS account -> running the snippet 2 times on new different VMs and I got: "bug1830725campaigntest&msstoresignedin=true" once and then "whatever_the_campaign_id_should_be&msstoresignedin=true"

We then tried on another two different machines and we got these results:

• Fresh VM install Windows 10x64 22H2 (no cid and no MS account) 19045.3803> installed Firefox MSIX -> running the snippet shows “”. We updated to build 19045.3996 and still got an empty result as previous after running the snippet
• Fresh VM install Windows 10x64 22H2 (no cid and no MS account) on another PC (different from previous two) and updated to 19045.3930> installed Firefox MSIX -> running the snippet shows: ""

I repeated Scenario 1 (W10 and no MS store account with cid included in the link) on the pc where I got a good result on scenario 5 and I received "". We have different results across different machines for some reason.
Also It seems that for scenario 5 on one machine we got unexpected results, but we then got expected results on another machine on Windows 10x64. Are these results expected? Thank you!

Did it really say msstoresignedin=true in every case? The ones where the MS account was not signed in should have said msstoresignedin=false. I don't think I called that out in Comment 20. Apologies.

Answering your question: Microsoft aggressively caches info and I found it was fairly inconsistent when testing across different VMs. I suspect Microsoft does some stuff even based on IP address, because I was getting results I shouldn't have across multiple different VMs running on the same host. I tried to use a VPN and that didn't help.

Other than my concerns about msstoresignedin=true when it should be false sometimes, this all appears to be working as expected. I was mostly concerned about causing breaks / slowdowns. The actual values reported are tough to determine as working perfectly given it's difficult to actually create a clean environment.

Is it possible to get this tested again to confirm that msstoresignedin=false in some cases where the user is not signed in?

Comment 49

[Alexandru Trif, Desktop QA [:atrif]]

(In reply to Michael Hughes from comment #48)

Is it possible to get this tested again to confirm that msstoresignedin=false in some cases where the user is not signed in?

Hello! We retested this without a Windows and Microsoft Store account and we got the same results as we had above. Note that this was tested on two different machines using VMs.

Scenario1: Win10 - no Windows account and no MS Store account -Fresh install then updated to 19045.4046: "whatever_the_campaign_id_should_be&msstoresignedin=true"
Scenario 5: Win10 - no Windows account and no MS Store account -Fresh install then updated to 19045.4046: "whatever_the_campaign_id_should_be&msstoresignedin=true"

Scenario3: Win11 - no Windows account and no MS Store account -Fresh install then updated to latest:"whatever_the_campaign_id_should_be&msstoresignedin=true"
Scenario 5: Win11 - no Windows account and no MS Store account -Fresh install then updated to latest: ""