1608807 - Intermittent telemetry/marionette/tests/client/test_search_counts_across_sessions.py TestSearchCounts.test_search_counts | AssertionError: u'9d44c05d-90f7-470b-a7ce-51697d48d5d3' is not None

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Treeherder Bug Filer]

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

---

[task 2020-01-13T12:29:16.698Z] 12:29:16 INFO - 1578918556692 Toolkit.Telemetry TRACE TelemetryStorage::_scanArchive
[task 2020-01-13T12:29:16.719Z] 12:29:16 INFO - 1578918556718 Toolkit.Telemetry TRACE TelemetryStorage::_scanArchive - checking in subdir: /builds/worker/workspace/build/tmpdd9ZUL.mozrunner/datareporting/archived/2020-01
[task 2020-01-13T12:29:16.735Z] 12:29:16 INFO - 1578918556730 Toolkit.Telemetry TRACE TelemetryStorage::_enforceArchiveQuota
[task 2020-01-13T12:29:16.816Z] 12:29:16 INFO - 1578918556810 Marionette TRACE Received observer notification marionette-startup-requested
[task 2020-01-13T12:29:16.816Z] 12:29:16 INFO - 1578918556811 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2020-01-13T12:29:16.876Z] 12:29:16 INFO - 1578918556865 Marionette TRACE All scripts recorded.
[task 2020-01-13T12:29:16.880Z] 12:29:16 INFO - 1578918556876 Marionette INFO Listening on port 2828
[task 2020-01-13T12:29:16.883Z] 12:29:16 INFO - 1578918556876 Marionette DEBUG Marionette is listening
[task 2020-01-13T12:29:16.899Z] 12:29:16 INFO - 1578918556897 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2020-01-13T12:29:16.907Z] 12:29:16 INFO - 1578918556902 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2020-01-13T12:29:16.907Z] 12:29:16 INFO - 1578918556902 Toolkit.Telemetry TRACE TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2020-01-13T12:29:16.948Z] 12:29:16 INFO - 1578918556943 Marionette DEBUG Accepted connection 0 from 127.0.0.1:46498
[task 2020-01-13T12:29:16.948Z] 12:29:16 INFO - 1578918556943 Marionette DEBUG Closed connection 0
[task 2020-01-13T12:29:16.948Z] 12:29:16 INFO - 1578918556944 Marionette DEBUG Accepted connection 1 from 127.0.0.1:46500
[task 2020-01-13T12:29:16.948Z] 12:29:16 INFO - 1578918556945 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556949 Marionette TRACE [9] Frame script loaded
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556949 Marionette TRACE [9] Frame script registered
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556949 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: marionette.contentListener
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556951 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"178c946c-e8ec-4f55-a4f2-fcbaa35f2bf4","capabilities":{"browserName":"firefox","browserVersion":"74.0" ... ld/tmpdd9ZUL.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556952 Marionette DEBUG 1 -> [0,2,"Marionette:SetContext",{"value":"content"}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556952 Marionette DEBUG 1 <- [1,2,null,{"value":null}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556953 Marionette DEBUG 1 -> [0,3,"Marionette:GetContext",{}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556953 Marionette DEBUG 1 <- [1,3,null,{"value":"content"}]
[task 2020-01-13T12:29:16.956Z] 12:29:16 INFO - 1578918556954 Marionette DEBUG 1 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-01-13T12:29:16.957Z] 12:29:16 INFO - 1578918556954 Marionette DEBUG 1 <- [1,4,null,{"value":null}]
[task 2020-01-13T12:29:16.957Z] 12:29:16 INFO - 1578918556955 Marionette DEBUG 1 -> [0,5,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-01-13T12:29:17.042Z] 12:29:17 INFO - TEST-UNEXPECTED-FAIL | telemetry/marionette/tests/client/test_search_counts_across_sessions.py TestSearchCounts.test_search_counts | AssertionError: u'9d44c05d-90f7-470b-a7ce-51697d48d5d3' is not None
[task 2020-01-13T12:29:17.042Z] 12:29:17 INFO - Traceback (most recent call last):
[task 2020-01-13T12:29:17.042Z] 12:29:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2020-01-13T12:29:17.042Z] 12:29:17 INFO - testMethod()
[task 2020-01-13T12:29:17.043Z] 12:29:17 INFO - File "/builds/worker/workspace/build/tests/telemetry/marionette/tests/client/test_search_counts_across_sessions.py", line 88, in test_search_counts
[task 2020-01-13T12:29:17.043Z] 12:29:17 INFO - self.assertIsNone(ping1_info["previousSubsessionId"])
[task 2020-01-13T12:29:17.043Z] 12:29:17 INFO - TEST-INFO took 8588ms
[task 2020-01-13T12:29:17.044Z] 12:29:17 INFO - 1578918557003 Marionette DEBUG 1 <- [1,5,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd368dZ50nal8yp50/ACeihfqoRZz29vZOQpwdQxwn9qZPr ... AIAAAAAIEJAAEAAAAgMAEgAAAAAAQmAAQAAACAwASAAAAAABCYABAAAAAAAhMAAgAAAEBgAkAAAAAACEwACAAAAACB/T/ls9jpRQLI6gAAAABJRU5ErkJggg=="}]
[task 2020-01-13T12:29:17.045Z] 12:29:17 INFO - 1578918557005 Marionette DEBUG 1 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2020-01-13T12:29:17.045Z] 12:29:17 INFO - 1578918557005 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2020-01-13T12:29:17.046Z] 12:29:17 INFO - 1578918557006 Marionette DEBUG 1 -> [0,7,"Marionette:GetContext",{}]
[task 2020-01-13T12:29:17.046Z] 12:29:17 INFO - 1578918557006 Marionette DEBUG 1 <- [1,7,null,{"value":"content"}]
[task 2020-01-13T12:29:17.047Z] 12:29:17 INFO - 1578918557007 Marionette DEBUG 1 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2020-01-13T12:29:17.047Z] 12:29:17 INFO - 1578918557007 Marionette DEBUG 1 <- [1,8,null,{"value":null}]
[task 2020-01-13T12:29:17.048Z] 12:29:17 INFO - 1578918557007 Marionette DEBUG 1 -> [0,9,"WebDriver:GetPageSource",{}]
[task 2020-01-13T12:29:17.048Z] 12:29:17 INFO - 1578918557008 Marionette DEBUG 1 <- [1,9,null,{"value":"<html xmlns="http://www.w3.org/1999/xhtml" dir="ltr" lang="en-US">\n<head>\n <meta http-equiv="Co ... "about:webrtc">about:webrtc</a></li><li><a href="about:welcome">about:welcome</a></li></ul>\n </div>\n</body>\n</html>"}]
[task 2020-01-13T12:29:17.048Z] 12:29:17 INFO - 1578918557009 Marionette DEBUG 1 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2020-01-13T12:29:17.049Z] 12:29:17 INFO - 1578918557010 Marionette DEBUG 1 <- [1,10,null,{"value":null}]
[task 2020-01-13T12:29:17.049Z] 12:29:17 INFO - 1578918557018 Marionette DEBUG 1 -> [0,11,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-01-13T12:29:17.050Z] 12:29:17 INFO - 1578918557018 Marionette DEBUG 1 <- [1,11,null,["1"]]
[task 2020-01-13T12:29:17.050Z] 12:29:17 INFO - 1578918557018 Marionette DEBUG 1 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-01-13T12:29:17.051Z] 12:29:17 INFO - 1578918557019 Marionette DEBUG 1 <- [1,12,null,["9"]]
[task 2020-01-13T12:29:17.548Z] 12:29:17 INFO - TEST-START | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 2

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

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

Comment 3

[Bogdan Tara[:bogdan_tara | bogdant]]

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=289982404&repo=mozilla-beta&lineNumber=3067

...
[task 2020-02-21T23:40:52.545Z] 23:40:52     INFO - pingserver pings_handler received 'main' ping with reason 'shutdown'
[task 2020-02-21T23:40:52.562Z] 23:40:52     INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2020-02-21T23:40:52.572Z] 23:40:52     INFO -  1582328452559	Toolkit.Telemetry	INFO	TelemetrySend::_doPing - successfully loaded, status: 200
[task 2020-02-21T23:40:52.573Z] 23:40:52     INFO -  1582328452559	Toolkit.Telemetry	TRACE	TelemetrySend::_onPingRequestFinished - success: true, persisted: true
[task 2020-02-21T23:40:52.573Z] 23:40:52     INFO -  1582328452559	Toolkit.Telemetry	TRACE	TelemetryStorage::removePendingPing - deleting ping with id: f88f2103-e74c-420d-acf2-0fbb885f5008, path: /builds/worker/workspace/build/tmpMMO3j_.mozrunner/saved-telemetry-pings/f88f2103-e74c-420d-acf2-0fbb885f5008
[task 2020-02-21T23:40:52.575Z] 23:40:52     INFO -  1582328452563	Toolkit.Telemetry	INFO	TelemetrySend::_doPing - successfully loaded, status: 200
[task 2020-02-21T23:40:52.575Z] 23:40:52     INFO -  1582328452563	Toolkit.Telemetry	TRACE	TelemetrySend::_onPingRequestFinished - success: true, persisted: true
[task 2020-02-21T23:40:52.575Z] 23:40:52     INFO -  1582328452563	Toolkit.Telemetry	TRACE	TelemetryStorage::removePendingPing - deleting ping with id: b75645a7-e80b-44d1-afcc-65d5b5e67b98, path: /builds/worker/workspace/build/tmpMMO3j_.mozrunner/saved-telemetry-pings/b75645a7-e80b-44d1-afcc-65d5b5e67b98
[task 2020-02-21T23:40:52.575Z] 23:40:52     INFO -  1582328452571	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0
[task 2020-02-21T23:40:52.599Z] 23:40:52     INFO -  1582328452596	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: browser-search-service, aData: settings-update-complete
[task 2020-02-21T23:40:52.626Z] 23:40:52     INFO -  1582328452622	Toolkit.Telemetry	TRACE	TelemetryStorage::loadPingfile - unreadable ping /builds/worker/workspace/build/tmpMMO3j_.mozrunner/datareporting/aborted-session-ping: {"operation":"open","path":"/builds/worker/workspace/build/tmpMMO3j_.mozrunner/datareporting/aborted-session-ping","unixErrno":2}
[task 2020-02-21T23:40:52.627Z] 23:40:52     INFO -  1582328452622	Toolkit.Telemetry	TRACE	TelemetryStorage::loadAbortedSessionPing - no such file
[task 2020-02-21T23:40:52.627Z] 23:40:52     INFO -  1582328452622	Toolkit.Telemetry	TRACE	TelemetryController::checkAbortedSessionPing - found aborted-session ping: false
[task 2020-02-21T23:40:52.629Z] 23:40:52     INFO -  1582328452622	Toolkit.Telemetry	TRACE	TelemetrySession::_saveAbortedSessionPing
[task 2020-02-21T23:40:52.631Z] 23:40:52     INFO -  1582328452622	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: aborted-session, clearSubsession: false
[task 2020-02-21T23:40:52.632Z] 23:40:52     INFO -  1582328452623	Toolkit.Telemetry	TRACE	TelemetrySession::assemblePayloadWithMeasurements - reason: aborted-session, submitting subsession data: true
[task 2020-02-21T23:40:52.635Z] 23:40:52     INFO -  1582328452625	Toolkit.Telemetry	TRACE	TelemetryController::saveAbortedSessionPing
[task 2020-02-21T23:40:52.635Z] 23:40:52     INFO -  1582328452626	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
[task 2020-02-21T23:40:52.639Z] 23:40:52     INFO -  1582328452631	Toolkit.Telemetry	TRACE	TelemetryStorage::saveAbortedSessionPing - ping path: /builds/worker/workspace/build/tmpMMO3j_.mozrunner/datareporting/aborted-session-ping
[task 2020-02-21T23:40:52.639Z] 23:40:52     INFO -  1582328452634	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2020-02-21T23:40:52.639Z] 23:40:52     INFO -  1582328452634	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /builds/worker/workspace/build/tmpMMO3j_.mozrunner/datareporting/aborted-session-ping
[task 2020-02-21T23:40:52.640Z] 23:40:52     INFO -  1582328452637	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange
[task 2020-02-21T23:40:52.650Z] 23:40:52     INFO -  1582328452637	Toolkit.Telemetry	TRACE	TelemetryScheduler::init
[task 2020-02-21T23:40:52.650Z] 23:40:52     INFO -  1582328452637	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
[task 2020-02-21T23:40:52.651Z] 23:40:52     INFO -  1582328452637	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Fri Feb 21 2020 23:45:52 GMT+0000 (Coordinated Universal Time)
[task 2020-02-21T23:40:52.651Z] 23:40:52     INFO -  1582328452638	Toolkit.Telemetry	TRACE	TelemetryStorage::cleanArchiveTask
[task 2020-02-21T23:40:52.651Z] 23:40:52     INFO -  1582328452638	Toolkit.Telemetry	TRACE	TelemetryStorage::removeFHRDatabase
[task 2020-02-21T23:40:52.666Z] 23:40:52     INFO -  1582328452659	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Starting up.
[task 2020-02-21T23:40:52.666Z] 23:40:52     INFO -  1582328452660	Toolkit.Telemetry	TRACE	TelemetryPrioPing::Starting up.
[task 2020-02-21T23:40:52.667Z] 23:40:52     INFO -  1582328452662	Toolkit.Telemetry	TRACE	TelemetryStorage::_purgeOldPings
[task 2020-02-21T23:40:52.682Z] 23:40:52     INFO -  1582328452676	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanArchive
[task 2020-02-21T23:40:52.690Z] 23:40:52     INFO -  1582328452686	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanArchive - checking in subdir: /builds/worker/workspace/build/tmpMMO3j_.mozrunner/datareporting/archived/2020-02
[task 2020-02-21T23:40:52.705Z] 23:40:52     INFO -  1582328452694	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforceArchiveQuota
[task 2020-02-21T23:40:52.747Z] 23:40:52     INFO -  1582328452744	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2020-02-21T23:40:52.748Z] 23:40:52     INFO -  1582328452745	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2020-02-21T23:40:52.823Z] 23:40:52     INFO -  1582328452814	Marionette	TRACE	All scripts recorded.
[task 2020-02-21T23:40:52.831Z] 23:40:52     INFO -  1582328452827	Marionette	INFO	Listening on port 2828
[task 2020-02-21T23:40:52.831Z] 23:40:52     INFO -  1582328452827	Marionette	DEBUG	Marionette is listening
[task 2020-02-21T23:40:52.846Z] 23:40:52     INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2020-02-21T23:40:52.850Z] 23:40:52     INFO -  1582328452848	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:54040
[task 2020-02-21T23:40:52.851Z] 23:40:52     INFO -  1582328452849	Marionette	DEBUG	Closed connection 0
[task 2020-02-21T23:40:52.851Z] 23:40:52     INFO -  1582328452849	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:54042
[task 2020-02-21T23:40:52.852Z] 23:40:52     INFO -  1582328452851	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-02-21T23:40:52.868Z] 23:40:52     INFO -  1582328452855	Marionette	TRACE	[9] Frame script loaded
[task 2020-02-21T23:40:52.868Z] 23:40:52     INFO -  1582328452855	Marionette	TRACE	[9] Frame script registered
[task 2020-02-21T23:40:52.869Z] 23:40:52     INFO -  1582328452857	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"317fed80-6a20-465e-9212-d3b30b947e90","capabilities":{"browserName":"firefox","browserVersion":"74.0" ... ld/tmpMMO3j_.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-02-21T23:40:52.870Z] 23:40:52     INFO -  1582328452860	Marionette	DEBUG	1 -> [0,2,"Marionette:SetContext",{"value":"content"}]
[task 2020-02-21T23:40:52.870Z] 23:40:52     INFO -  1582328452860	Marionette	DEBUG	1 <- [1,2,null,{"value":null}]
[task 2020-02-21T23:40:52.871Z] 23:40:52     INFO -  1582328452864	Marionette	DEBUG	1 -> [0,3,"Marionette:GetContext",{}]
[task 2020-02-21T23:40:52.871Z] 23:40:52     INFO -  1582328452864	Marionette	DEBUG	1 <- [1,3,null,{"value":"content"}]
[task 2020-02-21T23:40:52.873Z] 23:40:52     INFO -  1582328452865	Marionette	DEBUG	1 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-02-21T23:40:52.873Z] 23:40:52     INFO -  1582328452865	Marionette	DEBUG	1 <- [1,4,null,{"value":null}]
[task 2020-02-21T23:40:52.873Z] 23:40:52     INFO -  1582328452866	Marionette	DEBUG	1 -> [0,5,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-02-21T23:40:52.921Z] 23:40:52     INFO -  1582328452918	Marionette	DEBUG	1 <- [1,5,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd368dZ50nal8yp50/ACeihfqoRZze23vv/HJ2DHGc2Js+s ... ITAAIAAABAYAJAAAAAAAhMAAgAAAAAgQkAAQAAACAwASAAAAAABCYABAAAAIDABIAAAAAAEJgAEAAAAAACEwACAAAAQGD/D6mO8Tkx8MwnAAAAAElFTkSuQmCC"}]
[task 2020-02-21T23:40:52.961Z] 23:40:52     INFO -  1582328452960	Marionette	DEBUG	1 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2020-02-21T23:40:52.961Z] 23:40:52     INFO -  1582328452960	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2020-02-21T23:40:52.963Z] 23:40:52     INFO -  1582328452962	Marionette	DEBUG	1 -> [0,7,"Marionette:GetContext",{}]
[task 2020-02-21T23:40:52.966Z] 23:40:52     INFO -  1582328452962	Marionette	DEBUG	1 <- [1,7,null,{"value":"content"}]
[task 2020-02-21T23:40:52.966Z] 23:40:52     INFO -  1582328452964	Marionette	DEBUG	1 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2020-02-21T23:40:52.966Z] 23:40:52     INFO -  1582328452964	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2020-02-21T23:40:52.970Z] 23:40:52     INFO -  1582328452967	Marionette	DEBUG	1 -> [0,9,"WebDriver:GetPageSource",{}]
[task 2020-02-21T23:40:52.970Z] 23:40:52     INFO -  1582328452969	Marionette	DEBUG	1 <- [1,9,null,{"value":"<html xmlns=\"http://www.w3.org/1999/xhtml\" dir=\"ltr\" lang=\"en-US\">\n<head>\n  <meta http-equiv=\"Co ... "about:webrtc\">about:webrtc</a></li><li><a href=\"about:welcome\">about:welcome</a></li></ul>\n  </div>\n</body>\n</html>"}]
[task 2020-02-21T23:40:52.975Z] 23:40:52     INFO -  1582328452970	Marionette	DEBUG	1 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2020-02-21T23:40:53.012Z] 23:40:53     INFO - TEST-UNEXPECTED-FAIL | telemetry/marionette/tests/client/test_search_counts_across_sessions.py TestSearchCounts.test_search_counts | AssertionError: u'b4a32c5d-7e35-4ff0-acb7-2f1651584816' is not None
[task 2020-02-21T23:40:53.012Z] 23:40:53     INFO - Traceback (most recent call last):
[task 2020-02-21T23:40:53.012Z] 23:40:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2020-02-21T23:40:53.013Z] 23:40:53     INFO -     testMethod()
[task 2020-02-21T23:40:53.013Z] 23:40:53     INFO -   File "/builds/worker/workspace/build/tests/telemetry/marionette/tests/client/test_search_counts_across_sessions.py", line 88, in test_search_counts
[task 2020-02-21T23:40:53.013Z] 23:40:53     INFO -     self.assertIsNone(ping1_info["previousSubsessionId"])
[task 2020-02-21T23:40:53.013Z] 23:40:53     INFO - TEST-INFO took 9479ms

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 2

Platform breakdown:

• linux1804-64-devedition: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform breakdown:

• macosx1014-64-shippable: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-03-09&endday=2020-03-15&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 9

[Intermittent Failures Robot]

14 failures in 5582 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 14

Platform breakdown:

• macosx1014-64: 2
• windows10-64-mingwclang: 2
• windows7-32-mingwclang: 2
• linux1804-64-devedition: 1
• macosx1014-64-devedition: 2
• macosx1014-64-shippable: 4
• windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 8
• mozilla-release: 3
• autoland: 1
• try: 1

Platform breakdown:

• linux1804-64-asan: 1
• windows7-32: 1
• linux1804-64: 1
• windows10-64: 2
• linux1804-64-devedition: 1
• windows7-32-devedition: 1
• macosx1014-64-devedition: 1
• linux1804-64-shippable: 1
• windows7-32-mingwclang: 1
• windows7-32-shippable: 1
• windows10-64-shippable: 1
• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• mozilla-central: 2
• autoland: 1
• try: 1

Platform breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-05-04&endday=2020-05-10&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 13

[Intermittent Failures Robot]

24 failures in 4727 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 11
• mozilla-release: 5
• autoland: 7
• try: 1

Platform breakdown:

• windows7-32-mingwclang: 4
• windows10-64-shippable: 1
• windows7-32-shippable: 5
• linux1804-64-shippable: 2
• macosx1014-64-shippable: 2
• windows7-32: 9
• windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 14

[Cristina Coroiu [:ccoroiu]]

Started retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Windows%2C7%2Cdebug%2CTelemetry%2Ctests%2Ctest-windows7-32%2Fdebug-telemetry-tests-client-e10s%2Ctt%28c%29&tochange=3ff3c6dc6771b7f916f5f23e47c6029d934ed546&fromchange=c127b56cb97a4047a1b1b5f2c478a058c70f1f34&selectedTaskRun=Camn5r0kRxCiREWcJOYw-Q-0

Yura, is any chance that your push https://hg.mozilla.org/integration/autoland/rev/d05e4b2ab6d00a618e2931d99797dc369b568397 could cause this failures? Can you please take a look? Thank you

Comment 15

[Yura Zenevich [:yzen] (please use "needinfo")]

(In reply to Cristina Coroiu [:ccoroiu] from comment #14)

Started retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Windows%2C7%2Cdebug%2CTelemetry%2Ctests%2Ctest-windows7-32%2Fdebug-telemetry-tests-client-e10s%2Ctt%28c%29&tochange=3ff3c6dc6771b7f916f5f23e47c6029d934ed546&fromchange=c127b56cb97a4047a1b1b5f2c478a058c70f1f34&selectedTaskRun=Camn5r0kRxCiREWcJOYw-Q-0

Yura, is any chance that your push https://hg.mozilla.org/integration/autoland/rev/d05e4b2ab6d00a618e2931d99797dc369b568397 could cause this failures? Can you please take a look? Thank you

Hi Christina, If I understand correctly, this is on autoland (Nightly). If so, I do not think the patch should've changed anything because the flag for preference there did not change the behaviour on Nightly (just changed the behaviour on early beta and dev edition to be the same as nightly). The feature that the flag enables was already active on Nightly for weeks.

Comment 16

[Yura Zenevich [:yzen] (please use "needinfo")]

Just to clarify if this is a new issue problem that started on beta, dev edition, then perhaps it could be it.

Comment 17

[Intermittent Failures Robot]

20 failures in 5458 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• mozilla-central: 3
• try: 1

Platform breakdown:

• windows7-32: 16
• windows7-32-shippable: 1
• windows10-64-shippable: 1
• windows7-32-mingwclang: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 18

[Cristina Coroiu [:ccoroiu]]

Hi Yura,
Thank you for looking.
Yes, you understood this correctly, the retriggers were from autoland. All the failures are from autoland, mozilla-central and try.
We'll continue investigating.

Comment 19

[Intermittent Failures Robot]

13 failures in 4949 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• try: 6
• mozilla-central: 2

Platform breakdown:

• windows7-32: 12
• windows7-32-mingwclang: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-06-01&endday=2020-06-07&tree=all

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• mozilla-beta: 1

Platform breakdown:

• windows7-32: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1608807&startday=2020-06-08&endday=2020-06-14&tree=all

Comment 21

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

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

Comment 22

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

New occurrence: https://treeherder.mozilla.org/logviewer?job_id=336975682&repo=try

Comment 23

[Natalia Csoregi [:nataliaCs]]

This has a very high frequency on Beta: https://treeherder.mozilla.org/jobs?repo=mozilla-beta&group_state=expanded&collapsedPushes=842382&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=windows%2C10%2Cx64%2Casan%2Ctelemetry%2Ctests%2Ctest-windows10-64-asan%2Fopt-telemetry-tests-client-e10s%2Cc&fromchange=842785ce363f1590da22bc3213775f4cdf8d9299&selectedTaskRun=RgdBLMi3QVmZp7S1XGa_2w.0

Chris, could you take a look please?
Thank you.

Comment 24

[Chris H-C :chutten]

Last change to this test was last October with bug 1644515.

The failure as described suggests that there is another subsession happening in this test. Likely an "environment-change"... oh look there's one

And why was that. We disabled Normandy in bug 1579840 so it can't be experiments... oh, wait, I'm wrong. [task 2021-04-20T20:10:32.711Z] 20:10:32 INFO - 1618949432711 Toolkit.Telemetry TRACE TelemetryEnvironment::setExperimentActive - id: default-upgradeDialog, branch: upgradeDialog-defaultEnabled

Let's see if Experimenter has anything on this experiment. No? Weird.

Oh, Normandy's not the only one in town that can set experiments active. Nimbus does it too. Nimbus means I summon... k88hudson to tell me how to prevent Nimbus experiments from running in automation.

Comment 25

[Raphael Aurich [:raphael] UTC+01:00]

Reading your comment made my morning, Chutten. 😁 Thank you for looking into this!

Any idea why the failure rate is so high on Beta but not on Nightly?

Comment 26

[Chris H-C :chutten]

My guess is that the experiment (actually "a default") is targeting Beta specifically. Lemme ni?andreio who might have some information about this, too.

Comment 27

[Andrei Oprea [:andreio]]

Yes, you can see everything that's live here in remote settings. They are not exactly experiments, they are rollouts turning on some features but data is recorded in the experiments field. This was added in bug 1701034.

Comment 28

[Chris H-C :chutten]

I presume Nimbus isn't particularly interested in rolling out to or experimenting on these clients in automation. How should we disable it?

Comment 29

[Andrei Oprea [:andreio]]

By turning off Normandy ("app.shield.optoutstudies.enabled") or just our data fetch pipeline ("messaging-system.rsexperimentloader.enabled").

Comment 30

[Chris H-C :chutten]

Oh, app.normandy.enabled doesn't disable Normandy? That's what we used in bug 1641571.

Welp, at least we have a task to undertake.

Comment 31

[Chris H-C :chutten]

Attachment: Bug 1608807 - Disable more experiments in tt(c) r?raphael!

Comment 33

[Intermittent Failures Robot]

34 failures in 3224 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #33 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• try: 17
• mozilla-beta: 17

Platform and build breakdown:

• windows10-64: 16
  • asan: 16
• linux1804-64-devedition: 4
  • opt: 4
• linux1804-64-shippable: 3
  • opt: 3
• macosx1015-64-shippable-qr: 6
  • opt: 6
• linux1804-64-asan: 2
  • opt: 2
• linux1804-64: 2
  • debug: 2
• windows10-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1608807&startday=2021-04-19&endday=2021-04-25&tree=all

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fcf92e329cf9
Disable more experiments in tt(c) r=raphael

Comment 36

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/fcf92e329cf9

Comment 37

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/releases/mozilla-beta/rev/0f5aceb0adf6

Comment 39

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 8

Platform and build breakdown:

• windows10-64: 8
  • asan: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1608807&startday=2021-04-26&endday=2021-05-02&tree=all