Open Bug 1752482 Opened 4 years ago Updated 2 years ago

[macOS 11] Perma uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true

Categories

(Firefox :: File Handling, defect, P3)

defect

Tracking

()

ASSIGNED
Tracking Status
firefox-esr91 --- unaffected
firefox97 --- unaffected
firefox98 --- disabled
firefox99 --- disabled

People

(Reporter: intermittent-bug-filer, Assigned: Gijs, NeedInfo)

References

(Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell disabled][stockwell unknown])

Attachments

(1 file)

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=365872818&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/H95zb974RcW75KSkgqDfFA/runs/0/artifacts/public/logs/live_backing.log


[task 2022-01-28T06:21:56.451Z] 06:21:56     INFO - TEST-START | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js
<...>
[task 2022-01-28T06:22:14.744Z] 06:22:14     INFO - TEST-PASS | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | File contentType should be correct - 
[task 2022-01-28T06:22:14.745Z] 06:22:14     INFO - TEST-PASS | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | File name should be correct. - 
[task 2022-01-28T06:22:14.746Z] 06:22:14     INFO - TEST-PASS | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | download should appear in public list - 
[task 2022-01-28T06:22:14.748Z] 06:22:14     INFO - TEST-PASS | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | preferredAction - Pref enabled - choose internal + alwaysAsk default + checkbox should update persisted default - 
[task 2022-01-28T06:22:14.754Z] 06:22:14     INFO - TEST-PASS | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | alwaysAskBeforeHandling - Pref enabled - choose internal + alwaysAsk default + checkbox should update persisted default - 
[task 2022-01-28T06:22:14.756Z] 06:22:14     INFO - Cleaning up
[task 2022-01-28T06:22:14.758Z] 06:22:14     INFO - Testing with file_image_svgxml.svg; Pref enabled - saveToDisk with alwaysAsk default should update persisted default
[task 2022-01-28T06:22:14.760Z] 06:22:14     INFO - Load window and tabs
[task 2022-01-28T06:22:14.763Z] 06:22:14     INFO - Console message: [JavaScript Error: "[Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isExecutable]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/DownloadIntegration.jsm :: launchDownload :: line 758"  data: no]"]
[task 2022-01-28T06:22:14.764Z] 06:22:14     INFO - launchDownload@resource://gre/modules/DownloadIntegration.jsm:758:12
[task 2022-01-28T06:22:14.765Z] 06:22:14     INFO - launch@resource://gre/modules/DownloadCore.jsm:801:32
[task 2022-01-28T06:22:14.766Z] 06:22:14     INFO - _succeed@resource://gre/modules/DownloadCore.jsm:598:12
[task 2022-01-28T06:22:14.767Z] 06:22:14     INFO - 
[task 2022-01-28T06:22:14.768Z] 06:22:14     INFO - Buffered messages finished
[task 2022-01-28T06:22:14.770Z] 06:22:14     INFO - TEST-UNEXPECTED-FAIL | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true
[task 2022-01-28T06:22:14.771Z] 06:22:14     INFO - Stack trace:
[task 2022-01-28T06:22:14.772Z] 06:22:14     INFO - chrome://mochikit/content/browser-test.js:test_is:1403
[task 2022-01-28T06:22:14.773Z] 06:22:14     INFO - chrome://mochitests/content/browser/uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js:test_check_saving_handler_choices_with_downloads_pref_enabled:405
[task 2022-01-28T06:22:14.835Z] 06:22:14     INFO - GECKO(20128) | -----------------------------------------------------
[task 2022-01-28T06:22:14.838Z] 06:22:14     INFO - GECKO(20128) | Suppressions used:
[task 2022-01-28T06:22:14.840Z] 06:22:14     INFO - GECKO(20128) |   count      bytes template
[task 2022-01-28T06:22:14.842Z] 06:22:14     INFO - GECKO(20128) |      13        416 nsComponentManagerImpl
[task 2022-01-28T06:22:14.843Z] 06:22:14     INFO - GECKO(20128) |       2        288 libfontconfig.so
[task 2022-01-28T06:22:14.844Z] 06:22:14     INFO - GECKO(20128) | -----------------------------------------------------
[task 2022-01-28T06:23:26.479Z] 06:23:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-01-28T06:23:26.480Z] 06:23:26     INFO - TEST-UNEXPECTED-FAIL | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | Test timed out - 
[task 2022-01-28T06:23:26.487Z] 06:23:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-01-28T06:23:26.488Z] 06:23:26     INFO - TEST-UNEXPECTED-FAIL | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | Uncaught exception received from previously timed out test - popupshown listener on #downloadsPanel not removed before the end of test
[task 2022-01-28T06:23:26.496Z] 06:23:26     INFO - GECKO(20128) | MEMORY STAT | vsize 20975920MB | residentFast 1582MB
[task 2022-01-28T06:23:26.499Z] 06:23:26     INFO - TEST-OK | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | took 90047ms
[task 2022-01-28T06:23:26.500Z] 06:23:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-01-28T06:23:26.501Z] 06:23:26     INFO - TEST-UNEXPECTED-FAIL | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | Found a tab after previous test timed out: about:blank - 
[task 2022-01-28T06:23:26.609Z] 06:23:26     INFO - checking window state
[task 2022-01-28T06:23:26.614Z] 06:23:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-01-28T06:23:26.618Z] 06:23:26     INFO - TEST-UNEXPECTED-FAIL | uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | Found a  after previous test timed out - 
[task 2022-01-28T06:23:26.619Z] 06:23:26     INFO - GECKO(20128) | must wait for focus
[task 2022-01-28T06:23:26.854Z] 06:23:26     INFO - TEST-START | uriloader/exthandler/tests/mochitest/browser_pdf_save_as.js

Flags: needinfo?(gijskruitbosch+bugs)
Summary: Intermittent uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true → Perma uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true

(In reply to Andreea Pavel [:apavel] from comment #2)

This is permafailing since bug 1750253 landed: https://treeherder.mozilla.org/jobs?repo=mozilla-central&group_state=expanded&resultStatus=success%2Cpending%2Crunning%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=7a264eeeb866491cb9550c2fcb316aa7c6e8548b&searchStr=os%2Cx%2C11%2Cwebrender%2Cshippable%2Copt%2Cmochitests%2Ctest-macosx1100-64-shippable-qr%2Fopt-mochitest-browser-chrome-e10s%2Cbc4&selectedTaskRun=EQr2TTjyTomVaBFYo5yrFA.0
@Gijs can you please take a look?

I would love to, but as I noted in bug 1750253 comment 13, it was green on try. I'm not sure how to debug this if it's consistently green on try (and locally) but orange on central. :-
If it was orange on try I could add logging to find out why it was orange, but that doesn't work for autoland, unless I start landing patches to add automation-only logging. I can do that, but then we should make sure we can also reproduce the problem on autoland, so I don't have to wait 12-24h every time for the added logging to make it to central. Would that work, or am I missing an easier option? (Can we at least try if we can see this orange on autoland if we add the relevant jobs there?

Do you have other suggestions?

Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(apavel)

This backfill shows that Bug 1750253 is indeed the one that caused this perma failure.
This job doesn't run by default on autoland. Here you can see the jobs that run by default on autoland on OS X 11 WebRender Shippable.

Flags: needinfo?(apavel) → needinfo?(gijskruitbosch+bugs)
Regressed by: 1750253

(In reply to Iulian Moraru from comment #5)

This backfill shows that Bug 1750253 is indeed the one that caused this perma failure.
This job doesn't run by default on autoland. Here you can see the jobs that run by default on autoland on OS X 11 WebRender Shippable.

Sure, that still doesn't explain why the same tests running on m-c were all green on try... The parent rev was 4bff0b888cd9a91b7cb4dc3d35951160e39aa0ae, which is a merge from Tuesday, well after the patch from bug 1750253 had first landed and been backed out for similar orange - so it's pretty unlikely that it's some kind of interaction with another patch that was on central but not on try.

I'll try adding the same logging into the relevant code on autoland on Monday, and then seeing if that can help explain what's happening. But the whole thing is definitely very much non-obvious, and if the machine pools for try and autoland/central are different, perhaps there's some config difference, as I think the failure of the test would be explained by the under-test copy of nightly/firefox thinking it is the default handler for some filetype (hence the logging I added in the trypush; I'll add it into autoland but behind a check to see if we're in automation, to avoid spamming real users).

Hi Aryx, could you give your input on this? Something we missed between autoland and try?

Flags: needinfo?(aryx.bugmail)
Whiteboard: [stockwell needswork:owner]

The issue also affects the central-as-beta simulations on Try. See the guide how to run such a simulation.

Also observed: https://searchfox.org/mozilla-central/rev/855b2af753bc01bf27fc1b9f2d0184a0a440773d/uriloader/exthandler/nsExternalHelperAppService.cpp#698 lists the file types for which descriptions are supposed to be provided by unknownContentType.properties. The former lists jxl before svg and there is no description for it in the latter file - could this break initialization of download UI in any way?

Flags: needinfo?(aryx.bugmail)
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Keywords: leave-open
Severity: S4 → S2
Priority: P5 → P1
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/c8abc89e09ce skip browser_open_internal_choice_persistence.js on apple silicon for now, r=aryx DONTBUILD
Has Regression Range: --- → yes

OK, so one of my earlier suspicions was right, when things break we log:

[task 2022-02-07T13:03:23.937Z] 13:03:23     INFO - GECKO(5393) | App for image/svg+xml is the OS default.

with this patch:

https://hg.mozilla.org/try/rev/6db5bed7f393cdb716c64d6637aba65c4043c8fe

whereas my earlier trypush, which only ran the tests in this manifest, prints:

[task 2022-02-03T11:14:02.481Z] 11:14:02     INFO - GECKO(4191) | App for image/svg+xml is not the OS default.

which means we must have hit: https://searchfox.org/mozilla-central/rev/072f9e6b7f10a00e12d0a02ac713431d0a7ee368/uriloader/exthandler/mac/nsOSHelperAppService.mm#514 in the failing run, which means one of the earlier tests, has somehow convinced the OS that we should be the OS default for SVG files - or has convinced us that that is what the OS thinks. The latter is a bit less likely because we restart the browser with a fresh profile between every manifest run (AIUI) so I don't see how we would have persisted any in-app state.

That is... very strange. And I'm not sure how to work out which test it is - in the failing chunks, the uriloader tests run last, in this list:

[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -  'MOZHARNESS_TEST_PATHS': '{"mochitest-browser-chrome": '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '["accessible/tests/browser/events/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"accessible/tests/browser/fission/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"accessible/tests/browser/general/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/actors/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/base/content/test/alerts/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/base/content/test/metaTags/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/base/content/test/pageinfo/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/base/content/test/protectionsUI/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/base/content/test/utilityOverlay/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/enterprisepolicies/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/enterprisepolicies/tests/browser/disable_forget_button/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/originattributes/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/pagedata/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/protocolhandler/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/safebrowsing/content/test/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/search/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/components/urlbar/tests/quicksuggest/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"browser/modules/test/browser/formValidation/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"dom/fetch/tests/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"dom/media/mediacontrol/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"dom/notification/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"dom/reporting/tests/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"dom/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.957Z] 12:48:27     INFO -                           '"editor/libeditor/tests/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"ipc/glue/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/extensions/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/glean/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/messaging-system/schemas/TriggerActionSchemas/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/remotebrowserutils/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/remotepagemanager/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/components/startup/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/mozapps/downloads/tests/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"toolkit/mozapps/extensions/test/browser/browser.ini", '
[task 2022-02-07T12:48:27.958Z] 12:48:27     INFO -                           '"uriloader/exthandler/tests/mochitest/browser.ini"]}',

I can try to bisect it on try, but that will take a while. Is there a better path forward here?

Has Regression Range: yes → ---
Flags: needinfo?(gijskruitbosch+bugs)
Flags: needinfo?(dhouse)
Flags: needinfo?(aryx.bugmail)
Keywords: regression
Has Regression Range: --- → yes
Keywords: regression

Based on searches, the following three test directories are interesting because they use SVG files different from chrome-protocol urls:

  • browser/base/content/test/pageinfo/browser.ini
  • dom/tests/browser/browser.ini
  • editor/libeditor/tests/browser.ini

Let me know if I shall do the bisection.

Flags: needinfo?(aryx.bugmail)

(In reply to Pulsebot from comment #11)

Pushed by gijskruitbosch@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/c8abc89e09ce
skip browser_open_internal_choice_persistence.js on apple silicon for now,
r=aryx DONTBUILD

And on beta.
https://hg.mozilla.org/releases/mozilla-beta/rev/e46d4f692868

(In reply to Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout) from comment #13)

Based on searches, the following three test directories are interesting because they use SVG files different from chrome-protocol urls:

  • browser/base/content/test/pageinfo/browser.ini
  • dom/tests/browser/browser.ini
  • editor/libeditor/tests/browser.ini

Let me know if I shall do the bisection.

I think I had a better idea, which is just fail tests that finish with us as the default SVG handler. Trypush: https://treeherder.mozilla.org/jobs?repo=try&revision=ffc611121f6cd5410a00cd91a175b5ad93f99463

Flags: needinfo?(gijskruitbosch+bugs)

Just when you think this couldn't get weirder:

https://treeherder.mozilla.org/jobs?repo=try&revision=ffc611121f6cd5410a00cd91a175b5ad93f99463

the first manifest that runs is accessible/tests/browser/events/browser.ini. After the last test in that manifest, we don't think we're the default app for SVG files.

After the first test of the next manifest ( accessible/tests/browser/fission/browser_content_tree.js), we do.

I don't think any of these tests do anything to try and make themselves the default browser or the default SVG handling app.

I've triggered the other mochitest browser jobs to see if it's just happening everywhere, but this is the only test that has an issue with being the default SVG handler.

I'm still confused about how the one-off binary that's being run ends up being the default for anything (again, doesn't happen on macOS 10.15 or any other OS, afaict)

(In reply to :Gijs (he/him) from comment #16)

I've triggered the other mochitest browser jobs to see if it's just happening everywhere, but this is the only test that has an issue with being the default SVG handler.

This appears to be happening everywhere - ie the first run of the app to run tests is fine, and the second run thinks it's the default handler for SVG files.

This explains why my original trypushes in bug 1750253 didn't reproduce the orange: I ran with just the relevant directory of tests, so they were always the first to run.

Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][stockwell disabled]

(In reply to :Gijs (he/him) from comment #17)

(In reply to :Gijs (he/him) from comment #16)

I've triggered the other mochitest browser jobs to see if it's just happening everywhere, but this is the only test that has an issue with being the default SVG handler.

This appears to be happening everywhere - ie the first run of the app to run tests is fine, and the second run thinks it's the default handler for SVG files.

This explains why my original trypushes in bug 1750253 didn't reproduce the orange: I ran with just the relevant directory of tests, so they were always the first to run.

... but somehow this trypush was green: https://treeherder.mozilla.org/jobs?repo=try&revision=56eb6ec2f1b4bd1dc0fed2a702d8ca6976a7e8ef (restricted to 2 manifests)

but this one was not: https://treeherder.mozilla.org/jobs?repo=try&revision=e39245b724d1d1054f65207e816b4aaea5dbf7ab (not test-path restricted, just running the chunk that is hitting this particular test; otherwise same commits + base commit). I have absolutely no clue why that difference exists.

The additional logging shows that we genuinely think that the precise unpacked fx binary we're testing is what is the OS default for SVG files. It also shows that when the test job starts executing, it thinks the default is Safari. Unfortunately we have no idea why it's changing (or, more precisely, why firefox thinks it's different now).

I have other high-prio stuff to chase so more updates here may take a bit longer. For now central and beta are happy because the failing test is disabled, but given the strange environment implications here we should probably get to the bottom of this. If anyone has helpful ideas of what might be wrong here, they would be appreciated. Someone has already suggested some kind of OS bug, see e.g. this sad tale relating to mailto defaults. Still, extraordinary claims require extraordinary evidence, so this probably needs a bit more digging.

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

Severity: S2 → S3
Priority: P1 → P3

All the recent instances are on other platforms and caused by other issues, so clarifying summary so people file new bugs in future when starring those.

Summary: Perma uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true → [macOS 11] Perma uriloader/exthandler/tests/mochitest/browser_open_internal_choice_persistence.js | UCT window should have appeared - Got false, expected true
See Also: → 1757944

Clear a needinfo that is pending on an inactive user.

Inactive users most likely will not respond; if the missing information is essential and cannot be collected another way, the bug maybe should be closed as INCOMPLETE.

For more information, please visit BugBot documentation.

Flags: needinfo?(dhouse)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: