1444949 - Console logging for unprivileged payment dialog code

Status: RESOLVED FIXED

(Firefox :: WebPayments UI, enhancement, P1)

Description

[Sam Foster [:sfoster] (he/him)]

Console logging in unprivileged code should follow the dom.payments.loglevel pref.

Comment 1

[Sam Foster [:sfoster] (he/him)]

Attachment: Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

* This works as required, but the setup code for the content frame is probably in the wrong place and time.
* Tried cloneInto without success, now using cloneFunction. I've left it commented out just so you can see what I tried in case I just missed something silly.
* I'm not sure how to test this. Maybe I can spy on console in a browser test? But what I really want to know is if the message gets output for a given pref value, not if the method gets called.

Review commit: https://reviewboard.mozilla.org/r/227206/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/227206/

Comment 2

[Matthew N. [:MattN]]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review233036

I'll look into the rest later.

::: commit-message-d6957:5
(Diff revision 1)
> +Bug 1444949 - (WIP) Console logging for unprivileged code. r?MattN
> +
> +* This works as required, but the setup code for the content frame is probably in the wrong place and time.
> +* Tried cloneInto without success, now using cloneFunction. I've left it commented out just so you can see what I tried in case I just missed something silly.
> +* I'm not sure how to test this. Maybe I can spy on console in a browser test? But what I really want to know is if the message gets output for a given pref value, not if the method gets called.

I don't think we need a test for this. During development we'll notice if it breaks.

::: toolkit/components/payments/content/paymentDialogFrameScript.js:28
(Diff revision 1)
> -      return new ConsoleAPI({
> +      // NOTE: (sfoster) seems an odd side-effect to create this here
> +      // but I'm not sure what other trigger to use to get the timing right or
> +      // avoid needlessly loading the Console module
> +      let contentLogger = new ConsoleAPI({

I would be fine with re-using the same prefix or having a separate contentLogger getter as I agree it's a weird side-effect for the existing getter

::: toolkit/components/payments/content/paymentDialogFrameScript.js:61
(Diff revision 1)
> +    Cu.exportFunction(logger.log, content.console, {
> +      defineAs: "log",
> +    });
> +    Cu.exportFunction(logger.info, content.console, {
> +      defineAs: "info",
> +    });
> +    Cu.exportFunction(logger.warn, content.console, {
> +      defineAs: "warn",
> +    });
> +    Cu.exportFunction(logger.error, content.console, {
> +      defineAs: "error",
> +    });

If we override the `console.*` names we'll have to fight with eslint telling us not to use them. I think we should expose a `log` propertly on the global instead.

Comment 3

[Matthew N. [:MattN]]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review233322

::: toolkit/components/payments/content/paymentDialogFrameScript.js:61
(Diff revision 1)
> +    Cu.exportFunction(logger.log, content.console, {
> +      defineAs: "log",
> +    });
> +    Cu.exportFunction(logger.info, content.console, {
> +      defineAs: "info",
> +    });
> +    Cu.exportFunction(logger.warn, content.console, {
> +      defineAs: "warn",
> +    });
> +    Cu.exportFunction(logger.error, content.console, {
> +      defineAs: "error",
> +    });

If we don't use the `console.*` names we'll need a fallback for debugging over the file: URI.

One idea is to have a new file e.g. log.js referenced as the first <script> in the dialog xhtml with contents:

```js
var log = {
  info(...args) {
    console.info(...args);
  },
  warn(...args) {
    console.warn(...args);
  },
  …
};
```
The above will work over file: URIs. We'd need to silence the eslint console rule just for this file.

Then overwrite those methods with exportFunction (not sure if that works) from within paymentDialogFrameScript.js during the `initializeRequest` message (or maybe we'll have to do earlier).

I don't think you need to worry about lazy-loading since Console.jsm is likely loaded by then anyways or will be for the other logging shortly.

Comment 4

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/227206/diff/1-2/

Comment 5

[Sam Foster [:sfoster] (he/him)]

I've spent a while trying to get this to work, and I don't yet understand why it doesnt. When I exportFunction to console.log - to place the function on the log global that log.js creates - I get a Error: Invalid argument exception. 

I'll look at alternative approaches while I dig a bit further.

Comment 6

[Matthew N. [:MattN]]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review233662

::: toolkit/components/payments/content/paymentDialogFrameScript.js:55
(Diff revision 2)
> +      maxLogLevelPref: "dom.payments.loglevel",
> +      prefix: "paymentDialogContent",
> +    });
> +    for (let name of ["error", "warn", "info", "log", "debug"]) {
> +      // FIXME: (sfoster) export to content.console works fine, content.log does not
> +      Cu.exportFunction(privilegedLogger[name], content.log, {

The error is because `content.log` is undefined due to xray wrappers. You would need to `Cu.waiveXrays(content).log` but I'm not sure if that's safe. 

Since we need to have the fallback log.js for file URIs anyways… maybe we should use the dispatchEvent approach like we do for messages but for logs instead? It would be safer. Thoughts?

Comment 7

[Matthew N. [:MattN]]

Bobby, just to double-check, would the following code in a frame script cause any security issues:

```js
Cu.exportFunction(privilegedLogger.log, Cu.waiveXrays(content).log, {
  defineAs: "log",
});
```

`content` is for an unprivileged page that we don't want to necessarily trust and `log` is a global variable on that window. Is there any issue with exporting a function on a content object with a waived xray-wrapper? I can't think of a specific issue but I get nervous using waiveXrays in shipping code on untrusted objects.

Comment 8

[Sam Foster [:sfoster] (he/him)]

(In reply to Matthew N. [:MattN] (PM if requests are blocking you) from comment #6)
> The error is because `content.log` is undefined due to xray wrappers. You
> would need to `Cu.waiveXrays(content).log` but I'm not sure if that's safe. 
> 
> Since we need to have the fallback log.js for file URIs anyways… maybe we
> should use the dispatchEvent approach like we do for messages but for logs
> instead? It would be safer. Thoughts?

Yeah that's the alternative approach I was going to try in the meantime.

Comment 9

[Bobby Holley (:bholley)]

(In reply to Matthew N. [:MattN] (PM if requests are blocking you) from comment #7)
> Bobby, just to double-check, would the following code in a frame script
> cause any security issues:
> 
> ```js
> Cu.exportFunction(privilegedLogger.log, Cu.waiveXrays(content).log, {
>   defineAs: "log",
> });
> ```
> 
> `content` is for an unprivileged page that we don't want to necessarily
> trust and `log` is a global variable on that window. Is there any issue with
> exporting a function on a content object with a waived xray-wrapper? I can't
> think of a specific issue but I get nervous using waiveXrays in shipping
> code on untrusted objects.

So there are two things to look at:
(1) Is privilegedLogger.log hardened against malicious inputs?
(2) Shenanigans that the page might do by defining a getter for the "log" object, or making it a proxy.

In general, if you want to export a set of APIs, it tends to work a little better to define them all on an object together, and use Cu.cloneInto with cloneFunctions=true, defining the object straight onto the window.

That said, these mechanisms are intended for addons that want to inject simple hooks, not for DOM APIs. Why aren't we using WebIDL here?

Comment 10

[Sam Foster [:sfoster] (he/him)]

I have an implementation that passes the console messages up to the frame script as an event. We are already handling events there from the window so its straightforward. While I'm sure we *could* secure the console methods if they are not secured already, I'm not sure we need to.

Comment 11

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/227206/diff/2-3/

Comment 12

[Matthew N. [:MattN]]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review234374

Very close but I think there are some leftovers in the patch.

::: toolkit/components/payments/content/paymentDialogFrameScript.js:27
(Diff revision 3)
>        let {ConsoleAPI} = ChromeUtils.import("resource://gre/modules/Console.jsm", {});
>        return new ConsoleAPI({
>          maxLogLevelPref: "dom.payments.loglevel",
>          prefix: "paymentDialogFrameScript",
>        });
>      });
> +    XPCOMUtils.defineLazyGetter(this, "contentLog", () => {
> +      let {ConsoleAPI} = ChromeUtils.import("resource://gre/modules/Console.jsm", {});

Nit: For less memory we should define the lazy module getter for Console.jsm at the top-level so that both log getters can share the reference.

::: toolkit/components/payments/res/containers/payment-dialog.js:4
(Diff revision 3)
>  
> -/* global PaymentStateSubscriberMixin, paymentRequest */
> +/* global PaymentStateSubscriberMixin, paymentRequest, log */
>  

I guess this is leftover but I do think this patch should add some useful log calls

::: toolkit/components/payments/res/log.js:11
(Diff revision 3)
> +  toggleDispatch(should) {
> +    this._shouldDispatchMessage = !!should;
> +  },
> +  _dispatchMessage(methodName, ...args) {
> +    let event = new CustomEvent("paymentContentConsoleMessage", {
> +      bubbles: true,
> +      detail: {
> +        methodName,
> +        args,
> +      },
> +    });
> +    document.dispatchEvent(event);
> +  },
> +  init() {
> +    addEventListener("logStateChange", event => {
> +      this._shouldDispatchMessage = true;
> +    });

IIUC, we don't need both `logStateChange` and `toggleDispatch`?

::: toolkit/components/payments/res/log.js:15
(Diff revision 3)
> +    let event = new CustomEvent("paymentContentConsoleMessage", {
> +      bubbles: true,

It probably doesn't need to bubble which would save some resources if we dispatch on the window instead.

::: toolkit/components/payments/res/paymentRequest.js:11
(Diff revision 3)
>   * Loaded in the unprivileged frame of each payment dialog.
>   *
>   * Communicates with privileged code via DOM Events.
>   */
>  
> +/* global log */

```js
/* import-globals-from log.js */
```
will catch if log.js changes so is more useful. I realize that we aren't doing this everywhere but we should.

Comment 13

[Sam Foster [:sfoster] (he/him)]

I actually have to re-think this again. Adding in useful logging in paymentRequest.js uncovered an issue with logging any kind of non-primitive stuff, which I think we will need. It doesn't look like I can use cloneInto to clone the event detail into the frame script. But, AIUI I should be able to pass the log levels and pref value down to the content window and do the conditional logging there. 

(In reply to Matthew N. [:MattN] (PM if requests are blocking you) from comment #12)
> Comment on attachment 8958276 [details]
> Bug 1444949 - Pref-controlled console logging for unprivileged payments code.


> ```js
> /* import-globals-from log.js */
> ```
> will catch if log.js changes so is more useful. I realize that we aren't
> doing this everywhere but we should.

I ran into path resolution issues doing this. I end up with a i/o exception opening res/containers/log.js. I'll have to look into how that path is getting resolved.

Comment 14

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review234374

> Nit: For less memory we should define the lazy module getter for Console.jsm at the top-level so that both log getters can share the reference.

2nd log getter no longer necessary in the latest patch, so this remains as-is.

> I guess this is leftover but I do think this patch should add some useful log calls

I'm not sure what constitutes "useful", but in the latest patch I've added a couple calls in payment-dialog.js to verify the implementation

> It probably doesn't need to bubble which would save some resources if we dispatch on the window instead.

I had trouble with this. If I don't bubble, the event never reached the frame script - even when dispatching on the window rather than the document. 

Regardless, this event is no longer necessary in the latest patch as the unpriv. logger itself doesnt need to communicate with the script script. We just piggy-back on the initializeRequest event as a signal that the content is ready to receive our "loggingConfigure" event.

> ```js
> /* import-globals-from log.js */
> ```
> will catch if log.js changes so is more useful. I realize that we aren't doing this everywhere but we should.

This also gave me trouble. The way paths get resolved means that it fails to find log.js as it is looking in res/containers/. I tried various relative paths and re-ordering lines in jar.mn before giving up on this one. Suggestions needed.

Comment 15

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/227206/diff/3-4/

Comment 16

[Matthew N. [:MattN]]

Attachment: Bug 1444949 - Pref-controlled console logging for unprivileged code.

* Default log implementation for unprivileged content
* Export methods of a ConsoleAPI instance into the content frame to replace the default log
* Initialize the content logger when the "initializeRequest" message is received

Review commit: https://reviewboard.mozilla.org/r/229222/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/229222/

Comment 17

[Matthew N. [:MattN]]

(In reply to Bobby Holley (PTO through April 2) from comment #9)
> In general, if you want to export a set of APIs, it tends to work a little
> better to define them all on an object together, and use Cu.cloneInto with
> cloneFunctions=true, defining the object straight onto the window.

That wasn't working for some reason.

> That said, these mechanisms are intended for addons that want to inject
> simple hooks, not for DOM APIs. Why aren't we using WebIDL here?

Note that this isn't a general purpose DOM API, this is only injected in one "trusted content page". The reason it wasn't using WebIDL is because I couldn't think of a clean way to attach the interface to only this one frame without writing a bunch of C++ code in dom/ far away from the payments implementation. I assumed that DOM peers also wouldn't like it there. The untrusted page also doesn't have its own origin as it uses resource://… so it wasn't clear if there was an efficient way to selectively attach the logging interface for only this resource URL without affecting regular web content page performance.

In the meantime I remembered that there is an API for the console now implemented with WebIDL but marked as ChromeOnly (console.createInstance) so wondered if it's safer to export its methods instead as it least then unprivileged JS won't communicate with Console.jsm.

When you return from PTO can you confirm that the same code is safe if `privilegedLogger` implements a ChromeOnly WebIDL interface? Or would some security checks be bypassed because the logger object was created from a chrome-privileged context.
```js
let privilegedLogger = content.window.console.createInstance();
Cu.exportFunction(privilegedLogger.log, Cu.waiveXrays(content).log, {
  defineAs: "log",
});
```

Comment 18

[Matthew N. [:MattN]]

Comment on attachment 8958276 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged payments code.

https://reviewboard.mozilla.org/r/227206/#review234908

::: toolkit/components/payments/content/paymentDialogFrameScript.js:49
(Diff revision 4)
> +  setupContentLogger() {
> +    // send a message to the content frame
> +    // with current logging level and level constants
> +    let event = new content.CustomEvent("loggingConfigure", {
> +      detail: Cu.cloneInto({
> +        logLevel: Services.prefs.getCharPref("dom.payments.loglevel", ""),

Remove the second argument since it doesn't match the desired default from all.ja and we should throw instead if it goes missing from all.js.

::: toolkit/components/payments/res/log.js:26
(Diff revision 4)
> +  _log(methodName, ...args) {
> +    let levelName = this._logLevel ? this._logLevel.toUpperCase() : "DEBUG";
> +    let level, currentLevel;
> +    if (this._logLevelNumbers) {
> +      currentLevel = this._logLevelNumbers[levelName];
> +      level = this._logLevelNumbers[methodName.toUpperCase()];
> +      if (!level) {

I would rather avoid re-implementing the log level logic so propose using the new console.createInstance WebIDL interface to replace Console.jsm so we hopefully get the additional WebIDL checks.

Comment 19

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8960445 [details]
Bug 1444949 - Pref-controlled console logging for unprivileged code.

https://reviewboard.mozilla.org/r/229222/#review235232

Yeah, I think this covers it. Provided the waiveXrays(content) is safe there.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f11c1c4efc86
Pref-controlled console logging for unprivileged code. r=sfoster

Comment 21

[Tiberius Oros[:tiberius_oros]]

https://hg.mozilla.org/mozilla-central/rev/f11c1c4efc86