Frequent toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_removeDirectory.js | single tracking bug
Categories
(Toolkit :: Background Tasks, defect, P5)
Tracking
()
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
Comment 1•2 years ago
|
||
:saschanaz, since you are the author of the regressor, bug 1831154, could you take a look?
For more information, please visit BugBot documentation.
Assignee | ||
Comment 2•2 years ago
|
||
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 🤔
Updated•2 years ago
|
Comment 4•2 years ago
|
||
Tier 1 jobs failure link: https://treeherder.mozilla.org/logviewer?job_id=414784460&repo=autoland
Assignee | ||
Comment 5•2 years ago
|
||
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?
Comment 6•2 years ago
|
||
(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 :(
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?
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 9•2 years ago
|
||
(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
?
Comment 10•2 years ago
|
||
(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 :)
Assignee | ||
Comment 11•2 years ago
|
||
Oh that was a dumb question, sorry, I mean:
- I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
- Actually I don't think passing
--attach-console
makes it attach to the console when opened by Firefox, I still see no message
- Actually I don't think passing
- 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
Comment 12•2 years ago
|
||
(In reply to Kagami [:saschanaz] from comment #11)
Oh that was a dumb question, sorry, I mean:
- I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
- 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"
- On
./mach run
one would always expect the logsSo 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.
Assignee | ||
Comment 13•2 years ago
|
||
(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:
- I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
- Actually I don't think passing
--attach-console
makes it attach to the console when opened by Firefox, I still see no messageThis 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?
- On
./mach run
one would always expect the logsSo 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?
Comment 14•2 years ago
|
||
(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:
- I don't think background tasks on Windows attaches to the console by default as they do on Linux/macOS when opened by Firefox
- Actually I don't think passing
--attach-console
makes it attach to the console when opened by Firefox, I still see no messageThis 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.)
- On
./mach run
one would always expect the logsSo 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.
Assignee | ||
Comment 15•2 years ago
|
||
(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.
Assignee | ||
Comment 16•2 years ago
|
||
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 18•2 years ago
|
||
Comment 19•2 years ago
|
||
Set release status flags based on info from the regressing bug 1831154
Comment 20•2 years ago
|
||
bugherder |
Comment 21•2 years ago
|
||
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
towontfix
.
For more information, please visit BugBot documentation.
Assignee | ||
Comment 22•2 years ago
|
||
Test-only issue, not really important in terms of the product behavior. (But ping me if some release manager wants to uplift it)
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•