Intermittent REFTEST ERROR | EXCEPTION: InternalError: too much recursion
Categories
(Testing :: Reftest, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=350181792&repo=mozilla-esr91
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ErpW1v9TTlyktIHh2oYKGQ/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/ErpW1v9TTlyktIHh2oYKGQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
[task 2021-09-01T13:25:19.917Z] 13:25:19 INFO - Calling ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/reftest/runreftest.py', '--total-chunks', '32', '--this-chunk', '10', '--enable-webrender', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DESluCc1RQGaaLX3r6cVyA/artifacts/public/build/target.crashreporter-symbols.zip', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/reftest_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--suite=reftest', '--setpref=layers.acceleration.force-enabled=true', '--topsrcdir=tests/reftest/tests', '--', 'tests/reftest/tests/layout/reftests/reftest.list'] with output_timeout 1000
[task 2021-09-01T13:25:21.332Z] 13:25:21 INFO - REFTEST INFO | INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-09-01T13:25:21.333Z] 13:25:21 INFO - REFTEST INFO | Running with e10s: True
[task 2021-09-01T13:25:21.333Z] 13:25:21 INFO - REFTEST INFO | Running with fission: False
[task 2021-09-01T13:25:21.334Z] 13:25:21 INFO - REFTEST INFO | Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -profile /tmp/tmp1my0ft_t.mozrunner
[task 2021-09-01T13:25:25.761Z] 13:25:25 INFO - 1630502725760 Marionette INFO Marionette enabled
[task 2021-09-01T13:25:26.393Z] 13:25:26 INFO - 1630502726392 RemoteAgent DEBUG CDP enabled
[task 2021-09-01T13:25:26.757Z] 13:25:26 INFO - 1630502726756 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-09-01T13:25:40.453Z] 13:25:40 INFO - console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmp1my0ft_t.mozrunner/search.json.mozlz4", (void 0)))
[task 2021-09-01T13:25:48.636Z] 13:25:48 INFO - 1630502748634 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-09-01T13:25:48.638Z] 13:25:48 INFO - 1630502748636 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-09-01T13:25:48.773Z] 13:25:48 INFO - 1630502748772 Marionette TRACE All scripts recorded.
[task 2021-09-01T13:25:48.794Z] 13:25:48 INFO - 1630502748793 Marionette INFO Listening on port 2828
[task 2021-09-01T13:25:48.797Z] 13:25:48 INFO - 1630502748796 Marionette DEBUG Marionette is listening
[task 2021-09-01T13:25:49.066Z] 13:25:49 INFO - 1630502749064 Marionette DEBUG Accepted connection 0 from 127.0.0.1:45134
[task 2021-09-01T13:25:49.098Z] 13:25:49 INFO - 1630502749097 Marionette DEBUG Closed connection 0
[task 2021-09-01T13:25:49.102Z] 13:25:49 INFO - 1630502749101 Marionette DEBUG Accepted connection 1 from 127.0.0.1:45136
[task 2021-09-01T13:25:49.209Z] 13:25:49 INFO - 1630502749207 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-09-01T13:25:49.423Z] 13:25:49 INFO - 1630502749421 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"0210e90f-962e-4c46-bc73-4f1f3bfa379b","capabilities":{"browserName":"firefox","browserVersion":"91.1. ... .mozrunner","moz:shutdownTimeout":360000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-09-01T13:25:49.524Z] 13:25:49 INFO - 1630502749523 Marionette DEBUG 1 -> [0,2,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/specialpowers","temporary":true}]
[task 2021-09-01T13:25:49.854Z] 13:25:49 INFO - 1630502749853 Marionette DEBUG 1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-09-01T13:25:49.897Z] 13:25:49 INFO - 1630502749896 Marionette DEBUG 1 -> [0,3,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/reftest","temporary":true}]
[task 2021-09-01T13:25:50.264Z] 13:25:50 INFO - 1630502750260 Marionette TRACE [41] MarionetteEvents actor created for window id 22
[task 2021-09-01T13:25:50.345Z] 13:25:50 INFO - 1630502750343 Marionette TRACE Received observer notification domwindowopened
[task 2021-09-01T13:25:50.356Z] 13:25:50 INFO - 1630502750354 Marionette DEBUG 1 <- [1,3,null,{"value":"reftest@mozilla.org"}]
[task 2021-09-01T13:25:50.435Z] 13:25:50 INFO - 1630502750434 Marionette DEBUG 1 -> [0,4,"WebDriver:DeleteSession",{}]
[task 2021-09-01T13:25:50.487Z] 13:25:50 INFO - 1630502750485 Marionette DEBUG 1 <- [1,4,null,{"value":null}]
[task 2021-09-01T13:25:50.498Z] 13:25:50 INFO - 1630502750497 Marionette DEBUG Closed connection 1
[task 2021-09-01T13:25:53.365Z] 13:25:53 INFO - REFTEST INFO | Reading manifest file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list
[task 2021-09-01T13:25:53.444Z] 13:25:53 INFO - REFTEST INFO | Dumping JSON representation of sandbox
[task 2021-09-01T13:25:53.452Z] 13:25:53 INFO - REFTEST INFO | {"isDebugBuild":false,"isCoverageBuild":false,"xulRuntime":{"widgetToolkit":"gtk","OS":"Linux","XPCOMABI":"x86_64-gcc3"},"smallScreen":false,"d2d":false,"dwrite":false,"embeddedInFirefoxReality":false,"gpuProcess":false,"azureCairo":false,"azureSkia":true,"skiaContent":true,"azureSkiaGL":false,"contentSameGfxBackendAsCanvas":true,"remoteCanvas":false,"layersGPUAccelerated":true,"d3d11":false,"d3d9":false,"layersOpenGL":false,"swgl":false,"webrender":true,"layersOMTC":true,"advancedLayers":false,"layerChecksEnabled":false,"usesOverlayScrollbars":false,"Android":false,"cocoaWidget":false,"gtkWidget":true,"qtWidget":false,"winWidget":false,"is64Bit":true,"useDrawSnapshot":false,"unsupportedWithDrawSnapshot":false,"retainedDisplayList":true,"geckoview":false,"transparentScrollbars":true,"MinGW":false,"AddressSanitizer":false,"ThreadSanitizer":true,"webrtc":true,"jxl":false,"retainedDisplayLists":true,"compareRetainedDisplayLists":false,"release_or_beta":true,"http":{"userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0","appName":"Mozilla","appVersion":"5.0","platform":"X11","oscpu":"Linux x86_64","misc":"rv:91.0"},"appleSilicon":false,"windowsDefaultTheme":false,"nativeThemePref":false,"gpuProcessForceEnabled":false,"prefs":{},"browserIsRemote":true,"browserIsFission":false,"asyncPan":true,"usesRepeatResampling":false,"verify":false,"fission":false,"serviceWorkerE10s":true}
[task 2021-09-01T13:25:55.317Z] 13:25:55 INFO - REFTEST INFO | Skipping included manifest at file:///builds/worker/workspace/build/tests/reftest/tests/image/test/reftest/reftest.list line 32 due to matching skip condition
[task 2021-09-01T13:26:08.413Z] 13:26:08 ERROR - REFTEST ERROR | EXCEPTION: InternalError: too much recursion
[task 2021-09-01T13:26:08.415Z] 13:26:08 INFO - REFTEST INFO | Slowest test took 0ms (undefined)
[task 2021-09-01T13:26:08.419Z] 13:26:08 INFO - REFTEST INFO | Total canvas count = 0
[task 2021-09-01T13:26:09.453Z] 13:26:09 INFO - 1630502769452 Marionette TRACE Received observer notification quit-application
[task 2021-09-01T13:26:09.458Z] 13:26:09 INFO - 1630502769457 Marionette INFO Stopped listening on port 2828
[task 2021-09-01T13:26:09.459Z] 13:26:09 INFO - 1630502769458 Marionette DEBUG Marionette stopped listening
[task 2021-09-01T13:26:09.806Z] 13:26:09 INFO - JavaScript error: resource:///modules/Interactions.jsm, line 209: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-09-01T13:26:11.527Z] 13:26:11 INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-01T13:26:11.560Z] 13:26:11 INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-01T13:26:21.332Z] 13:26:21 INFO - REFTEST INFO | Process mode: e10s
[task 2021-09-01T13:26:21.333Z] 13:26:21 INFO - Error: parsing manifests failed!
[task 2021-09-01T13:26:21.372Z] 13:26:21 ERROR - Return code: 1
[task 2021-09-01T13:26:21.374Z] 13:26:21 ERROR - No suite end message was emitted by this harness.
[task 2021-09-01T13:26:21.374Z] 13:26:21 ERROR - No checks run.
[task 2021-09-01T13:26:21.374Z] 13:26:21 INFO - TinderboxPrint: reftest-reftest<br/><em class="testfail">T-FAIL</em>
[task 2021-09-01T13:26:21.374Z] 13:26:21 ERROR - # TBPL FAILURE #
[task 2021-09-01T13:26:21.375Z] 13:26:21 WARNING - setting return code to 2
[task 2021-09-01T13:26:21.375Z] 13:26:21 ERROR - The reftest suite: reftest ran with return status: FAILURE
[task 2021-09-01T13:26:21.375Z] 13:26:21 INFO - Running post-action listener: _package_coverage_data
[task 2021-09-01T13:26:21.376Z] 13:26:21 INFO - Running post-action listener: _resource_record_post_action
[task 2021-09-01T13:26:21.376Z] 13:26:21 INFO - Running post-action listener: process_java_coverage_data
[task 2021-09-01T13:26:21.377Z] 13:26:21 INFO - [mozharness: 2021-09-01 13:26:21.376051Z] Finished run-tests step (success)
[task 2021-09-01T13:26:21.377Z] 13:26:21 INFO - Running post-run listener: _resource_record_post_run
[task 2021-09-01T13:26:21.431Z] 13:26:21 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-09-01T13:26:21.434Z] 13:26:21 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "reftest.reftest.10.overall", "extraOptions": ["e10s", "taskcluster-m5.large"], "subtests": [{"name": "cpu_percent", "value": 60.566315789473684}, {"name": "io_write_bytes", "value": 1876037632}, {"name": "io.read_bytes", "value": 31481856}, {"name": "io_write_time", "value": 200840}, {"name": "io_read_time", "value": 9704}]}, {"name": "reftest.reftest.10.start-pulseaudio", "subtests": [{"name": "time", "value": 0.026229381561279297}]}, {"name": "reftest.reftest.10.install", "subtests": [{"name": "time", "value": 33.51566505432129}, {"name": "cpu_percent", "value": 50.4578125}]}, {"name": "reftest.reftest.10.stage-files", "subtests": [{"name": "time", "value": 0.0007297992706298828}]}, {"name": "reftest.reftest.10.run-tests", "subtests": [{"name": "time", "value": 62.33310627937317}, {"name": "cpu_percent", "value": 66.53688524590164}]}]}
[task 2021-09-01T13:26:21.435Z] 13:26:21 INFO - Total resource usage - Wall time: 95s; CPU: 67%; Read bytes: 31481856; Write bytes: 1876037632; Read time: 9704; Write time: 200840
[task 2021-09-01T13:26:21.436Z] 13:26:21 INFO - TinderboxPrint: CPU usage<br/>66.5%
[task 2021-09-01T13:26:21.437Z] 13:26:21 INFO - TinderboxPrint: I/O read bytes / time<br/>31,481,856 / 9,704
[task 2021-09-01T13:26:21.438Z] 13:26:21 INFO - TinderboxPrint: I/O write bytes / time<br/>1,876,037,632 / 200,840
[task 2021-09-01T13:26:21.439Z] 13:26:21 INFO - TinderboxPrint: CPU idle<br/>69.1 (36.4%)
[task 2021-09-01T13:26:21.439Z] 13:26:21 INFO - TinderboxPrint: CPU iowait<br/>5.6 (3.0%)
[task 2021-09-01T13:26:21.440Z] 13:26:21 INFO - TinderboxPrint: CPU system<br/>6.6 (3.5%)
[task 2021-09-01T13:26:21.441Z] 13:26:21 INFO - TinderboxPrint: CPU user<br/>108.3 (57.1%)
[task 2021-09-01T13:26:21.442Z] 13:26:21 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-09-01T13:26:21.442Z] 13:26:21 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-09-01T13:26:21.443Z] 13:26:21 INFO - install - Wall time: 34s; CPU: 50%; Read bytes: 221184; Write bytes: 845471744; Read time: 0; Write time: 41592
[task 2021-09-01T13:26:21.444Z] 13:26:21 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-09-01T13:26:21.445Z] 13:26:21 INFO - run-tests - Wall time: 62s; CPU: 67%; Read bytes: 30949376; Write bytes: 761868288; Read time: 8736; Write time: 119012
[task 2021-09-01T13:26:21.453Z] 13:26:21 WARNING - returning nonzero exit status 2
Comment hidden (Intermittent Failures Robot) |
Comment 2•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 3•2 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=390525640&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment 5•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Description
•