1494192 - Intermittent TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_header_Server_Timing.js | Test timed out

Status: RESOLVED INCOMPLETE

(Core :: Networking, defect, P3)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=201434445&repo=mozilla-esr60

https://queue.taskcluster.net/v1/task/adK7EGxpSg6EN1I3YFqwbw/runs/0/artifacts/public/logs/live_backing.log

[task 2018-09-25T14:30:50.225Z] 14:30:50     INFO -  TEST-START | netwerk/test/unit/test_header_Server_Timing.js
[task 2018-09-25T14:35:50.227Z] 14:35:50  WARNING -  TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_header_Server_Timing.js | Test timed out
[task 2018-09-25T14:35:50.229Z] 14:35:50     INFO -  TEST-INFO took 300000ms
[task 2018-09-25T14:35:50.231Z] 14:35:50     INFO -  >>>>>>>
[task 2018-09-25T14:35:50.233Z] 14:35:50     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2018-09-25T14:35:50.234Z] 14:35:50     INFO -  (xpcshell/head.js) | test pending (2)
[task 2018-09-25T14:35:50.236Z] 14:35:50     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2018-09-25T14:35:50.237Z] 14:35:50     INFO -  running event loop
[task 2018-09-25T14:35:50.239Z] 14:35:50     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2018-09-25T14:35:50.240Z] 14:35:50     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2018-09-25T14:35:50.242Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | onStopRequest - [onStopRequest : 181] 12 == 12
[task 2018-09-25T14:35:50.243Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 58] 4 == 4
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 62] "metric" == "metric"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 63] "description" == "description"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 64] 123.4 == 123.4
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 62] "metric2" == "metric2"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 63] "description1" == "description1"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 64] 456.78 == 456.78
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 62] "metric3" == "metric3"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 63] "description2" == "description2"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 64] 789.11 == 789.11
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 62] "metric4" == "metric4"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 63] "description3" == "description3"
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  TEST-PASS | netwerk/test/unit/test_header_Server_Timing.js | checkServerTimingContent - [checkServerTimingContent : 64] 1112.13 == 1112.13
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  (xpcshell/head.js) | test finished (1)
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  exiting test
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  <<<<<<<
[task 2018-09-25T14:35:50.245Z] 14:35:50     INFO -  xpcshell return code: None
[task 2018-09-25T14:52:30.272Z] 14:52:30     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py', '--total-chunks', '8', '--this-chunk', '5', '--symbols-path=https://queue.taskcluster.net/v1/task/Puj9WYVeToeOeQxFsHfVTQ/artifacts/public/build/target.crashreporter-symbols.zip', '--test-plugin-path=/builds/worker/workspace/build/application/firefox/plugins', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/xpcshell_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/xpcshell_errorsummary.log', '--utility-path=tests/bin', '--xpcshell=/builds/worker/workspace/build/application/firefox/xpcshell', '--manifest=tests/xpcshell/tests/xpcshell.ini']
[task 2018-09-25T14:52:30.312Z] 14:52:30    ERROR - timed out after 1000 seconds of no output
[task 2018-09-25T14:52:30.313Z] 14:52:30    ERROR - Return code: -15
[task 2018-09-25T14:52:30.314Z] 14:52:30    ERROR - No tests run or test summary not found
[task 2018-09-25T14:52:30.315Z] 14:52:30     INFO - TinderboxPrint: xpcshell-xpcshell<br/><em class="testfail">T-FAIL</em>
[task 2018-09-25T14:52:30.317Z] 14:52:30  WARNING - # TBPL FAILURE #
[task 2018-09-25T14:52:30.317Z] 14:52:30  WARNING - setting return code to 2
[task 2018-09-25T14:52:30.317Z] 14:52:30  WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2018-09-25T14:52:30.317Z] 14:52:30     INFO - Running post-action listener: _package_coverage_data
[task 2018-09-25T14:52:30.317Z] 14:52:30     INFO - Running post-action listener: _resource_record_post_action
[task 2018-09-25T14:52:30.317Z] 14:52:30     INFO - [mozharness: 2018-09-25 14:52:30.317100Z] Finished run-tests step (success)
[task 2018-09-25T14:52:30.317Z] 14:52:30     INFO - Running post-run listener: _resource_record_post_run
[task 2018-09-25T14:52:30.450Z] 14:52:30     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2018-09-25T14:52:30.456Z] 14:52:30     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 17.87390377588307}, {"name": "io_write_bytes", "value": 2830823424}, {"name": "io.read_bytes", "value": 12754944}, {"name": "io_write_time", "value": 982336}, {"name": "io_read_time", "value": 1400}], "extraOptions": ["taskcluster-m3.large"], "name": "xpcshell.xpcshell.5.overall"}, {"subtests": [{"name": "time", "value": 68.90816903114319}, {"name": "cpu_percent", "value": 50.3235294117647}], "name": "xpcshell.xpcshell.5.install"}, {"subtests": [{"name": "time", "value": 0.051287174224853516}], "name": "xpcshell.xpcshell.5.stage-files"}, {"subtests": [{"name": "time", "value": 1575.3832519054413}, {"name": "cpu_percent", "value": 16.45537531806616}], "name": "xpcshell.xpcshell.5.run-tests"}]}
[task 2018-09-25T14:52:30.458Z] 14:52:30     INFO - Total resource usage - Wall time: 1644s; CPU: 16.0%; Read bytes: 12754944; Write bytes: 2830823424; Read time: 1400; Write time: 982336
[task 2018-09-25T14:52:30.460Z] 14:52:30     INFO - TinderboxPrint: CPU usage<br/>16.5%
[task 2018-09-25T14:52:30.461Z] 14:52:30     INFO - TinderboxPrint: I/O read bytes / time<br/>12,754,944 / 1,400
[task 2018-09-25T14:52:30.463Z] 14:52:30     INFO - TinderboxPrint: I/O write bytes / time<br/>2,830,823,424 / 982,336
[task 2018-09-25T14:52:30.464Z] 14:52:30     INFO - TinderboxPrint: CPU idle<br/>2,664.9 (81.6%)
[task 2018-09-25T14:52:30.466Z] 14:52:30     INFO - TinderboxPrint: CPU system<br/>108.1 (3.3%)
[task 2018-09-25T14:52:30.467Z] 14:52:30     INFO - TinderboxPrint: CPU user<br/>478.9 (14.7%)
[task 2018-09-25T14:52:30.469Z] 14:52:30     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-09-25T14:52:30.470Z] 14:52:30     INFO - install - Wall time: 69s; CPU: 50.0%; Read bytes: 0; Write bytes: 977022976; Read time: 0; Write time: 425940
[task 2018-09-25T14:52:30.471Z] 14:52:30     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2018-09-25T14:52:30.480Z] 14:52:30     INFO - run-tests - Wall time: 1575s; CPU: 16.0%; Read bytes: 12754944; Write bytes: 1753137152; Read time: 1400; Write time: 519052
[task 2018-09-25T14:52:30.859Z] 14:52:30     INFO - Running post-run listener: copy_logs_to_upload_dir
[task 2018-09-25T14:52:30.862Z] 14:52:30     INFO - Copying logs to upload dir...
[task 2018-09-25T14:52:30.863Z] 14:52:30     INFO - mkdir: /builds/worker/workspace/build/upload/logs
[task 2018-09-25T14:52:30.865Z] 14:52:30     INFO - Copying logs to upload dir...
[task 2018-09-25T14:52:30.867Z] 14:52:30  WARNING - returning nonzero exit status 2

Comment 1

[Intermittent Failures Robot]

1 failures in 2773 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-esr60: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494192&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Cristina Coroiu [:ccoroiu]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=261993203&repo=mozilla-central&lineNumber=2993

task 2019-08-16T13:20:37.927Z] 13:20:37 INFO - TEST-START | netwerk/test/unit/test_header_Server_Timing.js
[task 2019-08-16T13:22:16.143Z] 13:22:16 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js failed or timed out, will retry.
[task 2019-08-16T13:22:50.903Z] 13:22:50 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_i18n_css.js failed or timed out, will retry.
[task 2019-08-16T13:22:53.832Z] 13:22:53 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging.js failed or timed out, will retry.
[task 2019-08-16T13:23:07.693Z] 13:23:07 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_about_blank_start.js failed or timed out, will retry.
[task 2019-08-16T13:23:15.087Z] 13:23:15 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js failed or timed out, will retry.
[task 2019-08-16T13:23:23.153Z] 13:23:23 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript.js failed or timed out, will retry.
[task 2019-08-16T13:23:26.691Z] 13:23:26 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_scriptCreated.js failed or timed out, will retry.
[task 2019-08-16T13:23:29.754Z] 13:23:29 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_canvas_tainting.js failed or timed out, will retry.
[task 2019-08-16T13:23:36.400Z] 13:23:36 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_xrays.js failed or timed out, will retry.
[task 2019-08-16T13:23:43.994Z] 13:23:43 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentScripts_register.js failed or timed out, will retry.
[task 2019-08-16T13:23:57.830Z] 13:23:57 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_MessageManagerProxy.js failed or timed out, will retry.
[task 2019-08-16T13:23:58.103Z] 13:23:58 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_contexts_gc.js failed or timed out, will retry.
[task 2019-08-16T13:24:02.169Z] 13:24:02 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_shadowdom.js failed or timed out, will retry.
[task 2019-08-16T13:24:08.805Z] 13:24:08 INFO - xpcshell-e10s.ini:toolkit/components/extensions/test/xpcshell/test_ext_adoption_with_xrays.js failed or timed out, will retry.
[task 2019-08-16T13:24:13.534Z] 13:24:13 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_replaces.js failed or timed out, will retry.
[task 2019-08-16T13:24:13.724Z] 13:24:13 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_periodic.js failed or timed out, will retry.
[task 2019-08-16T13:24:16.971Z] 13:24:16 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms.js failed or timed out, will retry.
[task 2019-08-16T13:24:17.784Z] 13:24:17 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_does_not_fire.js failed or timed out, will retry.
[task 2019-08-16T13:24:32.178Z] 13:24:32 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_api_permissions.js failed or timed out, will retry.
[task 2019-08-16T13:24:39.005Z] 13:24:39 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_background_generated_load_events.js failed or timed out, will retry.
[task 2019-08-16T13:24:40.898Z] 13:24:40 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_background_api_injection.js failed or timed out, will retry.
[task 2019-08-16T13:24:44.171Z] 13:24:44 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_background_generated_reload.js failed or timed out, will retry.
[task 2019-08-16T13:24:45.216Z] 13:24:45 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_background_early_shutdown.js failed or timed out, will retry.
[task 2019-08-16T13:24:45.973Z] 13:24:45 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_background_global_history.js failed or timed out, will retry.
[task 2019-08-16T13:25:37.926Z] 13:25:37 WARNING - TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_header_Server_Timing.js | Test timed out
[task 2019-08-16T13:25:37.927Z] 13:25:37 INFO - TEST-INFO took 300000ms
[task 2019-08-16T13:25:37.927Z] 13:25:37 INFO - >>>>>>>
[task 2019-08-16T13:25:37.928Z] 13:25:37 INFO - PID 11172 | Unable to load \untrusted-startup-test-dll.dll; LoadLibraryW failed: 126Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-08-16T13:25:37.928Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2632
[task 2019-08-16T13:25:37.928Z] 13:25:37 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-08-16T13:25:37.929Z] 13:25:37 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-08-16T13:25:37.929Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/extensions/permissions/nsPermissionManager.cpp, line 2901
[task 2019-08-16T13:25:37.930Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3200
[task 2019-08-16T13:25:37.930Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3200
[task 2019-08-16T13:25:37.930Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3200
[task 2019-08-16T13:25:37.931Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-16T13:25:37.931Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-16T13:25:37.932Z] 13:25:37 INFO - PID 11172 | [11172, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002: file z:/build/build/src/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 662
[task 2019-08-16T13:25:37.932Z] 13:25:37 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-08-16T13:25:37.933Z] 13:25:37 INFO - running event loop

Comment 4

[Intermittent Failures Robot]

1 failures in 4839 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494192&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 5

[Intermittent Failures Robot]

7 failures in 4182 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 7

Platform breakdown:

• linux64: 2
• macosx1014-64-shippable: 2
• linux64-shippable: 1
• windows10-64-shippable: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494192&startday=2019-10-21&endday=2019-10-27&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 3061 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1494192&startday=2021-05-17&endday=2021-05-23&tree=all

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

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