Closed Bug 1694647 Opened 3 years ago Closed 3 years ago

Intermittent mozilla/tests/workers/worker_timer_nesting_level.html | Worker timer nesting level - assert_true: timer nesting level reaches the max nesting level(5), interval time should be clamped at least 3, but got 2 expected true got false

Categories

(Core :: DOM: Workers, defect)

defect

Tracking

()

RESOLVED FIXED
Tracking Status
firefox88 --- wontfix
firefox89 --- fixed
firefox90 --- fixed

People

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

References

(Regression)

Details

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

Attachments

(2 files)

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


[task 2021-02-24T12:56:33.099Z] 12:56:33     INFO - TEST-START | /_mozilla/workers/worker_timer_nesting_level.html
[task 2021-02-24T12:56:33.115Z] 12:56:33     INFO - Setting pref dom.workers.testing.enabled (true)
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /webrtc/receiver-track-live.https.html | Inactivate the audio transceiver 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /webrtc/receiver-track-live.https.html | Reactivate the audio transceiver 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /webrtc/receiver-track-live.https.html | Clean-up 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /webrtc/simplecall-no-ssrcs.https.html | Can set up a basic WebRTC call without announcing ssrcs. 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /webrtc/simplecall.https.html | Can set up a basic WebRTC call. 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /workers/interfaces/SharedWorkerGlobalScope/name/getting.html | getting name 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /workers/interfaces/SharedWorkerGlobalScope/name/getting.html | getting name 1 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /workers/interfaces/SharedWorkerGlobalScope/name/getting.html | getting name 2 
[task 2021-02-24T12:56:33.473Z] 12:56:33     INFO - TEST-PASS | /workers/interfaces/SharedWorkerGlobalScope/name/setting.html | setting name 
[task 2021-02-24T12:56:33.474Z] 12:56:33     INFO - TEST-FAIL | /workers/interfaces/SharedWorkerGlobalScope/onconnect.html | onconnect - assert_array_equals: expected property 1 to be "null" but got "[object Object]" (expected array ["null", "null", "function", ""] got ["null", "[object Object]", "function", ""])
[task 2021-02-24T12:56:33.474Z] 12:56:33     INFO - @http://web-platform.test:8000/workers/interfaces/SharedWorkerGlobalScope/onconnect.html:10:24
[task 2021-02-24T12:56:33.474Z] 12:56:33     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2092:25
[task 2021-02-24T12:56:33.474Z] 12:56:33     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:2119:35
[task 2021-02-24T12:56:33.474Z] 12:56:33     INFO - TEST-UNEXPECTED-FAIL | /_mozilla/workers/worker_timer_nesting_level.html | Worker timer nesting level  - assert_true: timer nesting level reaches the max nesting level(5), interval time should be clamped at least 3, but got 2 expected true got false```

We had 77 failures in the past week
Recent failure: https://treeherder.mozilla.org/logviewer?job_id=333167012&repo=mozilla-central&lineNumber=3145

[task 2021-03-14T10:47:18.867Z] 10:47:18 INFO - TEST-START | /_mozilla/workers/worker_timer_nesting_level.html
[task 2021-03-14T10:47:18.893Z] 10:47:18 INFO - Setting pref dom.workers.testing.enabled (true)
[task 2021-03-14T10:47:19.048Z] 10:47:19 INFO - PID 23995 | [CodeCoverage] Setting handlers for process 24303.
[task 2021-03-14T10:47:19.154Z] 10:47:19 INFO - PID 23995 | 1615718839152 Marionette WARN Ignoring event 'DOMContentLoaded' because document has an invalid readyState of 'complete'.
[task 2021-03-14T10:47:19.154Z] 10:47:19 INFO - PID 23995 | JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-03-14T10:47:19.252Z] 10:47:19 INFO - PID 23995 | JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-03-14T10:47:19.256Z] 10:47:19 INFO - PID 23995 | JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-03-14T10:47:19.306Z] 10:47:19 INFO -
[task 2021-03-14T10:47:19.306Z] 10:47:19 INFO - TEST-UNEXPECTED-FAIL | /_mozilla/workers/worker_timer_nesting_level.html | Worker timer nesting level - assert_true: timer nesting level reaches the max nesting level(5), interval time should be clamped at least 3, but got 2 expected true got false
[task 2021-03-14T10:47:19.306Z] 10:47:19 INFO - @http://web-platform.test:8000/_mozilla/workers/worker_timer_nesting_level.html:50:14
[task 2021-03-14T10:47:19.306Z] 10:47:19 INFO - TEST-OK | /_mozilla/workers/worker_timer_nesting_level.html | took 440ms
[task 2021-03-14T10:47:19.307Z] 10:47:19 INFO - No more tests
[task 2021-03-14T10:47:19.308Z] 10:47:19 INFO - PID 23995 | 1615718839307 Marionette INFO Stopped listening on port 38741
[task 2021-03-14T10:47:19.441Z] 10:47:19 INFO - PID 23995 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-03-14T10:47:19.514Z] 10:47:19 INFO - PID 23995 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-03-14T10:47:19.516Z] 10:47:19 INFO - PID 23995 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-03-14T10:47:19.938Z] 10:47:19 INFO - Browser exited with return code 0
[task 2021-03-14T10:47:19.938Z] 10:47:19 INFO - PROCESS LEAKS None
[task 2021-03-14T10:47:19.938Z] 10:47:19 INFO - Closing logging queue
[task 2021-03-14T10:47:19.938Z] 10:47:19 INFO - queue closed
[task 2021-03-14T10:47:19.974Z] 10:47:19 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmp_ysxvisr
[task 2021-03-14T10:47:20.002Z] 10:47:20 INFO - PID 23995 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-03-14T10:47:20.031Z] 10:47:20 INFO - Starting runner
[task 2021-03-14T10:47:20.121Z] 10:47:20 INFO - PID 24358 | [CodeCoverage] Setting handlers for process 24358.
[task 2021-03-14T10:47:21.424Z] 10:47:21 INFO - PID 24358 | 1615718841423 Marionette INFO Marionette enabled
[task 2021-03-14T10:47:21.858Z] 10:47:21 INFO - Browser exited with return code 0
[task 2021-03-14T10:47:21.858Z] 10:47:21 INFO - PROCESS LEAKS None
[task 2021-03-14T10:47:21.861Z] 10:47:21 INFO - Closing logging queue
[task 2021-03-14T10:47:21.862Z] 10:47:21 INFO - queue closed
[task 2021-03-14T10:47:21.862Z] 10:47:21 INFO - PROCESS LEAKS None
[task 2021-03-14T10:47:22.762Z] 10:47:22 INFO - PID 24358 | [CodeCoverage] Setting handlers for process 24428.
[task 2021-03-14T10:47:22.949Z] 10:47:22 INFO - PID 24358 | [CodeCoverage] Setting handlers for process 24431.
[task 2021-03-14T10:47:23.577Z] 10:47:23 INFO - PID 24358 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2021-03-14T10:47:24.852Z] 10:47:24 INFO - PID 24358 | 1615718844851 Marionette INFO Listening on port 55475

Regressed by: 1684139
Has Regression Range: --- → yes

It seems the test added in Bug 1684139 isn't working reliably. Eden, could you give that a look?

Flags: needinfo?(echuang)

Thanks, Simon.

This is a known issue for checking the setTimeout is delayed after 4ms.
Keeping this bug being open to implementing a pref to enable/disable this unreliable checking.

Flags: needinfo?(echuang)
Assignee: nobody → echuang

Eden, I submitted an expectation update for worker_timer_nesting_level.html in case it is ok to suppress the failure lines till the real fix lands.

Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by malexandru@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ac93abaafbed
Update expectations for worker_timer_nesting_level.html on all platforms for frequent failures. r=edenchuang
Whiteboard: [stockwell disabled] → [stockwell needswork:owner]

Hi James, can you please take a look why this is still failing after the patch landed?

Flags: needinfo?(james)
Pushed by nbeleuzu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/233e28896a78
Remove whitespace from worker_timer_nesting_level.html. r=aryx
Flags: needinfo?(james)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [checkin-needed-beta]
Whiteboard: [checkin-needed-beta][stockwell disable-recommended] → [checkin-needed-beta]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Attachment #9218264 - Attachment description: WIP: Bug 1694647 - Eliminate intermittent failures caused by imprecise timer delay testing. → Bug 1694647 - Eliminate intermittent failures caused by imprecise timer delay testing.
Attachment #9218264 - Attachment description: Bug 1694647 - Eliminate intermittent failures caused by imprecise timer delay testing. → Bug 1694647 - Eliminate intermittent failures caused by imprecise timer delay testing. r=#dom-worker-reviewers,asuth
Pushed by echuang@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a9a52f01de13
Eliminate intermittent failures caused by imprecise timer delay testing. r=dom-worker-reviewers,asuth
Keywords: leave-open

The intermittent failures are all from the release channel.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: