Perma [tier2] ccov remote/test/browser/runtime/browser_callFunctionOn.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
Categories
(Remote Protocol :: CDP, defect, P1)
Tracking
(firefox76 fixed)
Tracking | Status | |
---|---|---|
firefox76 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: whimboo)
References
(Regression)
Details
(Keywords: intermittent-failure)
Attachments
(1 file)
Filed by: opoprus [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=294621061&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GlPAM0v5RKWhmssU-DW26A/runs/0/artifacts/public/logs/live_backing.log
[task 2020-03-25T05:12:22.931Z] 05:12:22 INFO - TEST-START | remote/test/browser/runtime/browser_callFunctionOn.js
[task 2020-03-25T05:12:24.730Z] 05:12:24 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5030.
[task 2020-03-25T05:12:27.201Z] 05:12:27 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5059.
[task 2020-03-25T05:12:27.383Z] 05:12:27 INFO - GECKO(4711) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-25T05:12:27.585Z] 05:12:27 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5061.
[task 2020-03-25T05:12:29.852Z] 05:12:29 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5139.
[task 2020-03-25T05:12:30.050Z] 05:12:30 INFO - GECKO(4711) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-25T05:12:30.253Z] 05:12:30 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5144.
[task 2020-03-25T05:12:32.447Z] 05:12:32 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5190.
[task 2020-03-25T05:12:33.519Z] 05:12:33 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5213.
[task 2020-03-25T05:12:35.440Z] 05:12:35 INFO - GECKO(4711) | [CodeCoverage] Setting handlers for process 5244.
[task 2020-03-25T05:12:41.316Z] 05:12:41 INFO - GECKO(4711) | JavaScript error: , line 0: uncaught exception: 42
[task 2020-03-25T05:12:47.027Z] 05:12:47 INFO - GECKO(4711) | JavaScript error: , line 0: uncaught exception: 42
[task 2020-03-25T05:12:48.463Z] 05:12:48 INFO - GECKO(4711) | JavaScript error: , line 0: uncaught exception: 42
[task 2020-03-25T05:13:20.018Z] 05:13:20 INFO - TEST-INFO | started process screentopng
[task 2020-03-25T05:13:20.208Z] 05:13:20 INFO - TEST-INFO | screentopng: exit 0
[task 2020-03-25T05:13:20.208Z] 05:13:20 INFO - <snipped 406 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-03-25T05:13:20.209Z] 05:13:20 INFO - Buffered messages logged at 05:13:09
[task 2020-03-25T05:13:20.209Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.210Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.212Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"-0","description":"-0"} deepEqual {"type":"number","unserializableValue":"-0","description":"-0"} -
[task 2020-03-25T05:13:20.212Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"NaN","description":"NaN"} deepEqual {"type":"number","unserializableValue":"NaN","description":"NaN"} -
[task 2020-03-25T05:13:20.213Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"Infinity","description":"Infinity"} deepEqual {"type":"number","unserializableValue":"Infinity","description":"Infinity"} -
[task 2020-03-25T05:13:20.213Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"-Infinity","description":"-Infinity"} deepEqual {"type":"number","unserializableValue":"-Infinity","description":"-Infinity"} -
[task 2020-03-25T05:13:20.213Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"bigint","unserializableValue":"42n","description":"42n"} deepEqual {"type":"bigint","unserializableValue":"42n","description":"42n"} -
[task 2020-03-25T05:13:20.213Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.215Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.216Z] 05:13:20 INFO - Leaving test bound returnByValueNotSerializable
[task 2020-03-25T05:13:20.217Z] 05:13:20 INFO - Entering test bound returnByValueUndefined
[task 2020-03-25T05:13:20.218Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.219Z] 05:13:20 INFO - Buffered messages logged at 05:13:10
[task 2020-03-25T05:13:20.219Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.219Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.220Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.220Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.221Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.223Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | Undefined type is correct - {"type":"undefined"} deepEqual {"type":"undefined"} -
[task 2020-03-25T05:13:20.223Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.224Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.224Z] 05:13:20 INFO - Leaving test bound returnByValueUndefined
[task 2020-03-25T05:13:20.224Z] 05:13:20 INFO - Entering test bound returnByValueArguments
[task 2020-03-25T05:13:20.225Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.225Z] 05:13:20 INFO - Buffered messages logged at 05:13:11
[task 2020-03-25T05:13:20.226Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.227Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.227Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.227Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.228Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.228Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","value":42,"description":"42"} deepEqual {"type":"number","value":42,"description":"42"} -
[task 2020-03-25T05:13:20.234Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","value":42,"description":"42"} deepEqual {"type":"number","value":42,"description":"42"} -
[task 2020-03-25T05:13:20.234Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"string","value":"42","description":"42"} deepEqual {"type":"string","value":"42","description":"42"} -
[task 2020-03-25T05:13:20.234Z] 05:13:20 INFO - Buffered messages logged at 05:13:12
[task 2020-03-25T05:13:20.236Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"boolean","value":true,"description":"true"} deepEqual {"type":"boolean","value":true,"description":"true"} -
[task 2020-03-25T05:13:20.237Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"boolean","value":false,"description":"false"} deepEqual {"type":"boolean","value":false,"description":"false"} -
[task 2020-03-25T05:13:20.238Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"object","value":null,"description":null} deepEqual {"type":"object","value":null,"description":null} -
[task 2020-03-25T05:13:20.239Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"object","value":{"foo":true},"description":"[object Object]"} deepEqual {"type":"object","value":{"foo":true},"description":"[object Object]"} -
[task 2020-03-25T05:13:20.240Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"object","value":{"foo":{"bar":42,"str":"str","array":[1,2,3]}},"description":"[object Object]"} deepEqual {"type":"object","value":{"foo":{"bar":42,"str":"str","array":[1,2,3]}},"description":"[object Object]"} -
[task 2020-03-25T05:13:20.240Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"object","value":[42,"42",true],"description":"42,42,true"} deepEqual {"type":"object","value":[42,"42",true],"description":"42,42,true"} -
[task 2020-03-25T05:13:20.242Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"object","value":[{"foo":true}],"description":"[object Object]"} deepEqual {"type":"object","value":[{"foo":true}],"description":"[object Object]"} -
[task 2020-03-25T05:13:20.243Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.244Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.245Z] 05:13:20 INFO - Leaving test bound returnByValueArguments
[task 2020-03-25T05:13:20.246Z] 05:13:20 INFO - Entering test bound returnByValueArgumentsNotSerializable
[task 2020-03-25T05:13:20.247Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.249Z] 05:13:20 INFO - Buffered messages logged at 05:13:13
[task 2020-03-25T05:13:20.249Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.250Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.251Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.252Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.252Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.252Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"-0","description":"-0"} deepEqual {"type":"number","unserializableValue":"-0","description":"-0"} -
[task 2020-03-25T05:13:20.253Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"NaN","description":"NaN"} deepEqual {"type":"number","unserializableValue":"NaN","description":"NaN"} -
[task 2020-03-25T05:13:20.253Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"Infinity","description":"Infinity"} deepEqual {"type":"number","unserializableValue":"Infinity","description":"Infinity"} -
[task 2020-03-25T05:13:20.253Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"number","unserializableValue":"-Infinity","description":"-Infinity"} deepEqual {"type":"number","unserializableValue":"-Infinity","description":"-Infinity"} -
[task 2020-03-25T05:13:20.254Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The returned value is the same than the input value - {"type":"bigint","unserializableValue":"42n","description":"42n"} deepEqual {"type":"bigint","unserializableValue":"42n","description":"42n"} -
[task 2020-03-25T05:13:20.254Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.254Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.255Z] 05:13:20 INFO - Leaving test bound returnByValueArgumentsNotSerializable
[task 2020-03-25T05:13:20.255Z] 05:13:20 INFO - Entering test bound returnByValueArgumentsSymbol
[task 2020-03-25T05:13:20.256Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.256Z] 05:13:20 INFO - Buffered messages logged at 05:13:15
[task 2020-03-25T05:13:20.256Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.257Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.257Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.258Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.258Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.260Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | Symbol cannot be returned as value -
[task 2020-03-25T05:13:20.260Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.261Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.261Z] 05:13:20 INFO - Leaving test bound returnByValueArgumentsSymbol
[task 2020-03-25T05:13:20.262Z] 05:13:20 INFO - Entering test bound exceptionDetailsJavascriptError
[task 2020-03-25T05:13:20.262Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.262Z] 05:13:20 INFO - Buffered messages logged at 05:13:16
[task 2020-03-25T05:13:20.263Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.264Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.265Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.265Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.267Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.267Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | Javascript error is passed to the client - {"text":"doesNotExists is not defined"} deepEqual {"text":"doesNotExists is not defined"} -
[task 2020-03-25T05:13:20.268Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.269Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.269Z] 05:13:20 INFO - Leaving test bound exceptionDetailsJavascriptError
[task 2020-03-25T05:13:20.270Z] 05:13:20 INFO - Entering test bound exceptionDetailsThrowError
[task 2020-03-25T05:13:20.270Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.271Z] 05:13:20 INFO - Buffered messages logged at 05:13:18
[task 2020-03-25T05:13:20.271Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.273Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.273Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.274Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.274Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.275Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | Exception details are passed to the client - {"text":"foo"} deepEqual {"text":"foo"} -
[task 2020-03-25T05:13:20.276Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.276Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.276Z] 05:13:20 INFO - Leaving test bound exceptionDetailsThrowError
[task 2020-03-25T05:13:20.277Z] 05:13:20 INFO - Entering test bound exceptionDetailsThrowValue
[task 2020-03-25T05:13:20.277Z] 05:13:20 INFO - CDP server started
[task 2020-03-25T05:13:20.278Z] 05:13:20 INFO - Buffered messages logged at 05:13:19
[task 2020-03-25T05:13:20.278Z] 05:13:20 INFO - CDP client instantiated
[task 2020-03-25T05:13:20.279Z] 05:13:20 INFO - Runtime domain has been enabled
[task 2020-03-25T05:13:20.281Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has an id -
[task 2020-03-25T05:13:20.281Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context is the default one -
[task 2020-03-25T05:13:20.281Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | The execution context has a frame id set -
[task 2020-03-25T05:13:20.281Z] 05:13:20 INFO - TEST-PASS | remote/test/browser/runtime/browser_callFunctionOn.js | Exception details are passed as a RemoteObject - {"exception":{"type":"string","value":"foo"}} deepEqual {"exception":{"type":"string","value":"foo"}} -
[task 2020-03-25T05:13:20.282Z] 05:13:20 INFO - CDP client closed
[task 2020-03-25T05:13:20.283Z] 05:13:20 INFO - CDP server stopped
[task 2020-03-25T05:13:20.284Z] 05:13:20 INFO - Leaving test bound exceptionDetailsThrowValue
[task 2020-03-25T05:13:20.285Z] 05:13:20 INFO - Buffered messages finished
[task 2020-03-25T05:13:20.285Z] 05:13:20 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/runtime/browser_callFunctionOn.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2020-03-25T05:13:20.286Z] 05:13:20 INFO - GECKO(4711) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-03-25T05:13:20.286Z] 05:13:20 INFO - GECKO(4711) | MEMORY STAT | vsize 3377MB | residentFast 686MB | heapAllocated 222MB
[task 2020-03-25T05:13:20.287Z] 05:13:20 INFO - TEST-OK | remote/test/browser/runtime/browser_callFunctionOn.js | took 57093ms
[task 2020-03-25T05:13:20.288Z] 05:13:20 INFO - checking window state
Assignee | ||
Comment 1•4 years ago
|
||
This is for ccov tests, which means Firefox runs very slowly. Lets see what's that slow here and how to split the test if necessary.
Assignee | ||
Updated•4 years ago
|
Assignee | ||
Comment 2•4 years ago
|
||
Marco, is there a way to get more detailed test output for each of the individual assertions, or at least for each entered/left test bound? If not how can I just run this specific test file in CI?
Assignee | ||
Comment 3•4 years ago
•
|
||
I actually figured out how to push a try build for a single test file only:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a7529db8e05a925467c97c4fa954f65d7c49d448
Assignee | ||
Updated•4 years ago
|
Assignee | ||
Comment 4•4 years ago
|
||
I will split-up this file and move out all the awaitPromise
tests to its own file.
Assignee | ||
Comment 5•4 years ago
|
||
Assignee | ||
Comment 6•4 years ago
|
||
Ok, so with the refactoring of the tests we now run each test in it's own tab. This also implies creating a new instance of the CDP client, which takes up to 2s. Having that many tests will cause the test file to run into the timeout. I pushed a try build by moving all the returnByValue
type of tests out into its own test file:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4ef616871dfa31614b612ab0968f9ad66595888e
We should still continue to improve the connection time via bug 1596390.
Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/6502d0dbe2be [remote] Split-up long running test file browser_callFunctionOn.js. r=remote-protocol-reviewers,maja_zf
Comment 8•4 years ago
|
||
bugherder |
Assignee | ||
Updated•4 years ago
|
Assignee | ||
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Description
•