Extra log fields are not logged to browser console

[dobesv]

When I do something like:

log.warn({foo: "bar"}, 'hello')

with ConsoleFormattedStream, the object fields are not shown in the JavaScript console.

I feel like this used to work, but not any more. Maybe they changed something in Chrome.

To reproduce, set up a browser-bunyan logger with ConsoleFormattedStream and try logging an object parameter in the latest version of Chrome, see if it shows the object or not.

[dobesv]

I also tried this in a current version of Firefox and got the same result, the extra fields are not printed.

[dobesv]

It looks like the formatter is expecting a field called obj in the message payload, but there is no such field.

[dobesv]

It looks like browser-bunyan has a very different API from node-bunyan in that it only logs the aditional fields if you nest them inside a field called obj.

It would be much preferred if instead it would construct an object itself with any fields it doesn't specifically handle and log that as the obj rather than requiring a field called obj as this would harmonize the logger usage between browser and node bunyan.

[dobesv]

Here's an example log stream implementation that does it this way:

import {
  TRACE,
  DEBUG,
  INFO,
  WARN,
  ERROR,
  FATAL,
} from '@browser-bunyan/levels';

const css = {
  levels: {
    trace: 'color: DeepPink',
    debug: 'color: GoldenRod',
    info: 'color: DarkTurquoise',
    warn: 'color: Purple',
    error: 'color: Crimson',
    fatal: 'color: Black',
  },
  def: 'color: DimGray',
  msg: 'color: SteelBlue',
  src: 'color: DimGray; font-style: italic; font-size: 0.9em',
};

export class ConsoleFormattedStream {
  write({
    childName,
    err,
    level,
    levelName,
    v,
    msg,
    name,
    src,
    time,
    ...extraFields
  }: Record<string, any>) {
    let levelCss, consoleMethod;
    const defaultCss = css.def;
    const msgCss = css.msg;
    const srcCss = css.src;

    const loggerName = childName ? name + '/' + childName : name;

    //get level name and pad start with spacs
    const formattedLevelName = (
      Array(6 - levelName.length).join(' ') + levelName
    ).toUpperCase();

    if (level === TRACE) {
      levelName = 'debug';
    } else if (level === FATAL) {
      levelName = 'error';
    }
    consoleMethod =
      typeof console[levelName as 'log' | 'error' | 'warn' | 'info'] ===
      'function'
        ? console[levelName as 'log' | 'error' | 'warn' | 'info']
        : console.log;

    if (level < DEBUG) {
      levelCss = css.levels.trace;
    } else if (level < INFO) {
      levelCss = css.levels.debug;
    } else if (level < WARN) {
      levelCss = css.levels.info;
    } else if (level < ERROR) {
      levelCss = css.levels.warn;
    } else if (level < FATAL) {
      levelCss = css.levels.error;
    } else {
      levelCss = css.levels.fatal;
    }

    const padZeros = (number: number, len: number) =>
      Array(len + 1 - (number + '').length).join('0') + number;

    const logArgs = [];
    // [time] level: loggerName: msg src?
    logArgs.push(`[%s:%s:%s:%s] %c%s%c: %s: %c%s ${src ? '%c%s' : ''}`);
    logArgs.push(padZeros(time.getHours(), 2));
    logArgs.push(padZeros(time.getMinutes(), 2));
    logArgs.push(padZeros(time.getSeconds(), 2));
    logArgs.push(padZeros(time.getMilliseconds(), 4));
    logArgs.push(levelCss);
    logArgs.push(formattedLevelName);
    logArgs.push(defaultCss);
    logArgs.push(loggerName);
    logArgs.push(msgCss);
    logArgs.push(msg);
    if (src) {
      logArgs.push(srcCss);
      logArgs.push(src);
    }
    if (Object.keys(extraFields).length) {
      logArgs.push('\n');
      logArgs.push(extraFields);
    }
    if (err && err.stack) {
      logArgs.push('\n');
      logArgs.push(err.stack);
    }
    consoleMethod.apply(console, logArgs);
  }
}

[philmander]

Hi @dobesv

Thanks for the feedback.

Just to break this down into two parts:

Firstly, the behavior for logging objects does deviate a little from Node Bunyan in that you have to use the obj field. That is documented here: https://github.com/philmander/browser-bunyan#logging-objects-to-the-console .

It's a while since I wrote that, but I think the rationale must have been to prevent the likelihood of conflicts with nested fields that should be serialized, like err. This is mentioned in the Node Bunyan docs here (the bit about best practice and dove-tailing with serializers). I guess I could take a fresh look at this and support logging of anything – just need to be sure I'm not overlooking something.

Secondly, I notice that where the value is a string, with the standard Node Bunyan pretty output, this statement:

logger.info({foo: 'bar' }, 'hi')

results in:

[2023-04-07T11:30:59.810Z] INFO: blah on Philips-MacBook-Air.local: hi (env=development, source=server, foo=bar)

...and I don't think this is handled like this in the built-in streams. So I'm happy to add that.

Of course, as a workaround, you can create your own streams which can give you the exact behavior you are looking for.