Closed Bug 1526445 Opened 3 years ago Closed 1 year ago

Tasks added after a skip()ed task aren't output in Mochitests

Categories

(Testing :: Mochitest, defect, P1)

Version 3
defect
Points:
2

Tracking

(firefox76 fixed)

RESOLVED FIXED
mozilla76
Iteration:
76.1 - Mar 9 - Mar 22
Tracking Status
firefox76 --- fixed

People

(Reporter: sfoster, Assigned: ahal)

References

Details

Attachments

(3 files)

Attached patch post-skip.patchSplinter Review

If you add_task() after a add_task().skip(), it appears that task is never run. Or at least the results not reported.

When I run browser_tasks_skip.js as-is, I get:

Ran 5 checks (4 subtests, 1 tests)
Expected results: 3
OK

When I apply the attached patch to add a not-skipped task after the last skipped one, I get:

Ran 5 checks (4 subtests, 1 tests)
Expected results: 3
OK

Summary: Tasks add after a skip()ed task arent run → Tasks added after a skip()ed task arent run
Priority: -- → P3

I can confirm this is still a problem.

./mach test testing/mochitest/tests/browser/browser_tasks_skip.js

0:04.93 TEST_START: testing/mochitest/tests/browser/browser_tasks_skip.js
0:04.93 PASS I'm a test in head file -
0:04.93 INFO Entering test bound skipMeNot1
0:04.93 PASS Well well well. - true == true -
0:04.93 INFO Leaving test bound skipMeNot1
0:04.93 EXPECTED-SKIP bound skipMe1
0:04.93 WARNING Skipping test bound skipMe1
0:04.93 EXPECTED-SKIP bound skipMe2
0:04.93 WARNING Skipping test bound skipMe2
0:04.95 GECKO(55816) MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
0:04.95 GECKO(55816) MEMORY STAT | vsize 7026MB | residentFast 302MB | heapAllocated 135MB
0:04.94 TEST_END: Test OK. Subtests passed 2/4. Unexpected 0

Note that tasks skipMeNot2 and skipMeNot3 are never run.

IMO this should be higher priority than P3 since it means that tasks we think are running actually aren't.

Johann, FYI for https://searchfox.org/mozilla-central/rev/070a000dd49aac4a26147e137efcd91a728d13b8/browser/components/preferences/in-content/tests/siteData/browser_siteData.js#74

Shane, FYI for https://searchfox.org/mozilla-central/rev/070a000dd49aac4a26147e137efcd91a728d13b8/browser/components/extensions/test/browser/browser_ext_tabs_events.js#423 and https://searchfox.org/mozilla-central/rev/070a000dd49aac4a26147e137efcd91a728d13b8/toolkit/components/extensions/test/xpcshell/test_ext_redirects.js#518

Blocks: 1380470
Summary: Tasks added after a skip()ed task arent run → Tasks added after a skip()ed task aren't run
Summary: Tasks added after a skip()ed task aren't run → Tasks added after a skip()ed task aren't run in Mochitests

Wow, I would argue that this is really bad and we should put in place some intermediate solution and alert folks that this is happening. The siteData test is not redundant and is testing user privacy features.

Assignee: nobody → mdeboer
Status: NEW → ASSIGNED
Iteration: --- → 76.1 - Mar 9 - Mar 22
Points: --- → 2
Priority: P3 → P1

The problem seems to be in the structured logger. The tests are executed.

Andrew, way back when I implemented this feature in bug 1380470, you requested that I use structuredLogger.deactivateBuffering() and structuredLogger.activateBuffering() respectively when we skip a task. This happens to cause all other subsequent test results to be eaten and not logged to the console (and possibly in automation too).

The test totals reported at the end still show the correct numbers, though, and when using dump everywhere instead of the logger also shows that the tasks are being run as expected.

When I remove the buffering pausing code, everything works as expected, which makes me wonder: can I simplify things and remove the code?

Flags: needinfo?(ahal)

You put the wrong link to the bug there, mind updating?

I don't really remember the context for why I asked you to do that. Sounds like the issue should be fixed in the buffering logic of the logger, though we could remove those calls temporarily at least to fix this in the short term.

I'll take a look at the output handler on the Python side.

Flags: needinfo?(ahal)

(In reply to Mike de Boer [:mikedeboer] from comment #3)

The problem seems to be in the structured logger. The tests are executed.

Thanks for confirming that. It was late so I didn't double-check that part. I confirmed that if a test fails it does get output so apologies for sounding the alarm.

Summary: Tasks added after a skip()ed task aren't run in Mochitests → Tasks added after a skip()ed task aren't output in Mochitests

I think I know what's happening, if I'm right it means we haven't lost any test coverage over the past year.

First a bit of context. The structured logger's "buffering" feature is intended to keep the logs under control. If we logged every single assertion of every single test, the logs would be massive. So to help with this, we suppress all test_status and log messages that happen between the test_start and test_end actions. We'll then only log those buffered messages if the test failed.

The logic responsible for counting and outputting subtests relies on the test_status logs. So when those get buffered, it actually impacts the number of total assertions reported. This is technically working as intended, though ideally we'd find a way to "buffer" the messages without impacting the assertion counts. Let's call this issue #1, which I'd argue isn't a terribly high priority.

The second issue is a bit more important and can be solved in this bug. Sometimes we disable buffering on purpose, one such case is when only running a single test (because we assume developers are working on said test and want to see the full output even if it passes). What's happening is the call to structuredLogger.activateBuffering() is enabling buffering even though the harness had originally wanted it disabled. So when you run ./mach test testing/mochitest/tests/browser/browser_tasks_skip.js buffering initially starts out disabled because you are only running a single test. But then after the call to skip() buffering gets turned on again due to the feature Mike implemented.

This should be fixed on the Python side of the harness, so I'll take this over.

Assignee: mdeboer → ahal

Thanks for finding the cause, Andrew! I corrected the bug number in comment 4.

Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3a7bf80352e4
[mochitest] Don't ever enable log buffering if it was initially disabled, r=gbrown
https://hg.mozilla.org/integration/autoland/rev/b2e47ad97d59
[mochitest] Ignore 'buffering_on' action if test is not running, r=gbrown
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla76

Thank you ahal and mike!

You need to log in before you can comment on or make changes to this bug.