Closed Bug 1375104 Opened 7 years ago Closed 7 years ago

Marionette test log files are missing stdout/stderr assertion/dump information

Categories

(Remote Protocol :: Marionette, defect)

Product:
Remote Protocol
Component:
Marionette
Version:
Version 3
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox56 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla56
Tracking Flags:
Tracking Status
firefox56 --- fixed

People

(Reporter: benjamin, Assigned: whimboo)

Details

Attachments

(1 file)

Bug 1375104 - Combine standard and Gecko log for Marionette.
59 bytes, text/x-review-board-request
ato
: review+
impossibus
: review+
Details 
Marionette run at https://treeherder.mozilla.org/logviewer.html#?job_id=108664858&repo=try

The build in question is firing an assertion (kinda-expected). I had added some logging information to this try build to help narrow down the situation which fires this assertion. That information is showing up in mochitest logs but not marionette logs.

As an example of this showing up correctly: https://treeherder.mozilla.org/logviewer.html#?job_id=108664802&repo=try&lineNumber=9005 has the following text in the log:

[task 2017-06-20T22:04:37.442550Z] 22:04:37     INFO - GECKO(2335) | 0 TM_notify(timer = [xpconnect wrapped nsITimer @ 0x7fde44e31c80 (native @ 0x7fde499d4660)]) ["jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js":213]
[task 2017-06-20T22:04:37.443000Z] 22:04:37     INFO - GECKO(2335) |     this = [object Object]
[task 2017-06-20T22:04:37.461225Z] 22:04:37     INFO - GECKO(2335) | Assertion failure: !sPreferences->mProfileShutdown (Setting user pref after profile shutdown.), at /home/worker/workspace/build/src/modules/libpref/Preferences.cpp:112
[task 2017-06-20T22:05:12.582937Z] 22:05:12     INFO - GECKO(2335) | #01: pref_HashPref [modules/libpref/prefapi.cpp:812]

(I added aan explicit xpc_DumpJSStack call to get the JS stack and not just the C++ stack, at this patch: https://hg.mozilla.org/try/rev/8ee6a78557bc5ed4eea211a51713222cb1978d02)
Please note that for Marionette based tests we have a separate log file called gecko.log. This one contains all the necessary information as logged by the gecko process:

https://treeherder.mozilla.org/logviewer.html#?job_id=108664858&repo=try&lineNumber=2718

Please note that assertion stacks are still not correct symbolicated. It's waiting for a fix on bug 1348961.

I wonder if we should combine both logs similar to what we do for Firefox ui tests. It would be indeed more helpful to have both the Python and Gecko output laying next to each other. Andreas, what do you think?
Flags: needinfo?(ato)
(In reply to Henrik Skupin (:whimboo) from comment #1)

> I wonder if we should combine both logs similar to what we do for
> Firefox ui tests. It would be indeed more helpful to have both the
> Python and Gecko output laying next to each other. Andreas, what do
> you think?

I think we should move the Marionette harness to structured logging,
which would allow for any composition of logs we want.

Surfacing the Gecko logs to the main log file is fine with me, though it
means we will no longer have a separate gecko.log file when the Gecko
log is redirected to stdout This may be acceptable.
Flags: needinfo?(ato)
Marionette already does structured logging, we can see this when looking at automation logs.

We need to combine the gecko.log and the structured logs into 1 log to get this fixed like in mochitest
(In reply to David Burns :automatedtester from comment #3)
> We need to combine the gecko.log and the structured logs into 1 log to get
> this fixed like in mochitest

Will this work? I mean the gecko.log has no structured data contents. But lets see. I pushed a try build:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=687323f7860c9ca448338ec694562e5560286ab5
My last try push was bogus. So I had to push once more:

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

We have the following two issues which do not play quite well yet:

1) Dump messages from any component of Firefox could use the ERROR level, which then will cause the test to be marked as failed:

> [task 2017-06-23T13:49:08.947771Z] 13:49:08    ERROR -  ExceptionHandler::GenerateDump cloned child 3698

2) An error which gets transferred back to the client, which can be expected is marked as a failure in Treeherder. 

> [task 2017-06-23T13:44:42.222565Z] 13:44:42    ERROR -  1498225482216	Marionette	TRACE	980 <- [1,21,{"error":"unknown error","message":"[Exception... \"The URI scheme corresponds to an unknown protocol handler\"  nsresult: \"0x804b0012 (NS_ERROR_UNKNOWN_PROTOCOL)\"  location: \"JS frame :: chrome://marionette/content/listener.js :: get/< :: line 1077\"  data: no]","stacktrace":"get/<@chrome://marionette/content/listener.js:1077:7\nnavigate/<@chrome://marionette/content/listener.js:361:13\nTaskImpl_run@resource://gre/modules/Task.jsm:321:42\nTaskImpl@resource://gre/modules/Task.jsm:279:3\nasyncFunction@resource://gre/modules/Task.jsm:254:14\nTask_spawn@resource://gre/modules/Task.jsm:168:12\nnavigate@chrome://marionette/content/listener.js:360:12\nget@chrome://marionette/content/listener.js:1076:5\n"},null]

I assume both situations happen because "Exception" is contained in those lines which trigger Treeherder to mark those as ERROR, based on the defined `error_lines`? Btw. those might need an update too.

https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/scripts/marionette.py#118
Flags: needinfo?(emorley)
I thin you will want to swallow the output from the process in a stream
and redirect it to the logger, much like what wptrunner is doing in
https://github.com/w3c/wptrunner/blob/master/wptrunner/browsers/firefox.py#L225L232.
(In reply to Henrik Skupin (:whimboo) from comment #5)
> I assume both situations happen because "Exception" is contained in those
> lines which trigger Treeherder to mark those as ERROR, based on the defined
> `error_lines`? Btw. those might need an update too.

Treeherder doesn't generate the "ERROR" prefix in the log, mozharness/test harnesses do.
Flags: needinfo?(emorley)
I just pushed another try build with a commit on top which simulates an unexpected crash and failure. As it looks like this is what we might want to have.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8a0fe5ad4182845357cebf0dd18dc4a120360bac&selectedJob=110263851

Benjamin, even this doesn't include an assertion, does it look like what you want to have?
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Attachment #8881654 - Flags: review?(ato)
Comment on attachment 8881654 [details]
Bug 1375104 - Combine standard and Gecko log for Marionette.

https://reviewboard.mozilla.org/r/152808/#review158016

I don’t have intimate knowledge with how marionette_parser works, but I’m assuming this produces the desired effect.

::: testing/mozharness/scripts/marionette.py:291
(Diff revision 1)
>              cmd.append('--disable-e10s')
>  
>          if self.config['headless']:
>              cmd.append('--headless')
>  
> -        cmd.append('--gecko-log=%s' % os.path.join(dirs["abs_blob_upload_dir"],
> +        cmd.append('--gecko-log=-')

I don’t think this won’t work in all shell environments, such as csh/tsch and rc.  You should do:

> cmd.append("--gecko-log").append("-")

Or:

> cmd.append("--gecko-log -")

I could be wrong about this, so please verify before making the change.

::: testing/mozharness/scripts/marionette.py:337
(Diff revision 1)
> -                                              error_list=self.error_list,
> +                                              error_list=BaseErrorList + HarnessErrorList,
>                                                strict=False)
> -        return_code = self.run_command(cmd, env=env,
> +        return_code = self.run_command(cmd,
> -                                output_timeout=1000,
> +                                       output_timeout=1000,
> -                                output_parser=marionette_parser)
> +                                       output_parser=marionette_parser,
> +                                       env=env,)

The last , is probably unnecessary here.
Attachment #8881654 - Flags: review?(ato) → review+
Comment on attachment 8881654 [details]
Bug 1375104 - Combine standard and Gecko log for Marionette.

https://reviewboard.mozilla.org/r/152808/#review158016

> I don’t think this won’t work in all shell environments, such as csh/tsch and rc.  You should do:
> 
> > cmd.append("--gecko-log").append("-")
> 
> Or:
> 
> > cmd.append("--gecko-log -")
> 
> I could be wrong about this, so please verify before making the change.

> cmd.append("--gecko-log -")

No, this doesn't work due to the space before the dash. In Firefox UI tests we successfully use the used method in my patch for a long time now, without having anz issues. Also we make use of the same style a line below for specifying the structured log output. So to stay in parity I will leave it as it is.
Attachment #8881654 - Flags: review?(mjzffr)
Comment on attachment 8881654 [details]
Bug 1375104 - Combine standard and Gecko log for Marionette.

https://reviewboard.mozilla.org/r/152808/#review158074

::: commit-message-6b989:3
(Diff revision 2)
> +Bug 1375104 - Combine standard and Gecko log for Marionette.
> +
> +In automation we should combine the standard logging and

Please also add a note about why you're replacing the `error_list`, since it's not strictly related to the combination of gecko.log with standard log.
Attachment #8881654 - Flags: review?(mjzffr) → review+
Comment on attachment 8881654 [details]
Bug 1375104 - Combine standard and Gecko log for Marionette.

https://reviewboard.mozilla.org/r/152808/#review158074

> Please also add a note about why you're replacing the `error_list`, since it's not strictly related to the combination of gecko.log with standard log.

I did now and explained why it was necessary to do for this patch.
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d03127f02471
Combine standard and Gecko log for Marionette. r=ato,maja_zf
https://hg.mozilla.org/mozilla-central/rev/d03127f02471
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: