Closed Bug 1831631 Opened 2 years ago Closed 2 years ago

Frequent toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug

Categories

(Toolkit :: Background Tasks, defect, P5)

defect

Tracking

()

RESOLVED FIXED
115 Branch
Tracking Status
firefox-esr102 --- unaffected
firefox113 --- unaffected
firefox114 --- wontfix
firefox115 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: saschanaz)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Attachments

(1 file)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=414783935&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ecGpT_IvTlCpGpJsaFKYOg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ecGpT_IvTlCpGpJsaFKYOg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2023-05-05T17:51:19.517Z] 17:51:19     INFO -  TEST-PASS | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | test_aLotOfTasks - [test_aLotOfTasks : 236] leaf8.abc should not exist - false == false
[task 2023-05-05T17:51:19.517Z] 17:51:19  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | test_aLotOfTasks - [test_aLotOfTasks : 235] Task 9 should succeed - 1 == 0
[task 2023-05-05T17:51:19.518Z] 17:51:19     INFO -  Z:/task_168330800551952/build/tests/xpcshell/tests/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js:test_aLotOfTasks:235
[task 2023-05-05T17:51:19.518Z] 17:51:19     INFO -  Z:\task_168330800551952\build\tests\xpcshell\head.js:_do_main:238
[task 2023-05-05T17:51:19.518Z] 17:51:19     INFO -  Z:\task_168330800551952\build\tests\xpcshell\head.js:_execute_test:585
[task 2023-05-05T17:51:19.519Z] 17:51:19     INFO -  -e:null:1
[task 2023-05-05T17:51:19.519Z] 17:51:19     INFO -  exiting test
[task 2023-05-05T17:51:19.519Z] 17:51:19     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2023-05-05T17:51:19.519Z] 17:51:19     INFO -  _abort_failed_test@Z:\task_168330800551952\build\tests\xpcshell\head.js:868:20
[task 2023-05-05T17:51:19.519Z] 17:51:19     INFO -  do_report_result@Z:\task_168330800551952\build\tests\xpcshell\head.js:977:5
[task 2023-05-05T17:51:19.520Z] 17:51:19     INFO -  Assert<@Z:\task_168330800551952\build\tests\xpcshell\head.js:71:21
[task 2023-05-05T17:51:19.520Z] 17:51:19     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2023-05-05T17:51:19.520Z] 17:51:19     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2023-05-05T17:51:19.521Z] 17:51:19     INFO -  test_aLotOfTasks@Z:/task_168330800551952/build/tests/xpcshell/tests/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js:235:10
[task 2023-05-05T17:51:19.521Z] 17:51:19     INFO -  _do_main@Z:\task_168330800551952\build\tests\xpcshell\head.js:238:6
[task 2023-05-05T17:51:19.521Z] 17:51:19     INFO -  _execute_test@Z:\task_168330800551952\build\tests\xpcshell\head.js:585:5
[task 2023-05-05T17:51:19.522Z] 17:51:19     INFO -  @-e:1:1
[task 2023-05-05T17:51:19.522Z] 17:51:19     INFO -  exiting test
[task 2023-05-05T17:51:19.522Z] 17:51:19     INFO -  PID 8812 | [Parent 8812, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-05T17:51:19.522Z] 17:51:19     INFO -  PID 8812 | [Parent 8812, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3376
[task 2023-05-05T17:51:19.523Z] 17:51:19     INFO -  PID 8812 | [Parent 8812, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-05T17:51:19.523Z] 17:51:19     INFO -  PID 8812 | [Parent 8812, Main Thread] WARNING: XPCOM object PerThreadData destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:216
[task 2023-05-05T17:51:19.524Z] 17:51:19     INFO -  PID 8812 | [Parent 8812, Main Thread] WARNING: XPCOM object SourceList destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:216
[task 2023-05-05T17:51:19.524Z] 17:51:19     INFO -  <<<<<<<
[task 2023-05-05T17:51:19.524Z] 17:51:19     INFO -  TEST-START | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js
[task 2023-05-05T17:51:33.417Z] 17:51:33  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | xpcshell return code: 0
[task 2023-05-05T17:51:33.422Z] 17:51:33     INFO -  TEST-INFO took 13897ms
[task 2023-05-05T17:51:33.422Z] 17:51:33     INFO -  >>>>>>>
[task 2023-05-05T17:51:33.422Z] 17:51:33     INFO -  PID 2456 | DLL blocklist was unable to intercept AppInit DLLs.
[task 2023-05-05T17:51:33.423Z] 17:51:33     INFO -  PID 2456 | [Parent 2456, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:132
[task 2023-05-05T17:51:33.423Z] 17:51:33     INFO -  PID 2456 | [Parent 2456, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:132
[task 2023-05-05T17:51:33.423Z] 17:51:33     INFO -  PID 2456 | [Parent 2456, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2908
[task 2023-05-05T17:51:33.424Z] 17:51:33     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-05-05T17:51:33.424Z] 17:51:33     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-05-05T17:51:33.425Z] 17:51:33     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-05-05T17:51:33.425Z] 17:51:33     INFO -  running event loop
[task 2023-05-05T17:51:33.425Z] 17:51:33     INFO -  toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | Starting test_simple
[task 2023-05-05T17:51:33.425Z] 17:51:33     INFO -  (xpcshell/head.js) | test test_simple pending (2)
[task 2023-05-05T17:51:33.426Z] 17:51:33     INFO -  TEST-PASS | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | test_simple - [test_simple : 23] true == true

:saschanaz, since you are the author of the regressor, bug 1831154, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(krosylight)

Honestly have no idea. https://searchfox.org/mozilla-central/rev/2c11f18f89056a806c299a9d06bfa808718c2e84/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js#206-208 implies this has already been a problem.

// This test creates a large number of tasks and directories.  Spawning a huge
// number of tasks concurrently (say, 50 or 100) appears to cause problems;
// since doing so is rather artificial, we haven't tracked this down.

Valentin, has there any update after that comment? Somehow it fails after ~10 tasks inside TV 🤔

Flags: needinfo?(krosylight) → needinfo?(valentin.gosu)
Duplicate of this bug: 1831645
Summary: Intermittent TV toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug → Intermittent toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug

So failures are all on Windows debug build. Maybe the repeated stderr/stdout handling is bad on Windows?

But Windows doesn't really have the console output problem, why do we have this part? https://searchfox.org/mozilla-central/rev/2c11f18f89056a806c299a9d06bfa808718c2e84/toolkit/xre/nsAppRunner.cpp#3904-3907

Nick, did you see the problem on Windows when implementing it? Can we skip it on Windows?

Flags: needinfo?(nalexander)

(In reply to Kagami [:saschanaz] from comment #5)

So failures are all on Windows debug build. Maybe the repeated stderr/stdout handling is bad on Windows?

This is certainly possible, but I don't follow what's leading you to think that it's something to do with stderr/stdout handling.

But Windows doesn't really have the console output problem, why do we have this part? https://searchfox.org/mozilla-central/rev/2c11f18f89056a806c299a9d06bfa808718c2e84/toolkit/xre/nsAppRunner.cpp#3904-3907

Windows does have the console output problem with ./mach run, which adds an --attach-console. It's a problem in debug (separate console) and non-debug (parent console) modes.

Nick, did you see the problem on Windows when implementing it? Can we skip it on Windows?

I added comments and tests to document what I saw. The many tasks issues were all around racing to find ephemeral profile directories and not around output. It's possible the --attach-console business, which is only on Windows debug IIRC, is exacerbating that race.

I'd prefer not to skip this on Windows for the reasons above. I have two suggestions for debugging:

  • use --profile ... to manage the profile directories manually for your test (distinct from the existing stress test, if possible). At least you can be sure that it's not ephemeral profiles in that situation.
  • use --MOZ_LOG=... and --MOZ_LOG_FILE=... to capture logs for these crashing processes. At least then you can get some hints about what's going wrong even when console logging is disabled.

Sorry that I can't be more helpful :(

Flags: needinfo?(nalexander)

Note I also landed bug 1818714 a few days ago, that might have changed the timing/locking too.

(In reply to Kagami [:saschanaz] from comment #2)

Valentin, has there any update after that comment? Somehow it fails after ~10 tasks inside TV 🤔

I assume a change in timing, either from your bug or something else makes that more likely to occur.
If I remember correctly, I could sometimes reproduce this locally. Unfortunately we don't have rr on windows, but maybe logs could tell us why the task is failing?
At worst you could disable that task since it's non-deterministic?

Flags: needinfo?(valentin.gosu)
Summary: Intermittent toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug → Frequent toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug

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

This is certainly possible, but I don't follow what's leading you to think that it's something to do with stderr/stdout handling.

Assuming this is indeed a regression from bug 1831154, I can't think of other possibilities, unless this is actually from bug 1818714 as Valentin says above.

Windows does have the console output problem with ./mach run, which adds an --attach-console. It's a problem in debug (separate console) and non-debug (parent console) modes.

But in what case we run a background task with ./mach run?

Flags: needinfo?(nalexander)

(In reply to Kagami [:saschanaz] from comment #9)

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

This is certainly possible, but I don't follow what's leading you to think that it's something to do with stderr/stdout handling.

Assuming this is indeed a regression from bug 1831154, I can't think of other possibilities, unless this is actually from bug 1818714 as Valentin says above.

I really don't think we can draw this conclusion without a theory of what's happening, and the best way to shape such a theory is to dig into the logging.

If now is not the time to run this down, I'd be fine with disabling the test on Windows debug builds.

Windows does have the console output problem with ./mach run, which adds an --attach-console. It's a problem in debug (separate console) and non-debug (parent console) modes.

But in what case we run a background task with ./mach run?

During development, I do this constantly. Do you not? That surprises me :)

Flags: needinfo?(nalexander)

Oh that was a dumb question, sorry, I mean:

  1. I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
    1. Actually I don't think passing --attach-console makes it attach to the console when opened by Firefox, I still see no message
  2. On ./mach run one would always expect the logs

So where's the need to suppress the log on Windows? This was what I wanted to ask

Flags: needinfo?(nalexander)

(In reply to Kagami [:saschanaz] from comment #11)

Oh that was a dumb question, sorry, I mean:

  1. I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
    1. Actually I don't think passing --attach-console makes it attach to the console when opened by Firefox, I still see no message

This is with a recent install that I was doing some other testing against:

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success --attach-console
console.error: "runBackgroundTask: success"
  1. On ./mach run one would always expect the logs

So where's the need to suppress the log on Windows? This was what I wanted to ask

This was the ticket that motivated the suppression in the first place :). See https://bugzilla.mozilla.org/show_bug.cgi?id=1830384.

Flags: needinfo?(nalexander)

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

(In reply to Kagami [:saschanaz] from comment #11)

Oh that was a dumb question, sorry, I mean:

  1. I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
    1. Actually I don't think passing --attach-console makes it attach to the console when opened by Firefox, I still see no message

This is with a recent install that I was doing some other testing against:

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success --attach-console
console.error: "runBackgroundTask: success"

But that's running the task directly, I mean when opening the task process from a Firefox process. That's what bug 1830384 was about, right?

  1. On ./mach run one would always expect the logs

So where's the need to suppress the log on Windows? This was what I wanted to ask

This was the ticket that motivated the suppression in the first place :). See https://bugzilla.mozilla.org/show_bug.cgi?id=1830384.

But that was not on Windows, was it?

Flags: needinfo?(nalexander)

(In reply to Kagami [:saschanaz] from comment #13)

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

(In reply to Kagami [:saschanaz] from comment #11)

Oh that was a dumb question, sorry, I mean:

  1. I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
    1. Actually I don't think passing --attach-console makes it attach to the console when opened by Firefox, I still see no message

This is with a recent install that I was doing some other testing against:

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success

nalexander@dama /c/ProgramData/Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38/updates/721C53625FA9C1D0
$ /c/Users/nalexander/AppData/Local/Mozilla\ Firefox\ 1/firefox.exe --backgroundtask success --attach-console
console.error: "runBackgroundTask: success"

But that's running the task directly, I mean when opening the task process from a Firefox process. That's what bug 1830384 was about, right?

Mmm, I see what you're driving at. I haven't verified but you're probably correct: a Firefox process invoking, e.g., pingsender task at shutdown on Windows shouldn't see this output. (But I've not verified.)

  1. On ./mach run one would always expect the logs

So where's the need to suppress the log on Windows? This was what I wanted to ask

This was the ticket that motivated the suppression in the first place :). See https://bugzilla.mozilla.org/show_bug.cgi?id=1830384.

But that was not on Windows, was it?

I believe not?

If you can confirm that we don't see console pollution after ./mach run when launching shutdown tasks on Windows, I'd be happy to remove (with a comment!) the Windows-specific stdout/stderr handling. Assuming that it addressed your issues on try, of course :)

This is all made more complicated because debug Windows builds allocate a Windows console by default. I don't know how that interacts with the timing issues we're seeing in this test.

Flags: needinfo?(nalexander) → needinfo?(krosylight)

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

Mmm, I see what you're driving at. I haven't verified but you're probably correct: a Firefox process invoking, e.g., pingsender task at shutdown on Windows shouldn't see this output. (But I've not verified.)

If you can confirm that we don't see console pollution after ./mach run when launching shutdown tasks on Windows, I'd be happy to remove (with a comment!) the Windows-specific stdout/stderr handling. Assuming that it addressed your issues on try, of course :)

Not seeing the console messages on Windows was why I totally missed such logging happened on macOS/Linux, so yes I can confirm.

This is all made more complicated because debug Windows builds allocate a Windows console by default. I don't know how that interacts with the timing issues we're seeing in this test.

Yup, we should first examine the cause here. For now I'm getting the exit code 1 time to time on random subtest but never with --attach-console. Let me check the same happens if I remove the stdout/stderr handling.

Flags: needinfo?(krosylight)
Assignee: nobody → krosylight
Status: NEW → ASSIGNED
See Also: → 1804833
Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/82c731bd300f Do not explicitly suppress stdout/stderr for background tasks on Windows r=nalexander

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

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 115 Branch

The patch landed in nightly and beta is affected.
:saschanaz, is this bug important enough to require an uplift?

  • If yes, please nominate the patch for beta approval.
  • If no, please set status-firefox114 to wontfix.

For more information, please visit BugBot documentation.

Flags: needinfo?(krosylight)

Test-only issue, not really important in terms of the product behavior. (But ping me if some release manager wants to uplift it)

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

Attachment

General

Created:
Updated:
Size: