1174766 - Prevent loss of gecko.log when restarting gecko process with marionette

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Chris Manchester (limited bugmail, email directly)]

When debugging a problem with marionette, the first thing I usually do is push to try and retrigger a lot with lots of logging enabled. To figure out what's going on in the server, there's really not much to go on without the log from the gecko process. We dump 'gecko.log' at the end of each run, but this is overwritten after each restart, so that log rarely contains the relevant info.

I have a quick patch to make a fresh log for after each restart and upload them to blobber. It's a lot to upload for every single run, but I think it's worth it (a quick conversation on irc indicates I wouldn't be the only one to find this useful).

Comment 1

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

Why not appending to the same file after a restart? We would only have to open the file with a different mode. Using different files would be different from our internal logging.

Comment 2

[Chris Manchester (limited bugmail, email directly)]

We end up with 12 logs on a Mn run, which is a lot to sift through. I'll see about concatenating.

Comment 3

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.

Comment 4

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: Bug 1174766 - Specify gecko.log for upload in Mn tests.

Bug 1174766 - Specify gecko.log for upload in Mn tests.

Comment 5

[Chris Manchester (limited bugmail, email directly)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e2845da3a9e5

Comment 6

[Andreas Tolfsen ❲:ato❳]

For data integrity reasons I think rotating the file would be better, but maybe we can consider doing that when the Mn job has been split up (see bug 1174491, especially comments 3 and 4).  Not loosing data is already better than status quo so I’ll have a look at this review later today.

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Yeah, a monolithic gecko.log is decent for debugging because I can just grep through for the filename of the test I care about, and was only a little harder to get working.

Comment 8

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8622684 [details]
MozReview Request: Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

https://reviewboard.mozilla.org/r/11427/#review9991

Ship It!

Comment 9

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8622685 [details]
MozReview Request: Bug 1174766 - Specify gecko.log for upload in Mn tests.

https://reviewboard.mozilla.org/r/11431/#review9995

Ship It!

Comment 10

[Chris Manchester (limited bugmail, email directly)]

https://hg.mozilla.org/build/mozharness/rev/d3632a67fe12

Comment 11

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/101932a675a4

Comment 12

[Chris Manchester (limited bugmail, email directly)]

Backed out for winXP failures in https://hg.mozilla.org/integration/mozilla-inbound/rev/8a25cd69c4ae

Comment 13

[Chris Manchester (limited bugmail, email directly)]

(In reply to Chris Manchester [:chmanchester] from comment #12)
> Backed out for winXP failures in
> https://hg.mozilla.org/integration/mozilla-inbound/rev/8a25cd69c4ae

A prior test using the mozrunner initiated restart must be interfering with the profile, because we have: "[GFX1-]: Failed to create the graphics startup lockfile.", which is just an attempt to do something in the profile directory. 

This is sort of awful. The relevant difference with this patch must be that we aren't hitting the retry loop for deleting the old log file, which was apparently providing critical time between tests.

I'm testing a patch to just use a new profile for this test that I can hopefully land, but this is a potentially significant hazard.

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Actually we're having trouble accessing the profile when restarting the browser with mozrunner _after_ restarting from within Firefox. This makes a bit more sense and is bit less disconcerting.

Comment 15

[Chris Manchester (limited bugmail, email directly)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=21927f4aaeeb

Comment 16

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8622684 [details]
MozReview Request: Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

Comment 17

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: Bug 1174766 - Modify test_profile_management to use a clean profile to avoid contention on windows.;r=ato

Bug 1174766 - Modify test_profile_management to use a clean profile to avoid contention on windows.;r=ato

Comment 18

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8625195 [details]
MozReview Request: Bug 1174766 - Modify test_profile_management to use a clean profile to avoid contention on windows.;r=ato

https://reviewboard.mozilla.org/r/11807/#review10263

Ship It!

Comment 19

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8622684 [details]
MozReview Request: Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

https://reviewboard.mozilla.org/r/11427/#review10371

::: testing/marionette/driver/marionette_driver/geckoinstance.py:63
(Diff revision 2)
> +                os.remove(self.gecko_log)

This will raise if `self.gecko_log` is a directory.  Is this what we want?

::: testing/marionette/driver/marionette_driver/geckoinstance.py:61
(Diff revision 2)
> +            gecko_log = os.path.realpath(gecko_log)

To not mangle the user input I feel `os.path.normpath` is more appropriate here.

Comment 20

[Andreas Tolfsen ❲:ato❳]

https://reviewboard.mozilla.org/r/11807/#review10373

Ship It!

Comment 21

[Chris Manchester (limited bugmail, email directly)]

https://reviewboard.mozilla.org/r/11427/#review10385

::: testing/marionette/driver/marionette_driver/geckoinstance.py:63
(Diff revision 2)
> +                os.remove(self.gecko_log)

This should be "gecko_log", it's never a directory because we convert it in the isdir branch above.

::: testing/marionette/driver/marionette_driver/geckoinstance.py:61
(Diff revision 2)
> +            gecko_log = os.path.realpath(gecko_log)

This is a direct port of the old code.

Comment 22

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8622684 [details]
MozReview Request: Bug 1174766 - Append to gecko logfile after marionette restarts the browser rather than removing the old file every time.;r=ato

https://reviewboard.mozilla.org/r/11427/#review10387

That’s good enough for me!

Comment 23

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d2d535a3fdbf
https://hg.mozilla.org/integration/mozilla-inbound/rev/585f52ceab5c

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d2d535a3fdbf
https://hg.mozilla.org/mozilla-central/rev/585f52ceab5c