Closed Bug 1705442 Opened 4 years ago Closed 4 years ago

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)

Product:
Toolkit
Component:
Application Update
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
90 Branch
Tracking Flags:
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)

Bug 1705442 - Skip `test_fog_background_update_ping.py` on MinGW. r?agashlin
(deleted), text/x-phabricator-request
Details

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"}
Flags: needinfo?(nalexander)
Whiteboard: [retriggered][stockwell needswork:owner]

I will investigate this.

Assignee: nobody → nalexander
Status: NEW → ASSIGNED
Flags: needinfo?(nalexander)

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"}

Nick are there updates here?

Flags: needinfo?(nalexander)

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.

(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.

(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.

Flags: needinfo?(nalexander)

There's no technical reason not to --enable-update-agent and run this
test on MinGW, but there are policy reasons:

  1. the installer and uninstaller don't completely succeed on MinGW

  2. we propose to not background update installations not installed
    with the Windows installer in the near future (see
    discussion)

  3. we propose to use the WDBA to remove background tasks on
    Windows    , and
    the WDBA is not supported on MinGW.

Attachment #9218392 - Attachment is obsolete: true
Pushed by nalexander@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/2a05168f7469 Skip `test_fog_background_update_ping.py` on MinGW. r=agashlin

https://hg.mozilla.org/mozilla-central/rev/2a05168f7469

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox90: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 90 Branch

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.

Flags: needinfo?(nalexander)

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:
Flags: needinfo?(nalexander)
Attachment #9218852 - Flags: approval-mozilla-beta?

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

Attachment #9218852 - Flags: approval-mozilla-beta?
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: