Skip to content
This repository has been archived by the owner on Oct 14, 2020. It is now read-only.

Nightly is crashing (possible only on Linux) somewhere in relation to onShutdown / onEndStudy when an expired study is encountered #254

Closed
motin opened this issue Jul 30, 2018 · 4 comments
Closed

Nightly is crashing (possible only on Linux) somewhere in relation to onShutdown / onEndStudy when an expired study is encountered #254

motin opened this issue Jul 30, 2018 · 4 comments

Comments

@motin
Copy link
Contributor

motin commented Jul 30, 2018

Nightly is crashing (possible only on Linux) somewhere in relation to onShutdown / onEndStudy when an expired study is encountered. This leads to failing tests and cryptic WebDriver errors in Circle CI.

Geckodriver logs for the tests 1) setup of an already expired study should result in endStudy('expired') reports A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down, see below:

1532933762828	webdriver::server	DEBUG	-> POST /session/687d4340-59ad-464c-8d4a-017f8f94c2c4/moz/addon/install {"path":"/home/circleci/checkout/dist/button_icon_preference_-_shield_study_example-2.0.0.zip","temporary":true}
1532933762828	webdriver::server	DEBUG	-> POST /session/687d4340-59ad-464c-8d4a-017f8f94c2c4/moz/context {"context":"chrome"}
1532933762831	Marionette	TRACE	0 -> [0,2,"Addon:Install",{"path":"/home/circleci/checkout/dist/button_icon_preference_-_shield_study_example-2.0.0.zip","temporary":true}]
console.debug: shield-study-utils: 
  loading web extension experiment study/api.js
console.debug: shield-study-utils: 
  constructed!
console.debug: shield-study-utils: 
  wanting guard
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  adding schemas [object Object]
console.debug: shield-study-utils: 
  Ajv schemas
Array
    - 0 = http://json-schema.org/draft-07/schema
    - 1 = http://json-schema.org/draft-04/schema
    - 2 = NullableString
    - 3 = NullableInteger
    - 4 = NullableNumber
    - 5 = studyTypesEnum
    - 6 = weightedVariationObject
    - 7 = weightedVariationsArray
    - 8 = anEndingRequest
    - 9 = onEndStudyResponse
    - 10 = studyInfoObject
    - 11 = studySetup
    - 12 = telemetryPayload
    - 13 = searchTelemetryQuery
    - 14 = anEndingAnswer
    - length = 15
1532933763166	Marionette	TRACE	0 <- [1,2,null,{"value":"[email protected]"}]
1532933763176	webdriver::server	DEBUG	<- 200 OK {"value":"[email protected]"}
1532933763181	Marionette	TRACE	0 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
1532933763182	Marionette	TRACE	0 <- [1,3,null,{"value":null}]
1532933763184	webdriver::server	DEBUG	<- 200 OK {"value": null}
console.debug: shield-study-utils: 
  setting up! -- {"activeExperimentName":"[email protected]","endings":{"user-disable":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=user-disable"],"category":null,"exacturls":null,"fullname":null},"ineligible":{"baseUrls":[],"category":null,"exacturls":null,"fullname":null},"expired":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=expired"],"category":null,"exacturls":null,"fullname":null},"used-often":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=used-often"],"category":"ended-positive","exacturls":null,"fullname":null},"a-non-url-opening-ending":{"baseUrls":[],"category":"ended-neutral","exacturls":null,"fullname":null},"introduction-leave-study":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=introduction-leave-study"],"category":"ended-negative","exacturls":null,"fullname":null}},"expire":{"days":14},"studyType":"shield","telemetry":{"removeTestingFlag":false,"send":true},"testing":{"expired":null,"firstRunTimestamp":0,"variationName":"kittens"},"weightedVariations":[{"name":"kittens","weight":1.5},{"name":"puppers","weight":1.5},{"name":"lizard","weight":1}],"allowEnroll":true}
console.debug: shield-study-utils: 
  about to guard
  studySetup
Object
    - activeExperimentName = [email protected]
    - endings = {"user-disable":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=user-disable"],"category":null,"exacturls":null,"fullname":null},"ineligible":{"baseUrls":[],"category":null,"exacturls":null,"fullname":null},"expired":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=expired"],"category":null,"exacturls":null,"fullname":null},"used-often":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=used-often"],"category":"ended-positive","exacturls":null,"fullname":null},"a-non-url-opening-ending":{"baseUrls":[],"category":"ended-neutral","exacturls":null,"fullname":null},"introduction-leave-study":{"baseUrls":["https://qsurvey.mozilla.com/s3/Shield-Study-Example-Survey/?reason=introduction-leave-study"],"category":"ended-negative","exacturls":null,"fullname":null}}
    - expire = {"days":14}
    - studyType = shield
    - telemetry = {"removeTestingFlag":false,"send":true}
    - testing = {"expired":null,"firstRunTimestamp":0,"variationName":"kittens"}
    - weightedVariations = Array [{"name":"kittens","weight":1.5},{"name":"puppers","weight":1.5},{"name":"lizard","weight":1}]
    - allowEnroll = true
console.debug: shield-study-utils: 
  setting up: variation kittens
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
console.debug: shield-study-utils: 
  encountered already expired study
console.debug: shield-study-utils: 
  called endStudy anEndingAlias
console.debug: shield-study-utils: 
  endStudy expired
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
console.debug: shield-study-utils: 
  unmarking TelemetryEnvironment
  [email protected]
  kittens
console.debug: shield-study-utils: 
  telemetry in:  shield-study {"study_state":"expired","study_state_fullname":"expired"}
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
console.debug: shield-study-utils: 
  telemetry INFO: {"activeExperimentName":"[email protected]","isFirstRun":false,"firstRunTimestamp":0,"variation":{"name":"kittens","weight":1.5},"shieldId":"","delayInMinutes":0}
console.debug: shield-study-utils: 
  telemetry: {"version":3,"study_name":"[email protected]","branch":"kittens","addon_version":"2.0.0","shield_version":"5.0.4","type":"shield-study","data":{"study_state":"expired","study_state_fullname":"expired"},"testing":true}
console.debug: shield-study-utils: 
  telemetry in:  shield-study {"study_state":"exit"}
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
console.debug: shield-study-utils: 
  telemetry INFO: {"activeExperimentName":"[email protected]","isFirstRun":false,"firstRunTimestamp":0,"variation":{"name":"kittens","weight":1.5},"shieldId":"","delayInMinutes":0}
console.debug: shield-study-utils: 
  telemetry: {"version":3,"study_name":"[email protected]","branch":"kittens","addon_version":"2.0.0","shield_version":"5.0.4","type":"shield-study","data":{"study_state":"exit"},"testing":true}
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
console.debug: shield-study-utils: 
  getting info
console.debug: shield-study-utils: 
  getVariation: {"name":"kittens","weight":1.5}
console.debug: shield-study-utils: 
  about to guard
  studyInfoObject
Object
    - activeExperimentName = [email protected]
    - isFirstRun = false
    - firstRunTimestamp = 0
    - variation = {"name":"kittens","weight":1.5}
    - shieldId = 
    - delayInMinutes = 0
1532933763403	Marionette	DEBUG	[4294967300] Frame script loaded
1532933763414	Marionette	DEBUG	[4294967300] Frame script registered
console.debug: shield-study-utils: 
  possible uninstalling
  ADDON_UNINSTALL
console.debug: shield-study-utils: 
  definitely uninstall | disable
  ADDON_UNINSTALL
console.debug: shield-study-utils: 
  endStudy, already ending!
1532933763470	Marionette	DEBUG	[6442450945] Frame script loaded
1532933763476	Marionette	DEBUG	[6442450945] Frame script registered
1532933764419	Marionette	DEBUG	[21] Frame script loaded
1532933764420	Marionette	DEBUG	[21] Frame script registered
A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
1532933764568	Marionette	DEBUG	Closed connection 0
1532933765179	webdriver::server	DEBUG	-> POST /session/687d4340-59ad-464c-8d4a-017f8f94c2c4/moz/context {"context":"chrome"}
1532933765180	webdriver::server	DEBUG	Deleting session
1532933765395	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
1532933765396	Marionette	DEBUG	Resetting recommended pref app.update.disabledForTesting
1532933765396	Marionette	DEBUG	Resetting recommended pref security.turn_off_all_security_so_that_viruses_can_take_over_this_computer
1532933765396	Marionette	DEBUG	Resetting recommended pref apz.content_response_timeout
1532933765396	Marionette	DEBUG	Resetting recommended pref browser.download.panel.shown
1532933765396	Marionette	DEBUG	Resetting recommended pref browser.pagethumbnails.capturing_disabled
1532933765396	Marionette	DEBUG	Resetting recommended pref browser.search.update
1532933765396	Marionette	DEBUG	Resetting recommended pref toolkit.cosmeticAnimations.enabled
1532933765397	Marionette	DEBUG	Resetting recommended pref browser.tabs.disableBackgroundZombification
1532933765397	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
1532933765397	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnOpen
1532933765398	Marionette	DEBUG	Resetting recommended pref browser.usedOnWindows10.introURL
1532933765398	Marionette	DEBUG	Resetting recommended pref browser.urlbar.suggest.searches
1532933765398	Marionette	DEBUG	Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
1532933765399	Marionette	DEBUG	Resetting recommended pref dom.disable_beforeunload
1532933765399	Marionette	DEBUG	Resetting recommended pref dom.disable_open_during_load
1532933765399	Marionette	DEBUG	Resetting recommended pref dom.file.createInChild
1532933765399	Marionette	DEBUG	Resetting recommended pref dom.max_chrome_script_run_time
1532933765399	Marionette	DEBUG	Resetting recommended pref dom.max_script_run_time
1532933765399	Marionette	DEBUG	Resetting recommended pref extensions.getAddons.cache.enabled
1532933765399	Marionette	DEBUG	Resetting recommended pref extensions.webservice.discoverURL
1532933765399	Marionette	DEBUG	Resetting recommended pref network.http.prompt-temp-redirect
1532933765400	Marionette	DEBUG	Resetting recommended pref network.http.speculative-parallel-limit
1532933765400	Marionette	DEBUG	Resetting recommended pref security.fileuri.strict_origin_policy
1532933765400	Marionette	DEBUG	Resetting recommended pref security.notification_enable_delay
1532933765400	Marionette	DEBUG	Resetting recommended pref signon.autofillForms
1532933765400	Marionette	DEBUG	Resetting recommended pref signon.rememberSignons
1532933765400	Marionette	INFO	Stopped listening on port 41148
1532933765400	Marionette	DEBUG	Remote service is inactive
1532933765581	geckodriver::marionette	DEBUG	Browser process stopped: exit code: 0
1532933765589	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to decode response from marionette","stacktrace":""}}
1532933765597	webdriver::server	DEBUG	-> DELETE /session/687d4340-59ad-464c-8d4a-017f8f94c2c4 
1532933765597	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"session not created","message":"Tried to run command without establishing a connection","stacktrace":""}}
@motin
Copy link
Contributor Author

motin commented Jul 30, 2018

@rhelmer This is intermittently failing our CI runs both in utils, the template repo and all shield studies based on the template. Could you advice us on how to get this resolved / debugged / reported properly?

@motin
Copy link
Contributor Author

motin commented Aug 31, 2018

With the latest nightly, our CI runs are now running without Nightly crashing. Will keep this under observation and if there are no new crashes, we can close this issue for now.

@rhelmer
Copy link

rhelmer commented Sep 6, 2018

@motin Sorry I missed this initially... I think as far as debugging in the future, using a "debug" build is probably the best bet, since this will give you more info on exactly where things are crashing.

You can build this yourself or you can download builds from e.g. https://treeherder.mozilla.org/#/jobs?repo=mozilla-central (the treeherder UI is a bit quirky, basically you'd look for "Linux Debug" then click the green "B", then "Job Details" will have a link to target.tar.bz2 which is the build that the Mozilla CI uploaded)

Hopefully it does not crop up again :)

@motin
Copy link
Contributor Author

motin commented Sep 10, 2018 •
edited
Loading

Closing this since CI runs are passing on Nightly consistently again.
Thanks @rhelmer, will let CI run debug builds in this crops up again, hopefully there is some way to get crash information dumped so that CI then can store that information as artifacts of the builds, available to further debug the cause of the crash.

@motin motin closed this as completed Sep 10, 2018
@motin motin mentioned this issue Sep 14, 2018
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rhelmer @motin