1411913 - Enable Marionette trace log for mochitest/reftest by default

Status: RESOLVED FIXED

(Testing :: General, enhancement)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

To be able to better investigate the problems like on bug 1397201 we should enable the Marionette trace logs. As stated over on that bug it should not give much overhead given that Marionette is only used to install an extension.

Right now we miss detailed information during the startup phase, and the patch which I will upload soon will enable those log lines.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

The following output would be visible during each startup of Firefox (log lines from Firefox removed):

GECKO(24713) | 1509015223093	Marionette	DEBUG	Received observer notification "profile-after-change"
GECKO(24713) | 1509015223254	Marionette	DEBUG	Received observer notification "command-line-startup"
GECKO(24713) | 1509015223254	Marionette	INFO	Enabled via --marionette
GECKO(24713) | 1509015225109	Marionette	DEBUG	Received observer notification "sessionstore-windows-restored"
GECKO(24713) | 1509015226020	Marionette	DEBUG	New connections are accepted
GECKO(24713) | 1509015226021	Marionette	INFO	Listening on port 2828
GECKO(24713) | 1509015226042	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:58336
GECKO(24713) | 1509015226061	Marionette	DEBUG	Closed connection 0
GECKO(24713) | 1509015226064	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:58337
GECKO(24713) | 1509015226081	Marionette	TRACE	1 -> [0,1,"newSession",{}]
GECKO(24713) | 1509015226125	Marionette	DEBUG	Register listener.js for window 6
GECKO(24713) | 1509015226170	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"7f19ca30-d20f-be4c-9bf6-7d77efd3f6ec","capabilities":{}}]
GECKO(24713) | 1509015226224	Marionette	TRACE	1 -> [0,2,"addon:install",{"path":"/var/folders/4k/sf4gz5fn3kl9hr3nd7pzbvhc0000gn/T/tmpjp66Yq.zip","temporary":false}]
GECKO(24713) | 1509015226436	Marionette	TRACE	1 <- [1,2,null,{"value":"[e-mail]"}]
GECKO(24713) | 1509015226517	Marionette	TRACE	1 -> [0,3,"addon:install",{"path":"/var/folders/4k/sf4gz5fn3kl9hr3nd7pzbvhc0000gn/T/tmp0pALHS.zip","temporary":false}]
GECKO(24713) | 1509015226670	Marionette	TRACE	1 <- [1,3,null,{"value":"[e-mail]"}]
GECKO(24713) | 1509015226691	Marionette	TRACE	1 -> [0,4,"getContext",{}]
GECKO(24713) | 1509015226692	Marionette	TRACE	1 <- [1,4,null,{"value":"content"}]
GECKO(24713) | 1509015226709	Marionette	TRACE	1 -> [0,5,"setContext",{"value":"chrome"}]
GECKO(24713) | 1509015226710	Marionette	TRACE	1 <- [1,5,null,{}]
GECKO(24713) | 1509015226719	Marionette	TRACE	1 -> [0,6,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"testUrl":"http://mochi.test:8888/redirect.html","flavor":"a11y"}],"filename":"runtests.py","script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, v. 2.0. If a copy of the MPL was not distr ...  which flavor and url to load.\nlet ev = new CustomEvent('mochitest-load', {'detail': [flavor, url]});\nwin.dispatchEvent(ev);\n","sandbox":"default","line":1716}]
GECKO(24713) | [24713, Main Thread] WARNING: Could not get disk status from nsIDiskSpaceWatcher: file /builds/worker/workspace/build/src/uriloader/prefetch/nsOfflineCacheUpdateService.cpp, line 283
GECKO(24713) | 1509015226755	Marionette	TRACE	1 <- [1,6,null,{"value":null}]
GECKO(24713) | 1509015226820	Marionette	TRACE	1 -> [0,7,"setContext",{"value":"content"}]
GECKO(24713) | 1509015226821	Marionette	TRACE	1 <- [1,7,null,{}]
GECKO(24713) | 1509015226860	Marionette	TRACE	1 -> [0,8,"deleteSession",{}]

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1411913 - Enable Marionette trace log for mochitest/reftest by default.

Review commit: https://reviewboard.mozilla.org/r/193330/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/193330/

Comment 3

[Joel Maher ( :jmaher ) (UTC -8) (PTO'ish until July 5)]

Comment on attachment 8922272 [details]
Bug 1411913 - Enable Marionette trace log for mochitest/reftest by default.

https://reviewboard.mozilla.org/r/193330/#review198560

please ensure this doesn't break Android or Autophone (check with :bc)

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Looks like I missed Android. So I triggered some new jobs in the same try build. Regarding autophone I'm not sure how this is involved here. Is it related to Mochitests and Reftests? Bob, would be great if you could give me some feedback.

Comment 5

[Bob Clary [:bc] (inactive)]

Autophone does run some reftest based tests (crash tests and some ogg/webm tests) as well as mochitest based tests, but I don't know how marionette is used underneath the hood. I submitted your try build to autophone for the relevant tests and we should see the results at <https://treeherder.mozilla.org/#/jobs?repo=try&revision=747dba951c77&filter-searchStr=autophone>. I'll loop back when those complete.

Comment 6

[Bob Clary [:bc] (inactive)]

We still have some pending but both mochitests and reftests have completed and I haven't seen issues with this. I do see marionette messages in the log cat. All seem well.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fe8fdf1bd074
Enable Marionette trace log for mochitest/reftest by default. r=jmaher

Comment 8

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

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