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)
Remote Protocol
Marionette
Tracking
(firefox62 fixed)
RESOLVED
FIXED
mozilla62
Tracking | Status | |
---|---|---|
firefox62 | --- | fixed |
People
(Reporter: ato, Assigned: ato)
References
Details
Attachments
(4 files)
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 | ||
Updated•6 years ago
|
Assignee | ||
Comment 1•6 years ago
|
||
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.
Assignee | ||
Comment 2•6 years ago
|
||
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 hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment 7•6 years ago
|
||
mozreview-review |
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 8•6 years ago
|
||
mozreview-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 9•6 years ago
|
||
mozreview-review |
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 10•6 years ago
|
||
mozreview-review |
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 11•6 years ago
|
||
mozreview-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?
Assignee | ||
Comment 12•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 13•6 years ago
|
||
mozreview-review-reply |
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?
Assignee | ||
Comment 14•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 15•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 16•6 years ago
|
||
mozreview-review-reply |
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 hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Comment 21•6 years ago
|
||
mozreview-review-reply |
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 22•6 years ago
|
||
mozreview-review |
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 23•6 years ago
|
||
mozreview-review-reply |
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 24•6 years ago
|
||
mozreview-review |
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 25•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 26•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 27•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 28•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 29•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Updated•6 years ago
|
Flags: needinfo?(hskupin)
Comment 30•6 years ago
|
||
mozreview-review-reply |
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 31•6 years ago
|
||
mozreview-review |
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 32•6 years ago
|
||
mozreview-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?
Assignee | ||
Comment 33•6 years ago
|
||
mozreview-review-reply |
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.
Assignee | ||
Comment 34•6 years ago
|
||
mozreview-review-reply |
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 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 42•6 years ago
|
||
mozreview-review-reply |
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 43•6 years ago
|
||
mozreview-review-reply |
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 44•6 years ago
|
||
mozreview-review |
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+
Comment 45•6 years ago
|
||
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
Comment 46•6 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/3f35f2bf32aa https://hg.mozilla.org/mozilla-central/rev/be9770353c74 https://hg.mozilla.org/mozilla-central/rev/3905574a9d0c https://hg.mozilla.org/mozilla-central/rev/6ce977d45274
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox62:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Assignee | ||
Updated•6 years ago
|
Flags: needinfo?(hskupin)
Updated•2 years ago
|
Product: Testing → Remote Protocol
You need to log in
before you can comment on or make changes to this bug.
Description
•