1691915 - Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/url-classifier/tests/unit/test_safebrowsing_protobuf.js | Test timed out

Status: RESOLVED INCOMPLETE

(Toolkit :: Safe Browsing, defect, P5)

Description

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

---

[task 2021-02-10T08:41:35.403Z] 08:41:35     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_WebExtensionContentScript.js | took 1752ms
[task 2021-02-10T08:41:35.472Z] 08:41:35     INFO -  TEST-START | toolkit/components/url-classifier/tests/unit/test_safebrowsing_protobuf.js
[task 2021-02-10T08:46:35.485Z] 08:46:35  WARNING -  TEST-UNEXPECTED-TIMEOUT | toolkit/components/url-classifier/tests/unit/test_safebrowsing_protobuf.js | Test timed out
[task 2021-02-10T08:46:35.485Z] 08:46:35     INFO -  TEST-INFO took 300004ms
[task 2021-02-10T08:46:35.485Z] 08:46:35     INFO -  >>>>>>>
[task 2021-02-10T08:46:35.485Z] 08:46:35     INFO -  PID 12700 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2021-02-10T08:46:35.485Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-02-10T08:46:35.485Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, 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:2916
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp:3324
[task 2021-02-10T08:46:35.486Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp:3324
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp:3324
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp:3324
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  TEST-PASS | toolkit/components/url-classifier/tests/unit/test_safebrowsing_protobuf.js | run_test - [run_test : 27] "ChUKE25hdmNsaWVudC1hdXRvLWZmb3g=" == "ChUKE25hdmNsaWVudC1hdXRvLWZmb3g="
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  TEST-PASS | toolkit/components/url-classifier/tests/unit/test_safebrowsing_protobuf.js | run_test - [run_test : 28] "ChUKE25hdmNsaWVudC1hdXRvLWZmb3gaEAgFEAEaBAAAAAAiAiACKAE=" == "ChUKE25hdmNsaWVudC1hdXRvLWZmb3gaEAgFEAEaBAAAAAAiAiACKAE="
[task 2021-02-10T08:46:35.487Z] 08:46:35     INFO -  (xpcshell/head.js) | test MAIN run_test finished (1)
[task 2021-02-10T08:46:35.488Z] 08:46:35     INFO -  exiting test
[task 2021-02-10T08:46:35.488Z] 08:46:35     INFO -  PID 12700 | [Parent 12700, 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:377
[task 2021-02-10T08:46:35.488Z] 08:46:35     INFO -  <<<<<<<
[task 2021-02-10T08:46:35.617Z] 08:46:35     INFO -  xpcshell return code: 1
[task 2021-02-10T08:46:35.654Z] 08:46:35     INFO -  TEST-START | toolkit/components/url-classifier/tests/unit/test_platform_specific_threats.js
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  TEST-PASS | toolkit/components/url-classifier/tests/unit/test_platform_specific_threats.js | took 667ms
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  INFO | Result summary:
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  INFO | Passed: 1654
[task 2021-02-10T08:46:36.341Z] 08:46:36  WARNING -  INFO | Failed: 1
[task 2021-02-10T08:46:36.341Z] 08:46:36  WARNING -  One or more unittests failed.
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  INFO | Todo: 4
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  INFO | Retried: 64
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  SUITE-END | took 2086s
[task 2021-02-10T08:46:36.341Z] 08:46:36     INFO -  Node moz-http2 server shutting down ...
[task 2021-02-10T08:49:41.876Z] WARNING | IO Completion Port failed to signal process shutdown
[task 2021-02-10T08:49:41.876Z] Parent process 6544 exited with children alive:
[task 2021-02-10T08:49:41.876Z] PIDS: 9760, 19500, 13236, 14972, 3352, 9400, 15564, 8940, 6400, 10500, 17204, 5940, 1868, 856, 6004, 16960, 5544, 13168, 4088
[task 2021-02-10T08:49:41.876Z] Attempting to kill them, but no guarantee of success
[task 2021-02-10T08:49:41.909Z] 08:49:41    ERROR - Return code: 1
[task 2021-02-10T08:49:41.909Z] 08:49:41     INFO - TinderboxPrint: xpcshell-xpcshell<br/>1654/<em class="testfail">1</em>/4
[task 2021-02-10T08:49:41.909Z] 08:49:41  WARNING - # TBPL FAILURE #
[task 2021-02-10T08:49:41.909Z] 08:49:41  WARNING - setting return code to 2
[task 2021-02-10T08:49:41.909Z] 08:49:41  WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2021-02-10T08:49:41.909Z] 08:49:41     INFO - Running post-action listener: _package_coverage_data
[task 2021-02-10T08:49:41.909Z] 08:49:41     INFO - Running post-action listener: _resource_record_post_action
[task 2021-02-10T08:49:41.910Z] 08:49:41     INFO - Running post-action listener: process_java_coverage_data
[task 2021-02-10T08:49:41.910Z] 08:49:41     INFO - [mozharness: 2021-02-10 08:49:41.910000Z] Finished run-tests step (success)
[task 2021-02-10T08:49:41.910Z] 08:49:41     INFO - Running post-run listener: _resource_record_post_run
[task 2021-02-10T08:49:42.163Z] 08:49:42     INFO - Validating Perfherder data against Z:\task_1612944358\mozharness\external_tools\performance-artifact-schema.json
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 97.72180317848412}, {"name": "io_write_bytes", "value": 11704602624}, {"name": "io.read_bytes", "value": 178990592}, {"name": "io_write_time", "value": 317}, {"name": "io_read_time", "value": 12}], "extraOptions": ["e10s", "taskcluster-c5.2xlarge"], "name": "xpcshell.xpcshell.overall"}, {"subtests": [{"name": "time", "value": 0.0}], "name": "xpcshell.xpcshell.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 2.678999900817871}, {"name": "cpu_percent", "value": 14.53125}], "name": "xpcshell.xpcshell.install"}, {"subtests": [{"name": "time", "value": 0.01900005340576172}], "name": "xpcshell.xpcshell.stage-files"}, {"subtests": [{"name": "time", "value": 2325.553999900818}, {"name": "cpu_percent", "value": 97.84400097943194}], "name": "xpcshell.xpcshell.run-tests"}]}
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - Total resource usage - Wall time: 2328s; CPU: 98.0%; Read bytes: 178990592; Write bytes: 11704602624; Read time: 12; Write time: 317
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: CPU usage<br/>97.8%
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: I/O read bytes / time<br/>178,990,592 / 12
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: I/O write bytes / time<br/>11,704,602,624 / 317
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: CPU idle<br/>371.5 (2.0%)
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: CPU system<br/>12,734.7 (68.3%)
[task 2021-02-10T08:49:42.167Z] 08:49:42     INFO - TinderboxPrint: CPU user<br/>5,511.1 (29.6%)
[task 2021-02-10T08:49:42.169Z] 08:49:42     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-02-10T08:49:42.171Z] 08:49:42     INFO - install - Wall time: 3s; CPU: 15.0%; Read bytes: 0; Write bytes: 17874944; Read time: 0; Write time: 0
[task 2021-02-10T08:49:42.173Z] 08:49:42     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-02-10T08:49:42.196Z] 08:49:42     INFO - run-tests - Wall time: 2326s; CPU: 98.0%; Read bytes: 178793984; Write bytes: 11647094784; Read time: 12; Write time: 316
[task 2021-02-10T08:49:42.763Z] 08:49:42  WARNING - returning nonzero exit status 2
[taskcluster 2021-02-10T08:49:42.808Z]    Exit Code: 2
[taskcluster 2021-02-10T08:49:42.808Z]    User Time: 0s
[taskcluster 2021-02-10T08:49:42.808Z]  Kernel Time: 15.625ms
[taskcluster 2021-02-10T08:49:42.808Z]    Wall Time: 41m7.617102s
[taskcluster 2021-02-10T08:49:42.808Z]       Result: FAILED
[taskcluster 2021-02-10T08:49:42.808Z] === Task Finished ===
[taskcluster 2021-02-10T08:49:42.808Z] Task Duration: 41m7.6180828s
[taskcluster 2021-02-10T08:49:42.994Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:43.764Z] Uploading artifact public/test_info/450b975c-0092-4706-b64c-8268f2f7e565.dmp from file build\blobber_upload_dir\450b975c-0092-4706-b64c-8268f2f7e565.dmp with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:44.446Z] Uploading artifact public/test_info/450b975c-0092-4706-b64c-8268f2f7e565.extra from file build\blobber_upload_dir\450b975c-0092-4706-b64c-8268f2f7e565.extra with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:44.808Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:45.357Z] Uploading artifact public/test_info/system-info.log from file build\blobber_upload_dir\system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:45.680Z] 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 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:45.996Z] 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 2022-02-10T07:37:19.208Z
[taskcluster 2021-02-10T08:49:46.374Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VkXcaaJyQF6cr3KU11XsMw/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-02-10T07:37:19.208Z
[taskcluster:error] exit status 2```

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691915&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 2

[Intermittent Failures Robot]

2 failures in 3737 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691915&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 3

[BugBot [:suhaib / :marco]]

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