Closed Bug 1765445 Opened 2 years ago Closed 1 month ago

Intermittent TEST-UNEXPECTED-TIMEOUT | dom/workers/test/test_file.xhtml | application timed out after 370 seconds with no output

Categories

(Core :: DOM: Workers, defect)

defect

Tracking

()

RESOLVED FIXED
126 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox-esr115 --- wontfix
firefox99 --- unaffected
firefox100 --- unaffected
firefox101 --- wontfix
firefox124 --- wontfix
firefox125 --- wontfix
firefox126 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disabled])

Attachments

(2 files)

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


[task 2022-04-19T20:46:59.312Z] 20:46:59     INFO - TEST-PASS | dom/workers/test/test_file.xhtml | lastModified proproperty accessed from worker is incorrect. 
[task 2022-04-19T20:46:59.313Z] 20:46:59     INFO - Buffered messages finished
[task 2022-04-19T20:46:59.314Z] 20:46:59    ERROR - TEST-UNEXPECTED-TIMEOUT | dom/workers/test/test_file.xhtml | application timed out after 370 seconds with no output
[task 2022-04-19T20:46:59.315Z] 20:46:59    ERROR - Force-terminating active process(es).
[task 2022-04-19T20:46:59.316Z] 20:46:59     INFO - Determining child pids from psutil...
[task 2022-04-19T20:46:59.316Z] 20:46:59     INFO - []
[task 2022-04-19T20:46:59.317Z] 20:46:59     INFO - ==> process 6169 launched child process 6187
[task 2022-04-19T20:46:59.318Z] 20:46:59     INFO - Found child pids: {6187}
[task 2022-04-19T20:46:59.318Z] 20:46:59     INFO - Failed to get child procs
[task 2022-04-19T20:46:59.319Z] 20:46:59     INFO - Killing process: 6187
[task 2022-04-19T20:46:59.320Z] 20:46:59     INFO - TEST-INFO | started process screentopng
[task 2022-04-19T20:46:59.468Z] 20:46:59     INFO - TEST-INFO | screentopng: exit 0
[task 2022-04-19T20:46:59.468Z] 20:46:59     INFO - Can't trigger Breakpad, process no longer exists
[task 2022-04-19T20:46:59.469Z] 20:46:59     INFO - Killing process: 6169
[task 2022-04-19T20:46:59.470Z] 20:46:59     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-19T20:46:59.612Z] 20:46:59     INFO - psutil found pid 6169 dead
[task 2022-04-19T20:46:59.614Z] 20:46:59     INFO - TEST-INFO | Main app process: exit 0

It looks like I can't find the regression Bug for this, can somone please take a look? There are some retriggers and backfills. Thanks!

Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][triggered]
Whiteboard: [stockwell needswork:owner][triggered] → [stockwell needswork:owner][retriggered]

First fail so far is here.

Flags: needinfo?(jstutte)
Regressed by: 1764251
Flags: needinfo?(jstutte)
No longer regressed by: 1764251

There are 65 failures in the last 5 days.

  • 35 failures on linux1804-64-qr
  • 21 failures on windows10-32/64-2004-qr
  • 9 failures on macosx1015-64-qr

Andreas, I did some extra retriggs and the failure seem to have started from bug 1739450.

Log snippet:

[task 2022-04-22T06:45:05.482Z] 06:45:05     INFO - TEST-START | dom/workers/test/test_file.xhtml
[task 2022-04-22T06:45:05.487Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/chrome/nsChromeRegistry.cpp:180
[task 2022-04-22T06:45:05.489Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/dom/security/nsCSPService.cpp:190
[task 2022-04-22T06:45:05.515Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:197
[task 2022-04-22T06:45:05.622Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A (NS_ERROR_MALFORMED_URI): file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp:45
[task 2022-04-22T06:45:05.623Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp:57
[task 2022-04-22T06:45:05.695Z] 06:45:05     INFO - GECKO(6205) | [Parent 6205, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:197
[task 2022-04-22T06:51:15.696Z] 06:51:15     INFO - Buffered messages finished
[task 2022-04-22T06:51:15.697Z] 06:51:15    ERROR - TEST-UNEXPECTED-TIMEOUT | dom/workers/test/test_file.xhtml | application timed out after 370 seconds with no output
[task 2022-04-22T06:51:15.701Z] 06:51:15    ERROR - Force-terminating active process(es).
[task 2022-04-22T06:51:15.702Z] 06:51:15     INFO - Determining child pids from psutil...
[task 2022-04-22T06:51:15.702Z] 06:51:15     INFO - []
[task 2022-04-22T06:51:15.703Z] 06:51:15     INFO - ==> process 6205 launched child process 6223
[task 2022-04-22T06:51:15.703Z] 06:51:15     INFO - Found child pids: {6223}
[task 2022-04-22T06:51:15.704Z] 06:51:15     INFO - Failed to get child procs
[task 2022-04-22T06:51:15.704Z] 06:51:15     INFO - Killing process: 6223
[task 2022-04-22T06:51:15.705Z] 06:51:15     INFO - TEST-INFO | started process screentopng
[task 2022-04-22T06:51:15.855Z] 06:51:15     INFO - TEST-INFO | screentopng: exit 0
Flags: needinfo?(afarre)
Has Regression Range: --- → yes
Regressed by: 1739450

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

Assignee: nobody → afarre
Status: NEW → ASSIGNED
Flags: needinfo?(afarre)

Let's wait if things settle a bit here before disabling.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

Hi :farre, should we disable the test until you are able to get to this? It's still pretty frequent, it seems.

Flags: needinfo?(afarre)

@farre: this has 116 total failures in the last 7 days and 227 total failures in the last 30 days. We're disabling it to reduce noise in trees.
Please re-enable the test in your fix.
Thank you.

Keywords: leave-open
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/71a9b7b599b5
disable test_file.xhtml on multiple platforms r=intermittent-reviewers,jmaher DONTBUILD
Summary: High frequency TEST-UNEXPECTED-TIMEOUT | dom/workers/test/test_file.xhtml | application timed out after 370 seconds with no output → Intermittent TEST-UNEXPECTED-TIMEOUT | dom/workers/test/test_file.xhtml | application timed out after 370 seconds with no output

So the patch did:

[test_file.xhtml]
skip-if =
  os == "linux" && bits == 64 && debug # Bug 1765445
  os == "mac" && os_version == "10.15" && !debug # Bug 1765445 
  win10_2004 && !debug # Bug 1765445

but today I read:

["test_file.xhtml"]
skip-if = [
  "os == 'linux' && bits == 64 && debug", # Bug 1765445
  "apple_catalina && !debug", # Bug 1765445
]

after bug 1873732 landed. IIUC that means the test was failing also on windows according to comment 20 and has been disabled there but today is not disabled anymore on any Windows variant and apparently not failing. Should we just try to enable it everywhere to see what happens?

Flags: needinfo?(afarre)

And FWIW until comment 27 (well after the patch landed) it failed on central for some configurations but then stopped entirely.

Pushed by smolnar@mozilla.com:
https://hg.mozilla.org/mozilla-central/rev/ee3f76663861
Enable test_file.xhtml everywhere. r=dom-worker-reviewers,smaug
Target Milestone: --- → 126 Branch
Status: ASSIGNED → RESOLVED
Closed: 1 month ago
Keywords: leave-open
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: