Closed Bug 1628261 Opened 4 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Test timed out

Categories

(Toolkit :: Crash Reporting, defect, P5)

Product:
Toolkit
Component:
Crash Reporting
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=296761772&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/JVuo_CCdSum_ITKdsTq_zA/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/JVuo_CCdSum_ITKdsTq_zA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2020-04-08T07:37:24.244Z] 07:37:24 INFO - SUITE-START | Running 1 tests
[task 2020-04-08T07:37:24.257Z] 07:37:24 INFO - TEST-START | toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js
[task 2020-04-08T07:42:24.330Z] 07:42:24 WARNING - TEST-UNEXPECTED-TIMEOUT | toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Test timed out
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - TEST-INFO took 300069ms
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - >>>>>>>
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | [2307, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2904
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - running event loop
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | [2307, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 363
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Starting run_test
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - (xpcshell/head.js) | test run_test pending (2)
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: Couldn't get the user appdata directory, crash dumps will go in an unusual location: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2964
[task 2020-04-08T07:42:24.330Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2904
[task 2020-04-08T07:42:24.331Z] 07:42:24 INFO - PID 2307 | [2308, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 194
[task 2020-04-08T07:42:24.331Z] 07:42:24 INFO - PID 2307 | [2308, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 194
[task 2020-04-08T07:42:24.331Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozPersonalDictionary.cpp, line 206
[task 2020-04-08T07:42:24.331Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 199
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 116
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Creating directory: /var/folders/dp/f2x0j2c13_q52sscs66y9mb4000017/T/xpc-profile-SOoXgF/UAppData
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Creating directory: /var/folders/dp/f2x0j2c13_q52sscs66y9mb4000017/T/xpc-profile-SOoXgF/UAppData/Crash Reports
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Creating directory: /var/folders/dp/f2x0j2c13_q52sscs66y9mb4000017/T/xpc-profile-SOoXgF/UAppData/Crash Reports/pending
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Creating directory: /var/folders/dp/f2x0j2c13_q52sscs66y9mb4000017/T/xpc-profile-SOoXgF/UAppData/Crash Reports/submitted
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Successfully installed fake UAppDir
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | [Parent 2307, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002: file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 673
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | JavaScript error: /Users/cltbld/tasks/task_1586327546/build/tests/xpcshell/head.js, line 246: uncaught exception: 2147500037
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "uncaught exception: 2147500037" {file: "/Users/cltbld/tasks/task_1586327546/build/tests/xpcshell/head.js" line: 246}]"
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-04-08T07:42:24.332Z] 07:42:24 INFO - PID 2307 | [Child 2308, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 363
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "/Users/cltbld/tasks/task_1586327546/build/tests/xpcshell/head.js" line: 378}]"
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "/Users/cltbld/tasks/task_1586327546/build/tests/xpcshell/head.js" line: 378}]"
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - PID 2307 | Hit MOZ_CRASH() at /builds/worker/checkouts/gecko/toolkit/crashreporter/test/nsTestCrasher.cpp:163
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - <<<<<<<
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - xpcshell return code: None
[task 2020-04-08T07:42:24.333Z] 07:42:24 INFO - toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Process still running after test!
[task 2020-04-08T07:59:04.373Z] 07:59:04 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1586327546/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1586327546/build/tests/xpcshell/runxpcshelltests.py', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--symbols-path=/Users/cltbld/tasks/task_1586327546/build/symbols', '--test-plugin-path=/Users/cltbld/tasks/task_1586327546/build/application/Firefox NightlyDebug.app/Contents/Resources/plugins', '--log-raw=/Users/cltbld/tasks/task_1586327546/build/blobber_upload_dir/xpcshell_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1586327546/build/blobber_upload_dir/xpcshell_errorsummary.log', '--utility-path=tests/bin', '--xpcshell=/Users/cltbld/tasks/task_1586327546/build/application/Firefox NightlyDebug.app/Contents/MacOS/xpcshell', '--manifest=tests/xpcshell/tests/xpcshell.ini', '--verify-max-time=900', '--verify', u'toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js']
[task 2020-04-08T07:59:04.475Z] 07:59:04 ERROR - timed out after 1000 seconds of no output
[task 2020-04-08T07:59:04.475Z] 07:59:04 ERROR - Return code: -15
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - TinderboxPrint: xpcshell-xpcshell<br/>10/0/0
[task 2020-04-08T07:59:04.475Z] 07:59:04 WARNING - # TBPL FAILURE #
[task 2020-04-08T07:59:04.475Z] 07:59:04 WARNING - setting return code to 2
[task 2020-04-08T07:59:04.475Z] 07:59:04 WARNING - TinderboxPrint: Per-test run of .../test_content_large_annotation.js<br/>: FAILURE
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - Running post-action listener: _package_coverage_data
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - [mozharness: 2020-04-08 07:59:04.475767Z] Finished run-tests step (success)
[task 2020-04-08T07:59:04.475Z] 07:59:04 INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-08T07:59:04.628Z] 07:59:04 INFO - instance_metadata.json not found; unable to determine instance type
[task 2020-04-08T07:59:04.632Z] 07:59:04 INFO - Validating Perfherder data against /Users/cltbld/tasks/task_1586327546/mozharness/external_tools/performance-artifact-schema.json
[task 2020-04-08T07:59:04.636Z] 07:59:04 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 1.8750388802488358}, {"name": "io_write_bytes", "value": 323473408}, {"name": "io.read_bytes", "value": 62705664}, {"name": "io_write_time", "value": 1126}, {"name": "io_read_time", "value": 944}], "extraOptions": ["e10s", "buildbot-unknown"], "name": ".overall"}, {"subtests": [{"name": "time", "value": 0.0004448890686035156}], "name": ".start-pulseaudio"}, {"subtests": [{"name": "time", "value": 21.511478900909424}, {"name": "cpu_percent", "value": 37.485}], "name": ".install"}, {"subtests": [{"name": "time", "value": 0.01651287078857422}], "name": ".stage-files"}, {"subtests": [{"name": "time", "value": 1314.0309579372406}, {"name": "cpu_percent", "value": 1.2910671936758937}], "name": ".run-tests"}]}
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - Total resource usage - Wall time: 1335s; CPU: 1.0%; Read bytes: 62705664; Write bytes: 323473408; Read time: 944; Write time: 1126
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: CPU usage<br/>1.3%
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: I/O read bytes / time<br/>62,705,664 / 944
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: I/O write bytes / time<br/>323,473,408 / 1,126
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: CPU idle<br/>5,251.4 (98.4%)
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: CPU user<br/>65.8 (1.2%)
[task 2020-04-08T07:59:04.637Z] 07:59:04 INFO - TinderboxPrint: Swap in / out<br/>298,344,448 / 0
[task 2020-04-08T07:59:04.638Z] 07:59:04 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-08T07:59:04.640Z] 07:59:04 INFO - install - Wall time: 22s; CPU: 37.0%; Read bytes: 263935488; Write bytes: 249974784; Read time: 17640; Write time: 492
[task 2020-04-08T07:59:04.641Z] 07:59:04 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-08T07:59:04.653Z] 07:59:04 INFO - run-tests - Wall time: 1314s; CPU: 1.0%; Read bytes: 53714944; Write bytes: 52142080; Read time: 841; Write time: 583
[task 2020-04-08T07:59:04.982Z] 07:59:04 WARNING - returning nonzero exit status 2
[fetches 2020-04-08T07:59:05.009Z] removing /Users/cltbld/tasks/task_1586327546/fetches
[fetches 2020-04-08T07:59:05.533Z] finished
[taskcluster 2020-04-08T07:59:05.543Z] Exit Code: 2
[taskcluster 2020-04-08T07:59:05.543Z] User Time: 1m44.311741s
[taskcluster 2020-04-08T07:59:05.543Z] Kernel Time: 46.895105s
[taskcluster 2020-04-08T07:59:05.543Z] Wall Time: 24m24.11083631s
[taskcluster 2020-04-08T07:59:05.543Z] Result: FAILED
[taskcluster 2020-04-08T07:59:05.543Z] === Task Finished ===
[taskcluster 2020-04-08T07:59:05.543Z] Task Duration: 24m24.114557398s
[taskcluster 2020-04-08T07:59:05.847Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-04-08T07:00:28.014Z
[taskcluster 2020-04-08T07:59:06.131Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2021-04-08T07:00:28.014Z
[taskcluster 2020-04-08T07:59:06.504Z] Uploading artifact public/test_info/xpcshell_errorsummary.log from file build/blobber_upload_dir/xpcshell_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2021-04-08T07:00:28.014Z
[taskcluster 2020-04-08T07:59:06.788Z] Uploading artifact public/test_info/xpcshell_raw.log from file build/blobber_upload_dir/xpcshell_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2021-04-08T07:00:28.014Z
[taskcluster:error] exit status 2

Regressed by: 1614933

I'll look into this ASAP.

I suspect this might be caused by bug 1624467.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer?job_id=323149079&repo=autoland&lineNumber=2261

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

I landed bug 1666383 this morning which touched this test so this is most likely fallout from it.

Regressed by: 1666383
Has Regression Range: --- → yes
Keywords: regression
Summary: Intermittent TV tier2 TEST-UNEXPECTED-TIMEOUT | toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Test timed out → Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/crashreporter/test/unit_ipc/test_content_large_annotation.js | Test timed out

Bug 1666383 has been backed out for causing perma failures: https://hg.mozilla.org/integration/autoland/rev/38f4b3abb54cee8a46f593891ac4b949239ac072

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