884397 - Structured logging in Log4Moz

Status: RESOLVED FIXED

(Cloud Services :: Firefox: Common, defect)

Description

[Chris Manchester (limited bugmail, email directly)]

With an eye towards machine readable test output, we should should be able to output structured log messages.

Comment 1

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Note that the test changes will not apply cleanly without the patch from bug 662247.

This is a basic implementation of JSON output for initial feedback - I would ultimately like to include the ability to convert to/from structured messages.

Comment 3

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

This implements a basic conversion between structured and unstructured formats, and un-bitrots with respect to the final patch from bug 662247.

<none>

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 765998 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 765998 [details] [diff] [review]:
-----------------------------------------------------------------

I like the start. I think we're fine with action + built-in metadata + user-supplied object for now. Over time, I predict we'll allow additional attributes per logger instance. But please don't bloat scope.

We may bike shed on the built-in metadata later.

Asking rnewman for feedback because he's good at API recommendations.

::: services/common/log4moz.js
@@ +150,2 @@
>   */
> +function Logger(name, repository, structuredEnabled=false) {

Hmmm. I'm not sure how I feel about passing structuredEnabled in as a constructor argument. Part of me likes how callers must explicitly select whether a logger is "classic" or "structured." On the other hand, I feel if you are going to make that distinction, it might be better to use a separate type.

That being said, there is something nice about having only 1 type of logger class. I feel that logging should be universal. You should see a this._log object and immediate think "oh, this type must be X therefore the API is Y." With separate types or behaviors, that API isn't consistent and can be confusing for code maintainability.

I think I would prefer structured messages either be emitted through overloading the existing APIs (e.g. detect when objects, not strings are passed). Or, I'd invent a new set of functions to handle just structured messages. I think I like the latter more because it is clearly obvious that something about that function call is different than normal logging. It stands out. It's obvious from the function name it is different. (Whereas with an overloaded "log", someone may be like "what's this object argument nonsense?)

@@ +212,5 @@
> +          }
> +          params.action = action;
> +          let messageString = params.message || "UNKNOWN";
> +          this.log(Log4Moz.Level[levelName], messageString, params);
> +        }

Remind me to teach you about function.bind() (it may not be applicable here, but you need to learn that trick).

@@ +350,5 @@
>  function Formatter() {}
>  Formatter.prototype = {
> +  formatStructured: function (logMessage) {
> +    return JSON.stringify(logMessage);
> +  },

formatStructured: JSON.stringify

@@ +359,4 @@
>  }
> +
> +// Basic formatter that doesn't do anything fancy.
> +function BasicFormatter() {}

It seems you broke backwards compatibility by removing dateFormat :(

Comment 5

[Richard Newman [:rnewman]]

Comment on attachment 765998 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 765998 [details] [diff] [review]:
-----------------------------------------------------------------

I guess my question is "can you mix structured and unstructured logging through the same logger"?

If yes, then you need API polymorphism:

  this._log.info("completed", {"foo": 1});
  this._log.debug("All done!");

If no, then you should have a delineation much higher up the stack.

  this._slog = new StructuredLogger(...);

The latter is much less likely to result in footguns -- it can check its method signatures, and you have a clue from the 'slog' part that this is a structured logger.

If you take the latter approach, you can even make StructuredLogger 'middleware' -- it takes a logger as an argument, and simply formats its inputs accordingly, dumping them to its inner logger.

Comment 6

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

This version differentiates between structured and unstructured interactions
with a logger by a new function, logStructured, with a level specified as
an object field. The underscore prefix is used in structured messages to
differentiate between built in metadata and fields of the user-supplied
object.

Comment 7

[Gregory Szorc [:gps]]

Comment on attachment 767970 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 767970 [details] [diff] [review]:
-----------------------------------------------------------------

We could probably go back and forth on API design for weeks. I think having a separate method for a structured message is a fine start. If we want to consolidate later, that door is still open. Pro tip: an important aspect of good API design and coding is not constraining future use. You don't want to be an "architect astronaut." But, you don't want basic libraries to unduly constrain consumers either.

::: services/common/log4moz.js
@@ +109,5 @@
>  /*
>   * LogMessage
>   * Encapsulates a single log event's data
>   */
> +function LogMessage(loggerName, level, message, params){

Nit: Fix formatting when touching a line (add space between "params" and ")").

@@ +127,5 @@
>  
>    toString: function LogMsg_toString(){
> +    return "LogMessage [" + this.time + " " +
> +      this.loggerName + " " + this.levelDesc + " " +
> +      this.message + " " + (JSON.stringify(this.params) || "") + "]";

We probably shouldn't change the formatting string if there are no params.

@@ +181,5 @@
>      parent.children.push(this);
>      this.updateAppenders();
>    },
>  
> +  _setLogFuns: function () {

Why did you move this out of the prototype? Before, we had a single prototype defining all the log functions. Now, we dynamically create 7 functions on each Logger instance. While you could say it's premature optimization, I think we should avoid this cost if at all possible.

@@ +190,5 @@
> +                  config: "Config",
> +                  debug: "Debug",
> +                  trace: "Trace"};
> +    for (let level in levels) {
> +      let levelName = levels[level];

You /could/ also rewrite this as:

for (let [level, levelName] in Iterator(levels)) {

@@ +193,5 @@
> +    for (let level in levels) {
> +      let levelName = levels[level];
> +      this[level] = function (message, params) {
> +        this.log(Log4Moz.Level[levelName], message, params);
> +      }

this[level] = this.log.bind(Log4Moz.Level[levelName]);

Pro tip: If a JS function consists of just a call to another function, you can use .bind if the argument order doesn't prevent it.

@@ +254,5 @@
> +    if (!params) {
> +      return this.log(this.level, "UNKOWN", {"action": action});
> +    }
> +
> +    let level = params.level || this.level;

What happened to our idea of having _-prefixed keys be the logger-state? i.e. y u no params._level?

@@ +366,5 @@
> +
> +  formatStructured: function (logMessage) {
> +    if (!logMessage.params) {
> +      logMessage.params = {};
> +      logMessage.params.action = "UNKNOWN";

I would argue that mutating the input message should not be a potential side-effect of formatting!

@@ +369,5 @@
> +      logMessage.params = {};
> +      logMessage.params.action = "UNKNOWN";
> +    }
> +
> +    let output = {_time: logMessage.time,

Nit: Please add a new line after "{" for multi-line objects definitions.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

This includes a fix to the way levels were handled in the case a level was
specified by a structured message.

Comment 9

[Gregory Szorc [:gps]]

Comment on attachment 770504 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 770504 [details] [diff] [review]:
-----------------------------------------------------------------

::: services/common/log4moz.js
@@ +143,2 @@
>      return "LogMessage [" + this.time + " " + this.level + " " +
>        this.message + "]";

Instead of repeating yourself, I'd build up the common string and just append. Internally, SpiderMonkey uses "ropes" for managing string concatenation, so it's not too expensive to keep appending to strings.

@@ +227,5 @@
>      this.ownAppenders.splice(index, 1);
>      this.updateAppenders();
>    },
>  
> +  logStructured: function (action, params) {

Can we get some docs on this method?

@@ +229,5 @@
>    },
>  
> +  logStructured: function (action, params) {
> +    if (!params) {
> +      return this.log(this.level, "UNKOWN", {"action": action});

unkown!

@@ +261,5 @@
>        appender.append(message);
>      }
>    },
>  
> +  fatal: function Logger_fatal(string, params) {

While you are here, nix the named function since it isn't necessary any more. (We generally fix style nits if modifying lines.)

@@ +361,2 @@
>  
> +  formatUnstructured: function (logMessage) {

I don't agree with the API breakage of renaming "format" to "formatUnstructured."

What's wrong with having a single "format" API that handles both structured and unstructured?

@@ +381,5 @@
>  };
>  
> +// Structured formatter that outputs JSON based on message data.
> +function StructuredFormatter() {
> +  this._counter = 0;

Why is a formatter keeping state? IMO a counter should be on the appender and/or the logger. It can then be attached to a message when said message is created.

Why do we need a counter in the first place?

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

Comment 11

[Gregory Szorc [:gps]]

Comment on attachment 772434 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 772434 [details] [diff] [review]:
-----------------------------------------------------------------

Performed some review IRL. New patch hopefully coming shortly.

::: services/common/log4moz.js
@@ +36,5 @@
>        20: "DEBUG",
>        10: "TRACE",
>        0:  "ALL"
> +    },
> +    Num: {

Nit: Please spell this out. Abbreviations hurt non-English speakers when they try to read our code.

@@ +131,5 @@
> +  if (this.params && this.params.action) {
> +    this._structured = true;
> +  } else {
> +    this._structured = false;
> +  }

Nit: You could also write this as:

this._structured == this.params && this.params.action;

Comment 12

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

Addresses nits and refrains from adding an 'UNKNOWN' field for structured
messages that do not include a message field.

Comment 13

[Gregory Szorc [:gps]]

Comment on attachment 774388 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 774388 [details] [diff] [review]:
-----------------------------------------------------------------

Almost there...

::: services/common/log4moz.js
@@ +244,5 @@
> +   *          at the indicated level.
> +   */
> +  logStructured: function (action, params) {
> +    if (!params) {
> +      return this.log(this.level, "UNKNOWN", {"action": action});

I think we should remove this "UNKNOWN." Let the formatter deal with a missing value.

Also, perhaps we should check for !action. Action is required, is it not?

@@ +248,5 @@
> +      return this.log(this.level, "UNKNOWN", {"action": action});
> +    }
> +
> +    let level = params._level || this.level;
> +    if ((typeof level === "string") && level in Log4Moz.Level.Numbers) {

No need for triple equals here. typeof always returns a string.

@@ +256,5 @@
> +    params.action = action;
> +    this.log(level, params._message, params);
> +  },
> +
> +  log: function Logger_log(level, string, params) {

Remove the function name since you touched this line.

::: services/common/tests/unit/test_log4moz.js
@@ +103,5 @@
> +
> +  logger.logStructured("test_message", {_message: "message string one"});
> +  logger.logStructured("test_message", {_message: "message string two",
> +                                        _level: "ERROR"});
> +  logger.logStructured("test_message", {_level: "ERROR"});

Please add a test that actually logs a non-internal/special field!

@@ +141,5 @@
> +  checkObjects(messageOne, JSON.parse(appender.messages[0]));
> +  checkObjects(messageTwo, JSON.parse(appender.messages[1]));
> +
> +  run_next_test();
> +});

Please add a test passing bad input into logStructured.

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Attachment: Implement structured output in Log4Moz;

Comment 15

[Gregory Szorc [:gps]]

Comment on attachment 775008 [details] [diff] [review]
Implement structured output in Log4Moz;

Review of attachment 775008 [details] [diff] [review]:
-----------------------------------------------------------------

https://hg.mozilla.org/integration/fx-team/rev/75a080f3f46e

Comment 16

[Gregory Szorc [:gps]]

Enjoy your weekend.

Comment 17

[Gregory Szorc [:gps]]

https://hg.mozilla.org/mozilla-central/rev/75a080f3f46e