Closed Bug 1464469 Opened 6 years ago Closed 6 years ago

Prefix log messages in frame script with window ID

Categories

(Remote Protocol :: Marionette, enhancement)

Product:
Remote Protocol
Component:
Marionette
Type:
enhancement
Priority:
Not set
Severity:
normal

Tracking

(firefox62 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla62
Tracking Flags:
Tracking Status
firefox62 --- fixed

People

(Reporter: ato, Assigned: ato)

References

Details

Attachments

(4 files)

Bug 1464469 - Shorthands for setting up Marionette logger.
59 bytes, text/x-review-board-request
whimboo
: review+
Details
Bug 1464469 - Avoid ad-hoc Marionette logging setup.
59 bytes, text/x-review-board-request
whimboo
: review+
Details
Bug 1464469 - Use MarionetteLog throughout.
59 bytes, text/x-review-board-request
whimboo
: review+
Details
Bug 1464469 - Prefix frame script logs with the outerWindowID.
59 bytes, text/x-review-board-request
whimboo
: review+
Details 
Gecko is a multitasking UA and when multiple tabs are present, log
entries may get “jumbled up”, making it unclear what the origin of
the entries are.  To make it clear where a log message originates
from we can prefix log entries coming from frame scripts with the
outerWindowID.

Later, when
https://bugzilla.mozilla.org/show_bug.cgi?id=marionette-window-tracking
lands, we can exchange the outerWindowID with the unique browsing
context ID, which will cause even less doubt about their origin.
Assignee: nobody → ato
Blocks: marionette-window-tracking
Status: NEW → ASSIGNED
Hm, if we added another column to indicate the content browser we
would have to do the same for other processes:

> 1527267786724	Marionette	TRACE	main	13 -> [0,26,"WebDriver:Navigate",{"url":"about:robots"}]
> 1527267786760	Marionette	DEBUG	24	Received DOM event beforeunload for about:preferences

Unfortunately I don’t think there any way to set a _default_ log
message prefix using Log.jsm, so we would need a getter such as
MarionetteLog.get() that would figure out _where_ the logger is
being requested from.  That is, however, a lot more complexity than
I had first thought.

The simple solution is just to prefix "[<outerWindowID>] " specifically
in testing/marionette/listener.js and not worry about introducing
a new column, but this makes the logs harder to read for a machine
because you can no longer use awk(1) to filter the columns.
I’ve decided to go for the simple approach and simply prefix messages
in listener.js with the outerWindowID for now.

Another unexpected benefit of the patches I’m working on is that
it gets rid of ad-hoc logger configuration in
testing/marionette/components/marionette.js and
testing/marionette/listener.js.
Comment on attachment 8983770 [details]
Bug 1464469 - Shorthands for setting up Marionette logger.

https://reviewboard.mozilla.org/r/249608/#review256476

I like that change! It makes things very easy now.

::: testing/marionette/log.js:70
(Diff revision 1)
> +    this.get();
> +    return StdLog.repository.getLoggerWithMessagePrefix("Marionette", `[${prefix}] `);
> +  }
> +}
> +
> +class MainProcessLog extends MarionetteLog {

Can we call this `ParentProcessLog` please?

::: testing/marionette/log.js:84
(Diff revision 1)
> +  static get() {
> +    let logger = super.get();
> +
> +    // Log.jsm is not e10s compatible (see https://bugzil.la/1411513)
> +    // so loading it in a new child process will reset the repository config
> +    logger.level = Services.cpmm.initialProcessData["Marionette:Log"];

I assume it will always return a value and not `undefined`? Or should we default to `INFO` here?
Attachment #8983770 - Flags: review?(hskupin) → review+
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review256480

::: testing/marionette/components/marionette.js:13
(Diff revision 1)
>  ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
>  
>  XPCOMUtils.defineLazyServiceGetter(
>      this, "env", "@mozilla.org/process/environment;1", "nsIEnvironment");
> -ChromeUtils.defineModuleGetter(this, "Log",
> -    "resource://gre/modules/Log.jsm");
> +ChromeUtils.defineModuleGetter(
> +    this, "Log", "chrome://marionette/content/log.js");

Do we really have to expose "Log" for the whole module? Why not encapsulating it inside of `XPCOMUtils.defineLazyGetter`?

::: testing/marionette/components/marionette.js
(Diff revision 1)
>  
>      // indicates that all pending window checks have been completed
>      // and that we are ready to start the Marionette server
>      this.finalUIStartup = false;
>  
> -    log.level = MarionettePrefs.logLevel;

Given that this is a lazy getter now, when exactly will we initialize `initialProcessData` now? I assume we can make sure that the logger is used in this module before any child process is using it?
Attachment #8983771 - Flags: review?(hskupin)
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review256482

::: testing/marionette/accessibility.js:13
(Diff revision 1)
> -ChromeUtils.import("resource://gre/modules/Log.jsm");
>  
> -const logger = Log.repository.getLogger("Marionette");
> +const {ElementNotAccessibleError} = ChromeUtils.import("chrome://marionette/content/error.js", {});
> +const {Log} = ChromeUtils.import("chrome://marionette/content/log.js", {});
>  
> -const {ElementNotAccessibleError} =
> +const logger = Log.get();

Why not making it a lazy getter? It will save us time when loading the module.

This also applies to all other files where you have made this change.
Attachment #8983772 - Flags: review?(hskupin)
Comment on attachment 8983773 [details]
Bug 1464469 - Prefix frame script logs with the outerWindowID.

https://reviewboard.mozilla.org/r/249614/#review256484

::: commit-message-b4166:15
(Diff revision 1)
> +true at the moment when Marionette does not have the capability to
> +uniquely identify a browser.
> +
> +The intention is to change from using the outerWindowID,
> +which changes when a content browser undergoes a remoteness
> +change, to using a unique identifier for the browser once

It's not only happening for `remoteness change` but also when the tab gets moved eg. to a different content process due to sandbox changes etc.

::: testing/marionette/listener.js:81
(Diff revision 1)
>  let legacyactions = new legacyaction.Chain();
>  
>  // last touch for each fingerId
>  let multiLast = {};
>  
> -// TODO: Log.jsm is not e10s compatible (see https://bugzil.la/1411513),
> +const logger = Log.getWithPrefix(outerWindowID);

Would it help to make it a lazy getter?

::: testing/marionette/listener.js:441
(Diff revision 1)
>   * Called when listener is first started up.  The listener sends its
>   * unique window ID and its current URI to the actor.  If the actor returns
>   * an ID, we start the listeners. Otherwise, nothing happens.
>   */
>  function registerSelf() {
>    let {outerWindowID} = winUtil;

This is global now and can be removed.

::: testing/marionette/listener.js:1602
(Diff revision 1)
>    }
>    flushWindow(content);
>  
>    if (anyPendingPaintsGeneratedInDescendants &&
>        !windowUtils.isMozAfterPaintPending) {
> -    logger.error("Internal error: descendant frame generated a MozAfterPaint event, but the root document doesn't have one!");
> +    logger.error("descendant frame generated a MozAfterPaint event, " +

nit: Lets start the sentence with a capital letter.
Attachment #8983773 - Flags: review?(hskupin) → review+
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review256486

::: testing/marionette/legacyaction.js:20
(Diff revision 1)
>  const CONTEXT_MENU_DELAY_PREF = "ui.click_hold_context_menus.delay";
>  const DEFAULT_CONTEXT_MENU_DELAY = 750;  // ms
>  
>  this.EXPORTED_SYMBOLS = ["legacyaction"];
>  
> -const logger = Log.repository.getLogger("Marionette");
> +const logger = Log.get();

So this module like others is also used in content processes. How could we improve that we see that the log entry comes from which browsing context? Do we need that or would it be enough to have the outer window id prefixed in listener.js?
Comment on attachment 8983770 [details]
Bug 1464469 - Shorthands for setting up Marionette logger.

https://reviewboard.mozilla.org/r/249608/#review256476

> Can we call this `ParentProcessLog` please?

Makes sense.  Has symmetry with ppmm.

> I assume it will always return a value and not `undefined`? Or should we default to `INFO` here?

We can default to Log.Level.Info, but we’ve not had any bugs with
this in the past.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review256480

> Do we really have to expose "Log" for the whole module? Why not encapsulating it inside of `XPCOMUtils.defineLazyGetter`?

I don’t think this makes any difference?
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review256480

> Given that this is a lazy getter now, when exactly will we initialize `initialProcessData` now? I assume we can make sure that the logger is used in this module before any child process is using it?

This is a good point.  It’s rather more unclear when it gets
initialised now.  Perhaps we can make an explicit Log.get() call
when Marionette gets initialised.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review256486

> So this module like others is also used in content processes. How could we improve that we see that the log entry comes from which browsing context? Do we need that or would it be enough to have the outer window id prefixed in listener.js?

I tried to explain why in last week’s meeting, but essentially the
JS modules are loaded once per child process and are not scoped to
the content frame script.  It is therefore possible that multiple
content browsers share the same JSMs.

This means we need to pass on any state information, such as the
outerWindowID, to the logger on construction.  Because multiple
browsers might share the same copy of a JSM I don’t think it will
not be possible to log the browser context ID/outerWindowID in
individual modules.
Comment on attachment 8983773 [details]
Bug 1464469 - Prefix frame script logs with the outerWindowID.

https://reviewboard.mozilla.org/r/249614/#review256484

> It's not only happening for `remoteness change` but also when the tab gets moved eg. to a different content process due to sandbox changes etc.

That would be my definition of what a remoteness change is.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review256486

> I tried to explain why in last week’s meeting, but essentially the
> JS modules are loaded once per child process and are not scoped to
> the content frame script.  It is therefore possible that multiple
> content browsers share the same JSMs.
> 
> This means we need to pass on any state information, such as the
> outerWindowID, to the logger on construction.  Because multiple
> browsers might share the same copy of a JSM I don’t think it will
> not be possible to log the browser context ID/outerWindowID in
> individual modules.

Oh, right. Forgot about that. I think then it is fine.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257344

::: testing/marionette/components/marionette.js:281
(Diff revision 2)
>      // indicates that all pending window checks have been completed
>      // and that we are ready to start the Marionette server
>      this.finalUIStartup = false;
>  
> -    log.level = MarionettePrefs.logLevel;
> -    Services.ppmm.initialProcessData["Marionette:Log"] = {level: log.level};
> +    // initialise logger
> +    Log.get();

This isn't needed anymore, right? We have a lazy getter above for getting the logger instance.
Attachment #8983771 - Flags: review?(hskupin)
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review256480

> I don’t think this makes any difference?

It does, because `Log` is only used once in `defineLazyGetter` for `log` once the other issue is fixed. So there is no need to expose it to the module, but could be kept inside of the lazy getter for `log`.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review257348

::: testing/marionette/accessibility.js:11
(Diff revisions 1 - 2)
>  
>  ChromeUtils.import("resource://gre/modules/Services.jsm");
>  ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
>  
>  const {ElementNotAccessibleError} = ChromeUtils.import("chrome://marionette/content/error.js", {});
>  const {Log} = ChromeUtils.import("chrome://marionette/content/log.js", {});

There is no need to expose `Log` to the module. It's only used in the lazy getter for `logger`.

This also applies to all the other modules.
Attachment #8983772 - Flags: review?(hskupin)
Comment on attachment 8983773 [details]
Bug 1464469 - Prefix frame script logs with the outerWindowID.

https://reviewboard.mozilla.org/r/249614/#review256484

> That would be my definition of what a remoteness change is.

Then lets drop it.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257344

> This isn't needed anymore, right? We have a lazy getter above for getting the logger instance.

You raised another issue about the fact that it was no longer clear
when the initial logger got initialised.  This explicitly initialises
the logger.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review256480

> It does, because `Log` is only used once in `defineLazyGetter` for `log` once the other issue is fixed. So there is no need to expose it to the module, but could be kept inside of the lazy getter for `log`.

Let me clarify: I don’t think it’s a problem that Log gets exposed
to the outer scope.  What I wanted to say is that it makes no
_practical_ difference.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review256482

> Why not making it a lazy getter? It will save us time when loading the module.
> 
> This also applies to all other files where you have made this change.

Maybe a little bit.  It also means we need to import XPCOMUtils.jsm
in more places, which might counteract the effect.  But it seems
worthwhile to avoid constructing it on module creation, for sure.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review257348

> There is no need to expose `Log` to the module. It's only used in the lazy getter for `logger`.
> 
> This also applies to all the other modules.

It makes _no practical difference_ if Log is exposed to the module
scope or inside an anonymous function.  I don’t know why you think
this is important.

We have a lazy getter for getting the logger instance which depends
on importing the module from where to get it.  As long as the module
is carefully designed so that it doesn’t unnecessarily define any
state—which it is—this is fine the way it is.
Flags: needinfo?(hskupin)
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257344

> You raised another issue about the fact that it was no longer clear
> when the initial logger got initialised.  This explicitly initialises
> the logger.

Andreas and I discussed this and he is going to remove this line because it is not necessary.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review257624

::: testing/marionette/evaluate.js:22
(Diff revision 2)
>    JavaScriptError,
>    ScriptTimeoutError,
>  } = ChromeUtils.import("chrome://marionette/content/error.js", {});
> +const {Log} = ChromeUtils.import("chrome://marionette/content/log.js", {});
>  
> -const log = Log.repository.getLogger("Marionette");
> +XPCOMUtils.defineLazyGetter(this, "log", Log.get);

As discussed yesterday it might be good to have `logger` or `log` used across all of the modules and not both.
Attachment #8983772 - Flags: review+
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257626

::: testing/marionette/components/marionette.js:13
(Diff revision 2)
>  ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
>  
>  XPCOMUtils.defineLazyServiceGetter(
>      this, "env", "@mozilla.org/process/environment;1", "nsIEnvironment");
> -ChromeUtils.defineModuleGetter(this, "Log",
> -    "resource://gre/modules/Log.jsm");
> +ChromeUtils.defineModuleGetter(
> +    this, "Log", "chrome://marionette/content/log.js");

Shouldn't this also be used for all the instances of the last commit in this series?
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257626

> Shouldn't this also be used for all the instances of the last commit in this series?

Everywhere else we load Log.jsm as we load all other JSMs.  The
reason to avoid it explicitly here is because the Marionette component
is loaded in a lot of unexpected places when Marionette might not
be enabled.

Once Marionette is enabled and the other JSMs in testing/marionette/*.js
are loaded, we know we need the logger and we know that it is already
loaded and cached in the process because this file would have loaded
it in.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review257624

> As discussed yesterday it might be good to have `logger` or `log` used across all of the modules and not both.

That will entail updating a lot of code so I would rather see that
done organically as we touch the files than enforcing a sweeping
change as part of this changeset.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257626

> Everywhere else we load Log.jsm as we load all other JSMs.  The
> reason to avoid it explicitly here is because the Marionette component
> is loaded in a lot of unexpected places when Marionette might not
> be enabled.
> 
> Once Marionette is enabled and the other JSMs in testing/marionette/*.js
> are loaded, we know we need the logger and we know that it is already
> loaded and cached in the process because this file would have loaded
> it in.

Makes sense. At least in `listener.js` we log immediately and then the module is loaded.
Comment on attachment 8983772 [details]
Bug 1464469 - Use MarionetteLog throughout.

https://reviewboard.mozilla.org/r/249612/#review257624

> That will entail updating a lot of code so I would rather see that
> done organically as we touch the files than enforcing a sweeping
> change as part of this changeset.

Sure, even better file a new good first bug someone new could work on. It would be a perfect starter.
Comment on attachment 8983771 [details]
Bug 1464469 - Avoid ad-hoc Marionette logging setup.

https://reviewboard.mozilla.org/r/249610/#review257700
Attachment #8983771 - Flags: review?(hskupin) → review+
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3f35f2bf32aa
Shorthands for setting up Marionette logger. r=whimboo
https://hg.mozilla.org/integration/autoland/rev/be9770353c74
Avoid ad-hoc Marionette logging setup. r=whimboo
https://hg.mozilla.org/integration/autoland/rev/3905574a9d0c
Use MarionetteLog throughout. r=whimboo
https://hg.mozilla.org/integration/autoland/rev/6ce977d45274
Prefix frame script logs with the outerWindowID. r=whimboo
Flags: needinfo?(hskupin)
Blocks: 1482829
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: