Closed Bug 1703904 Opened 4 years ago Closed 4 years ago

Intermittent browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | Test timed out -

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2021-04-08T17:00:41.449Z] 17:00:41     INFO - TEST-START | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js
[task 2021-04-08T17:04:42.317Z] 17:04:42     INFO - TEST-INFO | started process screentopng
[task 2021-04-08T17:04:43.064Z] 17:04:43     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - Buffered messages logged at 17:00:41
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - Entering test bound test_uniqueDomainsVisitedInPast24Hours
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - TEST-PASS | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | We should have no domains recorded in the history right after resetting - 
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - Buffered messages finished
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | Test timed out - 
[task 2021-04-08T17:04:43.065Z] 17:04:43     INFO - Cleaning up
[task 2021-04-08T17:04:43.148Z] 17:04:43     INFO - GECKO(1560) | MEMORY STAT | vsize 130552056MB | residentFast 3521MB
[task 2021-04-08T17:04:43.150Z] 17:04:43     INFO - TEST-OK | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | took 241704ms
[task 2021-04-08T17:04:43.349Z] 17:04:43     INFO - checking window state
[task 2021-04-08T17:04:43.351Z] 17:04:43     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-08T17:04:43.351Z] 17:04:43     INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | Found a browser window after previous test timed out - 
[task 2021-04-08T17:04:43.351Z] 17:04:43     INFO - GECKO(1560) | must wait for focus
[task 2021-04-08T17:04:44.022Z] 17:04:44     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-08T17:04:44.022Z] 17:04:44     INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | Uncaught exception received from previously timed out test - at resource://testing-common/BrowserTestUtils.jsm:500 - Error: The window unloaded while we were waiting for the browser to load - this should never happen.
[task 2021-04-08T17:04:44.022Z] 17:04:44     INFO - Stack trace:
[task 2021-04-08T17:04:44.022Z] 17:04:44     INFO - listener@resource://testing-common/BrowserTestUtils.jsm:500:15
[task 2021-04-08T17:04:44.299Z] 17:04:44     INFO - GECKO(1560) | 1617901484292	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
[task 2021-04-08T17:04:44.440Z] 17:04:44     INFO - Console message: [JavaScript Error: "1617901484292	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-04-08T17:04:44.441Z] 17:04:44     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2021-04-08T17:04:44.441Z] 17:04:44     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2021-04-08T17:04:44.441Z] 17:04:44     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2021-04-08T17:04:44.441Z] 17:04:44     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4016:25
[task 2021-04-08T17:04:44.441Z] 17:04:44     INFO - 
[task 2021-04-08T17:04:54.322Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1718
[task 2021-04-08T17:04:54.326Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1814
[task 2021-04-08T17:04:54.404Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1660
[task 2021-04-08T17:04:54.411Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1753
[task 2021-04-08T17:04:54.419Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1785
[task 2021-04-08T17:04:54.500Z] 17:04:54     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1635
[task 2021-04-08T17:04:58.699Z] 17:04:58     INFO - GECKO(1560) | Completed ShutdownLeaks collections in process 1560
[task 2021-04-08T17:04:58.699Z] 17:04:58     INFO - TEST-START | Shutdown
[task 2021-04-08T17:04:58.699Z] 17:04:58     INFO - Browser Chrome Test Summary
[task 2021-04-08T17:04:58.699Z] 17:04:58     INFO - Passed:  1361
[task 2021-04-08T17:04:58.699Z] 17:04:58     INFO - Failed:  3
[task 2021-04-08T17:04:58.700Z] 17:04:58     INFO - Todo:    0
[task 2021-04-08T17:04:58.700Z] 17:04:58     INFO - Mode:    e10s
[task 2021-04-08T17:04:58.701Z] 17:04:58     INFO - *** End BrowserChrome Test Results ***
[task 2021-04-08T17:04:58.903Z] 17:04:58     INFO - GECKO(1560) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2021-04-08T17:04:59.468Z] 17:04:59     INFO - GECKO(1560) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-08T17:04:59.927Z] 17:04:59     INFO - GECKO(1560) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-08T17:05:00.003Z] 17:05:00     INFO - GECKO(1560) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-08T17:05:01.731Z] 17:05:01     INFO - GECKO(1560) | 1617901501726	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2021-04-08T17:05:01.732Z] 17:05:01     INFO - GECKO(1560) | 1617901501727	Marionette	INFO	Stopped listening on port 2828
[task 2021-04-08T17:05:01.732Z] 17:05:01     INFO - GECKO(1560) | 1617901501727	Marionette	DEBUG	Marionette stopped listening
[task 2021-04-08T17:05:05.110Z] 17:05:05     INFO - TEST-INFO | Main app process: exit 0
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - runtests.py | Application ran for: 0:10:06.560000
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - zombiecheck | Reading PID log: /tmp/tmpXQQQN7pidlog
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - ==> process 1560 launched child process 1575
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - ==> process 1560 launched child process 1635
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - ==> process 1560 launched child process 1660
[task 2021-04-08T17:05:05.112Z] 17:05:05     INFO - ==> process 1560 launched child process 1718
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - ==> process 1560 launched child process 1753
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - ==> process 1560 launched child process 1785
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - ==> process 1560 launched child process 1814
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - ==> process 1560 launched child process 1954
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1954
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1635
[task 2021-04-08T17:05:05.113Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1814
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1575
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1718
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1785
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1753
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - zombiecheck | Checking for orphan process with PID: 1660
[task 2021-04-08T17:05:05.114Z] 17:05:05     INFO - Stopping web server
[task 2021-04-08T17:05:05.129Z] 17:05:05     INFO - Server shut down.
[task 2021-04-08T17:05:05.153Z] 17:05:05     INFO - Web server killed.
[task 2021-04-08T17:05:05.153Z] 17:05:05     INFO - Stopping web socket server
[task 2021-04-08T17:05:05.175Z] 17:05:05     INFO - Stopping ssltunnel
[task 2021-04-08T17:05:05.195Z] 17:05:05  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-04-08T17:05:05.195Z] 17:05:05     INFO - runtests.py | Running tests: end.
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO - Buffered messages finished
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO -  TEST-INFO | checking window state
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO -  Browser Chrome Test Summary
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO -  	Passed: 1361
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO -  	Failed: 3
[task 2021-04-08T17:05:05.251Z] 17:05:05     INFO -  	Todo: 0
[task 2021-04-08T17:05:05.252Z] 17:05:05     INFO -  	Mode: e10s
[task 2021-04-08T17:05:05.252Z] 17:05:05     INFO -  *** End BrowserChrome Test Results ***
[task 2021-04-08T17:05:05.252Z] 17:05:05     INFO - Buffered messages finished
[task 2021-04-08T17:05:05.252Z] 17:05:05     INFO - SUITE-END | took 608s
[task 2021-04-08T17:05:05.299Z] 17:05:05    ERROR - Return code: 1
[task 2021-04-08T17:05:05.301Z] 17:05:05    ERROR - Got 3 unexpected statuses
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>33/<em class="testfail">3</em>/0
[task 2021-04-08T17:05:05.301Z] 17:05:05  WARNING - # TBPL WARNING #
[task 2021-04-08T17:05:05.301Z] 17:05:05  WARNING - setting return code to 1
[task 2021-04-08T17:05:05.301Z] 17:05:05  WARNING - The mochitest suite: mochitest-browser-chrome ran with return status: WARNING
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - [mozharness: 2021-04-08 17:05:05.301746Z] Finished run-tests step (success)
[task 2021-04-08T17:05:05.301Z] 17:05:05     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-08T17:05:05.493Z] 17:05:05     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 42.30415821501015}, {"name": "io_write_bytes", "value": 2234843136}, {"name": "io.read_bytes", "value": 72975261696}, {"name": "io_write_time", "value": 244252}, {"name": "io_read_time", "value": 9500588}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.01816391944885254}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 33.45243310928345}, {"name": "cpu_percent", "value": 25.203125}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.0002009868621826172}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 609.3724310398102}, {"name": "cpu_percent", "value": 43.58894335511982}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - Total resource usage - Wall time: 643s; CPU: 44.0%; Read bytes: 72975261696; Write bytes: 2234843136; Read time: 9500588; Write time: 244252
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: CPU usage<br/>43.6%
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: I/O read bytes / time<br/>72,975,261,696 / 9,500,588
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: I/O write bytes / time<br/>2,234,843,136 / 244,252
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: CPU idle<br/>839.4 (32.9%)
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: CPU iowait<br/>857.6 (33.6%)
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: CPU system<br/>96.4 (3.8%)
[task 2021-04-08T17:05:05.497Z] 17:05:05     INFO - TinderboxPrint: CPU user<br/>757.6 (29.7%)
[task 2021-04-08T17:05:05.498Z] 17:05:05     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-08T17:05:05.498Z] 17:05:05     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-04-08T17:05:05.499Z] 17:05:05     INFO - install - Wall time: 33s; CPU: 25.0%; Read bytes: 4096; Write bytes: 1597775872; Read time: 0; Write time: 163600
[task 2021-04-08T17:05:05.499Z] 17:05:05     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-04-08T17:05:05.502Z] 17:05:05     INFO - run-tests - Wall time: 609s; CPU: 44.0%; Read bytes: 72974831616; Write bytes: 380821504; Read time: 9499700; Write time: 41888
[task 2021-04-08T17:05:05.581Z] 17:05:05  WARNING - returning nonzero exit status 1
[task 2021-04-08T17:05:05.617Z] cleanup
[task 2021-04-08T17:05:05.617Z] + cleanup
[task 2021-04-08T17:05:05.617Z] + local rv=1
[task 2021-04-08T17:05:05.617Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-04-08T17:05:05.617Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-04-08T17:05:05.638Z] + '[' ']'
[task 2021-04-08T17:05:05.638Z] + true
[task 2021-04-08T17:05:05.638Z] + cleanup_xvfb
[task 2021-04-08T17:05:05.638Z] ++ pidof Xvfb
[task 2021-04-08T17:05:05.644Z] + local xvfb_pid=50
[task 2021-04-08T17:05:05.644Z] + local vnc=false
[task 2021-04-08T17:05:05.644Z] + local interactive=false
[task 2021-04-08T17:05:05.644Z] + '[' -n 50 ']'
[task 2021-04-08T17:05:05.644Z] + [[ false == false ]]
[task 2021-04-08T17:05:05.644Z] + [[ false == false ]]
[task 2021-04-08T17:05:05.644Z] + kill 50
[task 2021-04-08T17:05:05.644Z] + screen -XS xvfb quit
[task 2021-04-08T17:05:05.671Z] + exit 1
[taskcluster 2021-04-08 17:05:06.674Z] === Task Finished ===
[taskcluster 2021-04-08 17:05:11.402Z] Unsuccessful task run with exit code: 1 completed in 962.106 seconds```
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.