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.

Comment on attachment 8875801 [details] Bug 1370863 - Stop using Marionette.log API in harness; https://reviewboard.mozilla.org/r/147208/#review151474

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.

Comment on attachment 8875803 [details] Bug 1370863 - Remove log and getLogs commands from Marionette; https://reviewboard.mozilla.org/r/147212/#review151482

Comment on attachment 8876108 [details] Bug 1370863 - Remove log() call from WPT Marionette executor; https://reviewboard.mozilla.org/r/147536/#review151814

Comment on attachment 8876107 [details] Bug 1370863 - Remove Marionette.log API from client; https://reviewboard.mozilla.org/r/147534/#review152016

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 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.

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!

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.

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

Strange. Nothing in the gecko.log shows this specific test: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/6721d5196757fbf24bb86513bc1404c45b50b1c7a4c10f682b4b2b46e8073113906f9206641ad6e9d3d9cdb03d244c3d32e9f6a01939dc3bcdcc6e966ad6b6a7

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"

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

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.

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.

(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.

(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.

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.

(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.

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

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

(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!

(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 .