feat: separate winston ecsFormat to composable ecsFields and ecsStringify

[trentm]

The current winston usage is a single ecsFormat formatter that handles both (a) putting together the ECS fields and then (b) serializing that to JSON (along with ecs-logging's preference for some serialized field order).

const log = winston.createLogger({
    format: ecsFormat(<options>),

Splitting these two steps into separate winston formatters allows for some composability. For example, redacting sensitive info, as requested in #57.

const { ecsFields, ecsStringify } = require('@elastic/ecs-winston-format')
const log = winston.createLogger({
    format: winston.format.combine(
        ecsFields(<options>),
        // Add a custom formatter to redact fields here.
        ecsStringify()
    ),

Fixes: #57

TODO

• [ ] get @lancegliser to try this out
• [x] changelog entry
• [x] tests for the new exports
• [ ] update asciidoc docs
• [ ] perhaps publish a winston-redact-format package with the example one created

[apmmachine]

:green_heart: Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Build Cause: Pull request #65 updated

• Start Time: 2021-03-18T18:49:53.861+0000

• Duration: 8 min 8 sec

• Commit: 4f150c7a3b6920f0418bdf76b04990617a74157e

Trends :test_tube:

[lancegliser]

@trentm could you lay out the steps you'd like me take to test this out for you? I think I'd need to swap the current formatter out for your fork at trentm/winston-redact ? Then any specifics you'd like reviewed?

[trentm]

@lancegliser

1. Does it seem like a reasonable solution?
2. Yes, you'd need manually npm install from this branch. Something like:

% git clone -b trentm/winston-redact https://github.com/elastic/ecs-logging-nodejs.git
% npm install ./ecs-logging-nodejs/loggers/winston

then try it out in your code with something like:

        const { ecsFields, ecsStringify } = require('@elastic/ecs-winston-format')
        const log = winston.createLogger({
            format: winston.format.combine(
                ecsFields(<options>),
                // Add a custom formatter to redact fields here.
                ecsStringify()
            ),
            // ...

Perhaps using the winston redact formatter I wrote here: https://github.com/elastic/ecs-logging-nodejs/blob/trentm/winston-redact/loggers/winston/examples/redact-fields.js#L61-L79 (which requires npm install fast-redact).

Then try it out to see if that works for your case.

[lancegliser]

@trentm I got some testing in this morning. Your plan to use ecsFields with a custom redactor works well. Here's the Typescript I landed on in case you want it:

import winston, { LoggerOptions, Logger, format } from "winston";
// @ts-expect-error They don't publish types, but we also don't need them just to pass to format
import { ecsFields, ecsStringify } from "@elastic/ecs-winston-format";
import fastRedact, { redactFn, RedactOptions } from "fast-redact";

const defaultLevel = process.env.LOG_LEVEL || "debug";

interface WinstonRedactFormatterOptions {
  /**
   * An array of strings describe the location of keys per
   * https://github.com/davidmarkclements/fast-redact#paths--array
   */
  paths: string[];
  /**
   * The replacement value, by default "[REDACTED]"
   * Tip: use `censor: undefined` to have matching paths replaced with
   * `undefined` which, if you use a JSON log output format, will result in
   * matching paths being *removed*.
   */
  censor?: string;
}
class WinstonRedactFormatter {
  private readonly redact: redactFn;

  constructor(options: WinstonRedactFormatterOptions) {
    const fastRedactOpts: RedactOptions = {
      paths: options.paths,
      // This option tells fast-redact to just do the redactions in-place.
      // Leave serialization to a separate Winston formatter.
      serialize: false,
    };
    if ("censor" in options) {
      fastRedactOpts.censor = options.censor;
    }
    this.redact = fastRedact(fastRedactOpts);
  }

  transform(info: any) {
    this.redact(info);
    return info;
  }
}

export const defaultOptions: LoggerOptions = {
  exitOnError: false,
  level: defaultLevel,
  format: format.combine(
    ecsFields({ convertReqRes: true }),
    new WinstonRedactFormatter({
      paths: ["http.request.headers.authorization"],
    }),
    ecsStringify()
  ),
  transports: [new winston.transports.Console()],
};

export default winston.createLogger(defaultOptions);

However I run into a different issue. When I attempt to use req and res as part of the formatting meta data I get a new error: Sample express controller method:

  public async logging(req: Request, res: Response) {
    logger.info("Log endpoint activated", {
      req,
      res,
      labels: {
        transactionId: res.locals?.transactionId,
      },
    });
  }

Result: TypeError: Converting circular structure to JSON --> starting at object with constructor 'Socket' | property '_writableState' -> object with constructor 'WritableState' | property 'afterWriteTickInfo' -> object with constructor 'Object' --- property 'stream' closes the circle

at JSON.stringify (<anonymous>)
at $main (eval at build (express-common/node_modules/fast-json-stringify/index.js:162:20), <anonymous>:345:51)
at Format.ecsStringifyTransform [as transform] (express-common/ecs-logging-nodejs/loggers/winston/index.js:149:19)

I tracked the cause down to:

function ecsStringifyTransform (info, opts) {
  info[MESSAGE] = stringify(info)
  return info
}

Where info contains Symbol(splat) which is {req: IncomingMessage, res: ServerResponse, labels: Object}, but there's a circular piece inside the req at several places because that's just Express. A little research showed me Use fast-safe-stringify for perf and to support circular refs #35 in winstonjs/winston changed their internal serialization agent to handle circular structure by moving to fast-safe-stringify. I checked the common helpers in this package and it looks like you're still using fast-json-stringify. Maybe that's somehow responsible for the difference?

A quick test swapping:

export const defaultOptions: LoggerOptions = {
  exitOnError: false,
  level: defaultLevel,
  format: format.combine(
    ecsFields({ convertReqRes: true }),
    new WinstonRedactFormatter({
      paths: ["http.request.headers.authorization"],
    }),
    // ecsStringify() // Bypass the ecsStringify
   format.json() // Use the winston standard json formatter
  ),
  transports: [new winston.transports.Console()],
};

Did indeed serial manage to output the correct format to the transporter: {"labels":{"transactionId":"0c91f790-8083-44da-ac4d-91eedb51a130"},"message":"Log endpoint activated","@timestamp":"2021-04-08T14:49:59.724Z","log.level":"error","ecs":{"version":"1.6.0"},"http":{"version":"1.1","request":{"method":"GET","headers":{"host":"127.0.0.1:62723","accept-encoding":"gzip, deflate","user-agent":"node-superagent/3.8.3","authorization":"[REDACTED]","connection":"close"}},"response":{"status_code":200,"headers":{"x-powered-by":"Express","access-control-allow-origin":"*"}}},"url":{"full":"http://127.0.0.1:62723/logging-info","path":"/logging-info","domain":"127.0.0.1"},"client":{"address":"::ffff:127.0.0.1","ip":"::ffff:127.0.0.1","port":62724},"user_agent":{"original":"node-superagent/3.8.3"}}

[fidgi]

Hi @trentm , when do you plan to publish a version with this improvment ?

[trentm]

Closed in favour of https://github.com/elastic/ecs-logging-nodejs/pull/161