Perma [tier2] test_end for telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping logged while not in progress.
Categories
(Toolkit :: Application Update, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox-esr78 | --- | unaffected |
firefox87 | --- | unaffected |
firefox88 | --- | unaffected |
firefox89 | --- | fixed |
firefox90 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: nalexander)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell needswork:owner])
Attachments
(1 file, 1 obsolete file)
Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=336621174&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/S6FwXgW9QtOkQTBK1yXEqw/runs/0/artifacts/public/logs/live_backing.log
[task 2021-04-15T09:53:33.359Z] 09:53:33 INFO - TEST-START | telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping
[task 2021-04-15T09:53:33.359Z] 09:53:33 INFO - Application command: Z:\task_1618479806\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_1618479806\build\tmpskny0dco.mozrunner
[task 2021-04-15T09:53:33.989Z] 09:53:33 INFO - [2021-04-15T09:53:33Z WARN rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2021-04-15T09:53:34.140Z] 09:53:34 INFO - 1618480414140 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2021-04-15T09:53:34.140Z] 09:53:34 INFO - 1618480414140 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2021-04-15T09:53:34.140Z] 09:53:34 INFO - 1618480414140 Toolkit.Telemetry TRACE TelemetryController::registerJsProbes - registering builtin JS probes
[task 2021-04-15T09:53:34.141Z] 09:53:34 INFO - 1618480414141 Toolkit.Telemetry TRACE TelemetryController::registerScalarProbes - registering scalar builtin JS probes
[task 2021-04-15T09:53:34.141Z] 09:53:34 INFO - 1618480414141 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json
[task 2021-04-15T09:53:34.144Z] 09:53:34 INFO - 1618480414145 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2021-04-15T09:53:34.145Z] 09:53:34 INFO - 1618480414145 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2021-04-15T09:53:34.145Z] 09:53:34 INFO - 1618480414145 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2021-04-15T09:53:34.154Z] 09:53:34 INFO - 1618480414154 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-04-15T09:53:34.155Z] 09:53:34 INFO - 1618480414155 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2021-04-15T09:53:34.164Z] 09:53:34 INFO - 1618480414164 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2021-04-15T09:53:34.184Z] 09:53:34 INFO - 1618480414184 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2021-04-15T09:53:34.186Z] 09:53:34 INFO - DLL blocklist was unable to intercept AppInit DLLs.
[task 2021-04-15T09:53:34.189Z] 09:53:34 INFO - 1618480414189 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2021-04-15T09:53:34.189Z] 09:53:34 INFO - 1618480414189 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2021-04-15T09:53:34.192Z] 09:53:34 INFO - 1618480414193 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2021-04-15T09:53:34.214Z] 09:53:34 INFO - 1618480414213 Marionette INFO Marionette enabled
[task 2021-04-15T09:53:34.344Z] 09:53:34 INFO - 1618480414344 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-04-15T09:53:34.361Z] 09:53:34 INFO - 1618480414361 Toolkit.Telemetry TRACE TelemetryController::registerEventProbes - registering builtin JS Event probes
[task 2021-04-15T09:53:34.361Z] 09:53:34 INFO - 1618480414361 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json
[task 2021-04-15T09:53:34.371Z] 09:53:34 INFO - 1618480414370 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2021-04-15T09:53:34.395Z] 09:53:34 INFO - [Parent 5248, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4236
[task 2021-04-15T09:53:34.857Z] 09:53:34 INFO - [Parent 5248, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4234
[task 2021-04-15T09:53:35.070Z] 09:53:35 INFO - [Parent 5248, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp:1562
[task 2021-04-15T09:53:41.854Z] 09:53:41 INFO - fog_ping_server pings_handler received 'baseline' ping
[task 2021-04-15T09:53:41.865Z] 09:53:41 INFO - [Parent 10960: Unnamed thread 1e398947c00]: V/fog_control::* [fog_control::viaduct_uploader] FOG Ping Uploader completed uploading to http://localhost:50600/submit/firefox-desktop/baseline/1/c08e34b2-d383-4ba1-83ce-f5a6e5e2343e (Result Ok(HttpStatus(200)))
[task 2021-04-15T09:53:41.866Z] 09:53:41 INFO - [Parent 10960: Unnamed thread 1e398947c00]: I/glean_core::* [glean_core::upload] Ping c08e34b2-d383-4ba1-83ce-f5a6e5e2343e successfully sent 200.
[task 2021-04-15T09:53:41.866Z] 09:53:41 INFO - [Parent 10960: Unnamed thread 1e398947c00]: I/glean_core::* [glean_core::upload::directory] File was deleted Z:\task_1618479806\build\tmpk5sahgq6.mozrunner/datareporting/glean\pending_pings\c08e34b2-d383-4ba1-83ce-f5a6e5e2343e
[task 2021-04-15T09:53:41.867Z] 09:53:41 INFO - [Parent 10960: Unnamed thread 1e398947c00]: I/glean_core::* [glean_core::upload] No more pings to upload! You are done.
[task 2021-04-15T09:53:42.137Z] 09:53:42 INFO - 1618480422136 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-04-15T09:53:42.138Z] 09:53:42 INFO - 1618480422138 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2021-04-15T09:53:42.194Z] 09:53:42 INFO - 1618480422194 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-04-15T09:53:42.194Z] 09:53:42 INFO - 1618480422194 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-04-15T09:53:42.250Z] 09:53:42 INFO - 1618480422250 Marionette TRACE All scripts recorded.
[task 2021-04-15T09:53:42.253Z] 09:53:42 INFO - 1618480422252 Marionette INFO Listening on port 2828
[task 2021-04-15T09:53:42.253Z] 09:53:42 INFO - 1618480422253 Marionette DEBUG Marionette is listening
[task 2021-04-15T09:53:42.320Z] 09:53:42 INFO - 1618480422320 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: write-settings-to-disk-complete
[task 2021-04-15T09:53:42.339Z] 09:53:42 INFO - 1618480422339 Marionette DEBUG Accepted connection 0 from 127.0.0.1:50635
[task 2021-04-15T09:53:42.344Z] 09:53:42 INFO - 1618480422344 Marionette DEBUG Closed connection 0
[task 2021-04-15T09:53:42.345Z] 09:53:42 INFO - 1618480422345 Marionette DEBUG Accepted connection 1 from 127.0.0.1:50636
[task 2021-04-15T09:53:42.393Z] 09:53:42 INFO - 1618480422393 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-04-15T09:53:42.424Z] 09:53:42 INFO - 1618480422423 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"f8aabfa2-d83f-4f4a-acbc-073cb74d2afd","capabilities":{"browserName":"firefox","browserVersion":"89.0a ... \tmpk5sahgq6.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2021-04-15T09:53:42.431Z] 09:53:42 INFO - [Parent 10960, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4234
[task 2021-04-15T09:53:42.431Z] 09:53:42 INFO - [Parent 10960, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4234
[task 2021-04-15T09:53:42.437Z] 09:53:42 INFO - 1618480422437 Marionette DEBUG 1 -> [0,2,"Marionette:SetContext",{"value":"content"}]
[task 2021-04-15T09:53:42.437Z] 09:53:42 INFO - 1618480422438 Marionette DEBUG 1 <- [1,2,null,{"value":null}]
[task 2021-04-15T09:53:42.455Z] 09:53:42 INFO - 1618480422454 Marionette DEBUG 1 -> [0,3,"Marionette:GetContext",{}]
[task 2021-04-15T09:53:42.455Z] 09:53:42 INFO - 1618480422455 Marionette DEBUG 1 <- [1,3,null,{"value":"content"}]
[task 2021-04-15T09:53:42.459Z] 09:53:42 INFO - 1618480422459 Marionette DEBUG 1 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-04-15T09:53:42.460Z] 09:53:42 INFO - 1618480422459 Marionette DEBUG 1 <- [1,4,null,{"value":null}]
[task 2021-04-15T09:53:42.464Z] 09:53:42 INFO - 1618480422463 Marionette DEBUG 1 -> [0,5,"WebDriver:ExecuteScript",{"script":"return AppConstants.MOZ_UPDATE_AGENT;","args":[],"newSandbox":true,"sandbox":"defau ... 26,"filename":"Z:\\task_1618479806\\build\\tests\\telemetry\\marionette\\tests\\client\\test_fog_background_update_ping.py"}]
[task 2021-04-15T09:53:42.470Z] 09:53:42 INFO - 1618480422471 Marionette TRACE [7] MarionetteCommands actor created for window id 2
[task 2021-04-15T09:53:42.478Z] 09:53:42 INFO - 1618480422478 Marionette DEBUG 1 <- [1,5,null,{"value":false}]
[task 2021-04-15T09:53:42.480Z] 09:53:42 INFO - 1618480422480 Marionette DEBUG 1 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2021-04-15T09:53:42.480Z] 09:53:42 INFO - 1618480422480 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2021-04-15T09:53:42.485Z] 09:53:42 INFO - 1618480422485 Marionette DEBUG 1 -> [0,7,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-04-15T09:53:42.486Z] 09:53:42 INFO - 1618480422486 Marionette DEBUG 1 <- [1,7,null,["7"]]
[task 2021-04-15T09:53:42.490Z] 09:53:42 INFO - 1618480422490 Marionette DEBUG 1 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2021-04-15T09:53:42.490Z] 09:53:42 INFO - 1618480422490 Marionette DEBUG 1 <- [1,8,null,["19"]]
[task 2021-04-15T09:53:42.760Z] 09:53:42 INFO - 1618480422760 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.lastupdatetime
[task 2021-04-15T09:53:42.760Z] 09:53:42 INFO - 1618480422761 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.nextupdatetime
[task 2021-04-15T09:53:42.982Z] 09:53:42 INFO - pingserver Stopped http server on localhost:8000
[task 2021-04-15T09:53:43.355Z] 09:53:43 INFO - pingserver Stopped http server on localhost:50600
[task 2021-04-15T09:53:43.356Z] 09:53:43 INFO - TEST-SKIP | telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping | took 9997ms
[task 2021-04-15T09:53:43.359Z] 09:53:43 ERROR - test_end for telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 247, in run\n self.tearDown()\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\telemetry_harness\\fog_testcase.py\", line 61, in tearDown\n super(FOGTestCase, self).tearDown(*args, **kwargs)\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\telemetry_harness\\testcase.py\", line 240, in tearDown\n super(TelemetryTestCase, self).tearDown()\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py\", line 24, in tearDown\n if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1338, in chrome_window_handles\n return self._send_message(\"WebDriver:GetChromeWindowHandles\")\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 27, in _\n return func(*args, **kwargs)\n File \"Z:\\task_1618479806\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 618, in _send_message\n raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_fog_background_update_ping.TestBackgroundUpdatePing", "method_name": "test_background_update_ping"}, "test": "telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping", "status": "ERROR"}
Updated•4 years ago
|
Updated•4 years ago
|
Updated•4 years ago
|
Assignee | ||
Comment 1•4 years ago
|
||
I will investigate this.
Comment hidden (Intermittent Failures Robot) |
Comment 3•4 years ago
|
||
Update:
There have been 42 failures within the last 7 days:
- 21 failures on Windows 7 MinGW debug
- 21 failures on Windows 10 x64 MinGW debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=337622267&repo=mozilla-central&lineNumber=8068
[task 2021-04-24T16:27:23.107Z] 16:27:23 INFO - 1619281643106 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.lastupdatetime
[task 2021-04-24T16:27:23.107Z] 16:27:23 INFO - 1619281643108 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.nextupdatetime
[task 2021-04-24T16:27:23.260Z] 16:27:23 INFO - pingserver Stopped http server on localhost:8000
[task 2021-04-24T16:27:23.503Z] 16:27:23 INFO - pingserver Stopped http server on localhost:50780
[task 2021-04-24T16:27:23.504Z] 16:27:23 INFO - TEST-SKIP | telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping | took 11179ms
[task 2021-04-24T16:27:23.507Z] 16:27:23 ERROR - test_end for telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n File "Z:\task_1619281263\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 247, in run\n self.tearDown()\n File "Z:\task_1619281263\build\venv\lib\site-packages\telemetry_harness\fog_testcase.py", line 61, in tearDown\n super(FOGTestCase, self).tearDown(*args, **kwargs)\n File "Z:\task_1619281263\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 240, in tearDown\n super(TelemetryTestCase, self).tearDown()\n File "Z:\task_1619281263\build\venv\lib\site-packages\marionette_harness\runner\mixins\window_manager.py", line 24, in tearDown\n if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n File "Z:\task_1619281263\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1338, in chrome_window_handles\n return self._send_message("WebDriver:GetChromeWindowHandles")\n File "Z:\task_1619281263\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _\n return func(*args, **kwargs)\n File "Z:\task_1619281263\build\venv\lib\site-packages\marionette_driver\marionette.py", line 618, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n", "extra": {"class_name": "test_fog_background_update_ping.TestBackgroundUpdatePing", "method_name": "test_background_update_ping"}, "test": "telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping", "status": "ERROR"}
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 6•4 years ago
|
||
We had --disable-update-agent
due to Bug 1561797, a deep interaction
between Rust, clang/lld, and the MinGW toolchain. This was because
the background update agent was to be written in Rust. Bug 1681574
removed the update agent Rust skeleton and in Bug 1689520 we went in a
totally different direction, implementing the background update part
as a background task implemented in Firefox itself. And this works
just fine on Windows MinGW, so we need not disable it.
Assignee | ||
Comment 7•4 years ago
|
||
(In reply to Andreea Pavel [:apavel] from comment #4)
Nick are there updates here?
Yes! This one is interesting. It's not intermittent; it just looks that way 'cuz it's the mingwclang
variants that fail. What's happening is that those variants have --disable-update-agent
from a previous technology generation (see Bug 1561797). The test doesn't have access to this statically, so it skips itself when the flag isn't enabled, and this is a failure.
I've pushed a patch for review and a try build is percolating: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c7a24a8dfbb81dc7ca36703c1638218cee150cb5.
Assignee | ||
Comment 8•4 years ago
|
||
(In reply to Nick Alexander :nalexander [he/him] from comment #7)
(In reply to Andreea Pavel [:apavel] from comment #4)
Nick are there updates here?
Yes! This one is interesting. It's not intermittent; it just looks that way 'cuz it's the
mingwclang
variants that fail. What's happening is that those variants have--disable-update-agent
from a previous technology generation (see Bug 1561797). The test doesn't have access to this statically, so it skips itself when the flag isn't enabled, and this is a failure.I've pushed a patch for review and a try build is percolating: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c7a24a8dfbb81dc7ca36703c1638218cee150cb5.
Try build looks green. Clearing NI; I expect to land this in the normal manner.
Assignee | ||
Comment 9•4 years ago
|
||
New try build, skipping the test, looks green at https://treeherder.mozilla.org/jobs?repo=try&revision=3b4749620c75a020d261947cf648b7a38c86edf5.
Assignee | ||
Comment 10•4 years ago
|
||
There's no technical reason not to --enable-update-agent and run this
test on MinGW, but there are policy reasons:
-
the installer and uninstaller don't completely succeed on MinGW
-
we propose to not background update installations not installed
with the Windows installer in the near future (see
discussion) -
we propose to use the WDBA to remove background tasks on
Windows, and
the WDBA is not supported on MinGW.
Updated•4 years ago
|
Comment 11•4 years ago
|
||
Comment 12•4 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment 14•4 years ago
|
||
The patch landed in nightly and beta is affected.
:nalexander, is this bug important enough to require an uplift?
If not please set status_beta
to wontfix
.
For more information, please visit auto_nag documentation.
Assignee | ||
Comment 15•4 years ago
|
||
Comment on attachment 9218852 [details]
Bug 1705442 - Skip test_fog_background_update_ping.py
on MinGW. r?agashlin
Beta/Release Uplift Approval Request
- User impact if declined: None.
- Is this code covered by automated tests?: Yes
- Has the fix been verified in Nightly?: Yes
- Needs manual test from QE?: No
- If yes, steps to reproduce:
- List of other uplifts needed: None
- Risk to taking this patch: Low
- Why is the change risky/not risky? (and alternatives if risky): Not risky: this is just disabling a test on a platform where it fails; it's a quality of life issue for sheriffs.
- String changes made/needed:
Comment 16•4 years ago
|
||
Comment on attachment 9218852 [details]
Bug 1705442 - Skip test_fog_background_update_ping.py
on MinGW. r?agashlin
test-only changes don't require approval
Comment 17•4 years ago
|
||
bugherder uplift |
Updated•4 years ago
|
Description
•