Discontinue Marionette server logging

RESOLVED FIXED in Firefox 56

Status

Testing
Marionette
RESOLVED FIXED
6 months ago
6 months ago

People

(Reporter: ato, Assigned: ato)

Tracking

Version 3
mozilla56
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox56 fixed)

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(5 attachments)

(Assignee)

Description

6 months ago
Marionette currently has interfaces that enable logs to be stored in the server.  This is no longer needed and we can remove the client APIs Marionette.get_logs and Marionette.log along with the server APIs.
(Assignee)

Updated

6 months ago
Assignee: nobody → ato
Status: NEW → ASSIGNED
(Assignee)

Updated

6 months ago
Depends on: 1368674
(Assignee)

Updated

6 months ago
Depends on: 1370871
(Assignee)

Updated

6 months ago
Duplicate of this bug: 1369102
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

6 months ago
Attachment #8875801 - Flags: review?(dburns)
Attachment #8875802 - Flags: review?(dburns)
Attachment #8875803 - Flags: review?(dburns)

Comment 5

6 months ago
mozreview-review
Comment on attachment 8875801 [details]
Bug 1370863 - Stop using Marionette.log API in harness;

https://reviewboard.mozilla.org/r/147208/#review151474
Attachment #8875801 - Flags: review?(dburns) → review+

Comment 6

6 months ago
mozreview-review
Comment on attachment 8875802 [details]
Bug 1370863 - Stop using Marionette.log API in external media tests;

https://reviewboard.mozilla.org/r/147210/#review151478

::: commit-message-39e63:1
(Diff revision 1)
> +Bug 1370863 - Remove Marionette.log API from client

Please can you flag someone from media so they are aware of the changes happening in their directory.
Attachment #8875802 - Flags: review?(dburns) → review+

Comment 7

6 months ago
mozreview-review
Comment on attachment 8875803 [details]
Bug 1370863 - Remove log and getLogs commands from Marionette;

https://reviewboard.mozilla.org/r/147212/#review151482
Attachment #8875803 - Flags: review?(dburns) → review+
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 13

6 months ago
mozreview-review
Comment on attachment 8876108 [details]
Bug 1370863 - Remove log() call from WPT Marionette executor;

https://reviewboard.mozilla.org/r/147536/#review151814
Attachment #8876108 - Flags: review?(james) → review+

Comment 14

6 months ago
mozreview-review
Comment on attachment 8876107 [details]
Bug 1370863 - Remove Marionette.log API from client;

https://reviewboard.mozilla.org/r/147534/#review152016
Attachment #8876107 - Flags: review?(dburns) → review+

Comment 15

6 months ago
mozreview-review
Comment on attachment 8875802 [details]
Bug 1370863 - Stop using Marionette.log API in external media tests;

https://reviewboard.mozilla.org/r/147210/#review152176

::: dom/media/test/external/external_media_tests/media_utils/youtube_puppeteer.py:172
(Diff revision 2)
>          if self._last_seen_player_state.player_ad_inactive:
>              return
>          ad_timeout = (self._search_ad_duration() or 30) + 5
>          wait = Wait(self, timeout=ad_timeout, interval=1)
>          try:
> -            self.marionette.log('process_ad: waiting {} s for ad'
> +            print('process_ad: waiting {}s for ad'.format(ad_timeout)

Missing closing )

Comment 16

6 months ago
mozreview-review
Comment on attachment 8875802 [details]
Bug 1370863 - Stop using Marionette.log API in external media tests;

https://reviewboard.mozilla.org/r/147210/#review152178

LGTM with closing ) added. Heads up that I'm likely to remove the external media tests soon as part of the media teams on going deprecation of them -- not relevant to this change but figured it may be good to know.
Attachment #8875802 - Flags: review?(bvandyk) → review+
(Assignee)

Comment 17

6 months ago
mozreview-review-reply
Comment on attachment 8875802 [details]
Bug 1370863 - Stop using Marionette.log API in external media tests;

https://reviewboard.mozilla.org/r/147210/#review152178

OK, thanks for the head’s up!
(Assignee)

Comment 18

6 months ago
mozreview-review-reply
Comment on attachment 8875802 [details]
Bug 1370863 - Stop using Marionette.log API in external media tests;

https://reviewboard.mozilla.org/r/147210/#review152176

> Missing closing )

Good catch.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 29

6 months ago
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/90b14cb85f51
Stop using Marionette.log API in harness; r=automatedtester
https://hg.mozilla.org/integration/autoland/rev/bb80abe6a298
Stop using Marionette.log API in external media tests; r=automatedtester,SingingTree
https://hg.mozilla.org/integration/autoland/rev/b0a081dfd577
Remove Marionette.log API from client; r=automatedtester
https://hg.mozilla.org/integration/autoland/rev/986d20fecd11
Remove log() call from WPT Marionette executor; r=jgraham
https://hg.mozilla.org/integration/autoland/rev/e4605e515ffd
Remove log and getLogs commands from Marionette; r=automatedtester
I had to back these out for frequent marionette e10s failures like https://treeherder.mozilla.org/logviewer.html#?job_id=106496933&repo=autoland


https://hg.mozilla.org/integration/autoland/rev/b4c6f63508ef61e275966d7c5ea853a045d472eb
Flags: needinfo?(ato)
Strange. Nothing in the gecko.log shows this specific test:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/6721d5196757fbf24bb86513bc1404c45b50b1c7a4c10f682b4b2b46e8073113906f9206641ad6e9d3d9cdb03d244c3d32e9f6a01939dc3bcdcc6e966ad6b6a7
(Assignee)

Comment 32

6 months ago
Judging by the log, it is able to find the element, but when the
clickElement command is called with its UUID, an error saying it is
unknown is returned.  Then a beforeunload event occurs, indicating that
the click did in fact work.

> 1497308323385	Marionette	TRACE	1042 -> [0,3,"findElement",{"using":"tag name","value":"a"}]
> 1497308323429	Marionette	TRACE	1042 <- [1,3,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"45265a8c-653c-4bdf-9d50-90124646c0e0","ELEMENT":"45265a8c-653c-4bdf-9d50-90124646c0e0"}}]
> 1497308323435	Marionette	TRACE	1042 -> [0,4,"clickElement",{"id":"45265a8c-653c-4bdf-9d50-90124646c0e0"}]
> 1497308324381	Marionette	TRACE	1042 <- [1,4,{"error":"javascript error","message":"Element reference not seen before: 45265a8c-653c-4bdf-9d50-90124646c0e0","stacktrace":""},null]
> 1497308324392	Marionette	DEBUG	Received DOM event "beforeunload" for "data:text/html;charset=utf-8,%3Ca%20href%3Dhttps%3A//127.0.0.1%3A49342/test.html%3Ehttps%20is%20the%20future%3C/a%3E"
Flags: needinfo?(ato)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 43

6 months ago
I haven’t been able to reproduce this locally.  Doing a try
run to see if that reveals the same issue after a rebase:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ee37349175ba
(Assignee)

Comment 44

6 months ago
This appears to reproduce rather consistently in automation on Linux
x64 debug.
Your try run doesn't show any test start and end log lines anymore in gecko.log which will make it unimpossible for us to analyze tracing logs. I filed bug 1374323, when I was looking at your try build, but didn't notice that it has been introduced by those changes.

It means we need a solution to still being able to log test start and end lines inside of gecko.log. Please do not land the patch as it is. Thanks.
Depends on: 1374323
Flags: needinfo?(ato)
(Assignee)

Comment 46

6 months ago
I think being needinfo’ed on my own bug is a first.

(In reply to Henrik Skupin (:whimboo) from comment #45)

> Your try run doesn't show any test start and end log lines anymore in
> gecko.log which will make it unimpossible for us to analyze tracing
> logs.
> 
> I filed bug 1374323, when I was looking at your try build, but didn't
> notice that it has been introduced by those changes.

I do agree it would be nice to have a complete, synthesised log
with everything included.  I don’t think it should necessarily be
considered a bug/regression that we don’t log the test name on the
server.

Since this is off topic for this bug, I will continue the discussion in
https://bugzilla.mozilla.org/show_bug.cgi?id=1374323 with some ideas for
addressing your concerns.

> It means we need a solution to still being able to log test start and
> end lines inside of gecko.log. Please do not land the patch as it
> is. Thanks.

I don’t see the lack of test name logging as a blocker for these
patches.
Flags: needinfo?(ato)
(In reply to Andreas Tolfsen ‹:ato› from comment #46)
> > It means we need a solution to still being able to log test start and
> > end lines inside of gecko.log. Please do not land the patch as it
> > is. Thanks.
> 
> I don’t see the lack of test name logging as a blocker for these
> patches.

As mentioned on the other bug, and I want to express it again, we loose ANY capability of analyzing failures as run in TC and reported to Treeherder. You won't be able to correlate lines in gecko.log with the equivalent logging lines in the normal log file.

As such I consider this a blocker.
(Assignee)

Comment 48

6 months ago
(In reply to Henrik Skupin (:whimboo) from comment #47)

> (In reply to Andreas Tolfsen ‹:ato› from comment #46)
> 
> > > It means we need a solution to still being able to log test start
> > > and end lines inside of gecko.log. Please do not land the patch as
> > > it is. Thanks.
> > 
> > I don’t see the lack of test name logging as a blocker for these
> > patches.
> 
> As mentioned on the other bug, and I want to express it again, we
> loose ANY capability of analyzing failures as run in TC and reported
> to Treeherder.  You won't be able to correlate lines in gecko.log with
> the equivalent logging lines in the normal log file.
> 
> As such I consider this a blocker.

Again, I respectfully disagree with you.  This patch has
not landed on m-c yet, and as such it is pointless that
https://bugzilla.mozilla.org/show_bug.cgi?id=1374323 is a blocker.

I will mark that bug as invalid and add a new commit to this changeset
that dumps the test name to stdout.
(Assignee)

Updated

6 months ago
Duplicate of this bug: 1374323
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 55

6 months ago
The actual change I ended up making to
testing/marionette/harness/marionette_harness/marionette_test/testcases.
py looks like this:

> @@ -317,7 +311,7 @@ class MarionetteTestCase(CommonTestCase):
>      def setUp(self):
>          super(MarionetteTestCase, self).setUp()
>          self.marionette.test_name = self.test_name
> -        self.marionette.execute_script("log('TEST-START: {0}')"
> +        self.marionette.execute_script("dump('TEST-START: {0}')"
>                                         .format(self.test_name),
>                                         sandbox="simpletest")
>  
> @@ -329,7 +323,7 @@ class MarionetteTestCase(CommonTestCase):
>  
>          if not self.marionette.crashed:
>              try:
> -                self.marionette.execute_script("log('TEST-END: {0}')"
> +                self.marionette.execute_script("dump('TEST-END: {0}')"
>                                                 .format(self.test_name),
>                                                 sandbox="simpletest")
>                  self.marionette.test_name = None

And a try run can be inspected in
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5974b25123d0&group_state=expanded.
(In reply to Andreas Tolfsen ‹:ato› from comment #48)
> Again, I respectfully disagree with you.  This patch has
> not landed on m-c yet, and as such it is pointless that
> https://bugzilla.mozilla.org/show_bug.cgi?id=1374323 is a blocker.

I filed that other bug *before* I noticed that these were actually changes made on this patch series. So the bug itself can be close, right. But the requested change itself would be a blocker.

(In reply to Andreas Tolfsen ‹:ato› from comment #55)
> > -        self.marionette.execute_script("log('TEST-START: {0}')"
> > +        self.marionette.execute_script("dump('TEST-START: {0}')"
> >                                         .format(self.test_name),
> >                                         sandbox="simpletest")

Looks wayyy better now! Thanks. But it's not enough. You definitely also have to add a line break. Otherwise two separate log lines are glued together:

TEST-START: test_click.py TestClick.test_clicking_an_element_that_is_not_displayed_raises1497968188744	Marionette	TRACE	354 <- [1,5,null,{"value":null}]

Getting the timing information added too, would be a bonus point.
(Assignee)

Comment 57

6 months ago
(In reply to Henrik Skupin (:whimboo) from comment #56)
> (In reply to Andreas Tolfsen ‹:ato› from comment #55)
> > > -        self.marionette.execute_script("log('TEST-START: {0}')"
> > > +        self.marionette.execute_script("dump('TEST-START: {0}')"
> > >                                         .format(self.test_name),
> > >                                         sandbox="simpletest")
> 
> Looks wayyy better now! Thanks. But it's not enough. You definitely also
> have to add a line break. Otherwise two separate log lines are glued
> together:
> 
> TEST-START: test_click.py
> TestClick.test_clicking_an_element_that_is_not_displayed_raises1497968188744
> Marionette	TRACE	354 <- [1,5,null,{"value":null}]

Oh, good catch!  I’ve fixed it up.

> Getting the timing information added too, would be a bonus point.

Unfortunately the timestamp produced by Python with int(time.time()) has
ten digits, whereas Date.now() in JS produces 13.  Not sure how I can
overcome that.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 63

6 months ago
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/52b09d6a10db
Stop using Marionette.log API in harness; r=automatedtester
https://hg.mozilla.org/integration/autoland/rev/e8e676d8958c
Stop using Marionette.log API in external media tests; r=automatedtester,SingingTree
https://hg.mozilla.org/integration/autoland/rev/addcbdea2bd5
Remove Marionette.log API from client; r=automatedtester
https://hg.mozilla.org/integration/autoland/rev/1e92bb39550a
Remove log() call from WPT Marionette executor; r=jgraham
https://hg.mozilla.org/integration/autoland/rev/f865971d8357
Remove log and getLogs commands from Marionette; r=automatedtester

Comment 64

6 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/52b09d6a10db
https://hg.mozilla.org/mozilla-central/rev/e8e676d8958c
https://hg.mozilla.org/mozilla-central/rev/addcbdea2bd5
https://hg.mozilla.org/mozilla-central/rev/1e92bb39550a
https://hg.mozilla.org/mozilla-central/rev/f865971d8357
Status: ASSIGNED → RESOLVED
Last Resolved: 6 months ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
(In reply to Andreas Tolfsen ‹:ato› from comment #57)
> > Getting the timing information added too, would be a bonus point.
> 
> Unfortunately the timestamp produced by Python with int(time.time()) has
> ten digits, whereas Date.now() in JS produces 13.  Not sure how I can
> overcome that.

You could have done this by extending the JS code inside of execute_script. But it blows up the code. Lets see if we need it at all. I'm only worried about timing because we have seen some delays between commands where we don't know those are happen currently. Anyway, thanks for fixing!
(Assignee)

Comment 66

6 months ago
(In reply to Henrik Skupin (:whimboo) from comment #65)

> (In reply to Andreas Tolfsen ‹:ato› from comment #57)
> 
> > Unfortunately the timestamp produced by Python with int(time.time())
> > has ten digits, whereas Date.now() in JS produces 13.  Not sure how
> > I can overcome that.
> 
> You could have done this by extending the JS code inside of
> execute_script.  But it blows up the code. Lets see if we need
> it at all. I'm only worried about timing because we have seen
> some delays between commands where we don't know those are happen
> currently. Anyway, thanks for fixing!

Yes, I didn’t want to bloat the log unnecessarily just to add a log  .
line I’m sure it is possible to get more precise digits in Python,   .
but we can fix this if it is a problem                                 .
You need to log in before you can comment on or make changes to this bug.