Henrik Skupin [:whimboo][⌚️UTC+1] Reporter
	Description • 6 years ago

With the changes on bug 1169290 the type of logging has been changed and with that it is no longer visible if Marionette is enabled or not:

https://treeherder.mozilla.org/logviewer.html#?job_id=162593675&repo=mozilla-inbound&lineNumber=1174

05:11:01     INFO -  Application command: Z:\task_1518757393\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmp7ievm8.mozrunner
05:11:01     INFO -  1518757861934	Marionette	DEBUG	Received observer notification profile-after-change
05:11:01     INFO -  1518757861972	Marionette	DEBUG	Received observer notification command-line-startup
05:11:01     INFO -  1518757861972	Marionette	DEBUG	Received observer notification nsPref:changed

Instead of enabled we only see "nsPref:changed".

Andreas, can you please get this fixed? Maybe by also adding `subject` to the debug line, which should work in most of the cases.

	Andreas Tolfsen ❲:ato❳
	Comment 1 • 6 years ago

You can tell that Marionette is enabled by the “Marionette     Listening
on port 2828” line.

	Henrik Skupin [:whimboo][⌚️UTC+1] Reporter
	Comment 2 • 6 years ago

No, this only means that the socket is active, but if something fails in-between "command-line-startup" and "sessionstore-windows-restored" we do not know the state of Marionette.

	Andreas Tolfsen ❲:ato❳
	Comment 3 • 6 years ago

I don’t think it is particularly useful to log that a system
observer notification fires.  If they don’t fire there is a more
fundamental problem with nsICommandLine or nsISessionStore.

If something errors in nsIMarionette before we reach “Listening
on port <N>”, XPCOM logs this to stdout per usual:

> % ./mach marionette test --gecko-log -
>  0:00.00 INFO Using workspace for temporary data: "/home/ato/src/gecko"
>  0:00.00 mozversion INFO application_buildid: 20180221114841
>  0:00.00 mozversion INFO application_display_name: Nightly
>  0:00.00 mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
>  0:00.00 mozversion INFO application_name: Firefox
>  0:00.00 mozversion INFO application_remotingname: firefox
>  0:00.01 mozversion INFO application_vendor: Mozilla
>  0:00.01 mozversion INFO application_version: 60.0a1
>  0:00.01 mozversion INFO platform_buildid: 20180221114841
>  0:00.01 mozversion INFO platform_version: 60.0a1
>  0:00.01 INFO Application command: /home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/firefox -no-remote -marionette -profile /tmp/tmpV8BOLr.mozrunner
> libGL error: No matching fbConfigs or visuals found
> libGL error: failed to load driver: swrast
> JavaScript error: file:///home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/components/marionette.js, line 288: Error: hello from init()

It can be argued we should expand the try…catch block in
MarionetteMainProcess#init() so that we shut down Firefox when
something throws an error at any point during initialisation,
however that is unrelated to this bug.