Use safe-stable-stringify for perf and to support circular refs

[lancegliser]

The winston package updated it's stringification tool to fast-safe-stringify a while back at Jun 11, 2018.

I introduced here: #57. In it's PR I raised a this as a separate issue in one comment with notes. Pulling those in here for easy read:

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"}}

[trentm]

@lancegliser Thanks for your work here. I'm just coming back to this after ages. I understand if you don't want to engage again.

So Winston switched to fast-safe-stringify, then to safe-stable-stringify (winstonjs/logform#98) because it is faster/less-buggy. After a while you changed your PR back to using fast-json-stringify. Is there a reason for your changing back?

I am leaning towards changing away from fast-json-stringify to get the safety for JSON logging. Both pino and winston now using safe-stable-stringify, which is pretty good validation.

[lancegliser]

@trentm I'll admit to being way out of the loop. A quick look over the history doesn't ring a bell for me. I'm going to need to devote a bit of time... Booked some hours on Tuesday. Hope to get you an answer on if it's easy enough to just switch and merge.

[trentm]

I am leaning towards changing away from fast-json-stringify to get the safety for JSON logging. Both pino and winston now using safe-stable-stringify, which is pretty good validation.

I'll try to clarify what I said above. There are so many JSON.stringify-related packages that my head spins.

• Currently the ecs-logging-nodejs libs are using fast-json-stringify. It can be faster than others. However it does not protect against circular references. It is used by Fastify for its schema-based JSON HTTP response handlers. That makes sense there.
• I intend to switch the ecs-logging-nodejs libraries to use safe-stable-stringify because that library does provide protection against circular references (and also against possible issues serializing bigint usage). This safety is more appropriate for logging libraries, IMHO.

[lancegliser]

Not sure where to post the updates, but we'll continue here.

I created a repo you can use (with a little effort) to reproduce for testing: lancegliser/winston-ecs-redaction.
You'll have to update the package install location. It's probably not: "@elastic/ecs-winston-format": "file:../../trentm/ecs-logging-nodejs/loggers/winston/elastic-ecs-winston-format-1.0.0.tgz",

To test things out, you can src/server/logger.ts to swap between stringify functions:

const logger = winston.createLogger({
  // Uncomment to cause
  // { errors: [{ "message": "Converting circular structure to JSON\n    --> starting at object with constructor 'Socket'\n    |     property 'parser' -> object with constructor 'HTTPParser'\n    --- property 'socket' closes the circle", }} }
  format: format.combine(
    ecsFields({ convertReqRes: true }),
    new WinstonRedactFormatter({
      paths: ["http.request.headers.authorization"],
    }),
    // Keep uncommented to cause the error
    ecsStringify(),
    // Bypass the ecsStringify using winston standard json formatter to get success
    // format.json(),
  ),
});

To run api, use dev:watch.
You should able to then hit the sandbox at localhost:5000.

You can fire the following GraphQL query to hit the required code:

query SystemConfig {
  system {
    config {
      timestamp
    }
  }
}

You'll want to provide a header: "Authorization: FooBar" to test redaction as well.

That will fire the system.config method at src/components/system/system.resolvers.ts.
It makes a quick object that includes circular reference with the message "Reference object".

Example of message with ecsStringify:

{
  "@timestamp": "2023-10-11T02:23:08.331Z",
  "log.level": "error",
  "message": "Apollo.didEncounterErrors: :query SystemConfig {\n  system {\n    config {\n ...",
  "ecs": {
    "version": "1.6.0"
  },
  "event.kind": "event",
  "event.category": [
    "network",
    "web"
  ],
  "error.type": "GraphQLError",
  "error.message": "Converting circular structure to JSON\n    --> starting at object with constructor 'Socket'\n    |     property 'parser' -> object with constructor 'HTTPParser'\n    --- property 'socket' closes the circle",
  "error.stack_trace": "TypeError: Converting circular structure to JSON\n    --> starting at object with constructor 'Socket'\n    |     property 'parser' -> object with constructor 'HTTPParser'\n    --- property 'socket' closes the circle\n    at JSON.stringify (<anonymous>)\n    ...",
  "event.type": [
    "end",
    "allowed",
    "error"
  ],
  "event.reason": "Apollo.didEncounterErrors",
  "event.extras": {
    "request": {
      "query": "query SystemConfig {\n  system {\n    config {\n      timestamp\n    }\n  }\n}",
      "variables": [],
      "headers": {
        "host": "localhost:5000",
        "connection": "keep-alive",
        "content-length": "136",
        "sec-ch-ua": "\"Google Chrome\";v=\"117\", \"Not;A=Brand\";v=\"8\", \"Chromium\";v=\"117\"",
        "content-type": "application/json",
        "sec-ch-ua-mobile": "?0",
        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36",
        "sec-ch-ua-platform": "\"macOS\"",
        "accept": "*/*",
        "origin": "http://localhost:5000",
        "sec-fetch-site": "same-origin",
        "sec-fetch-mode": "cors",
        "sec-fetch-dest": "empty",
        "referer": "http://localhost:5000/",
        "accept-encoding": "gzip, deflate, br",
        "accept-language": "en-US,en;q=0.9,ru;q=0.8"
      }
    },
    "response": {
      "errors": [
        {
          "message": "Converting circular structure to JSON\n    --> starting at object with constructor 'Socket'\n    |     property 'parser' -> object with constructor 'HTTPParser'\n    --- property 'socket' closes the circle",
          "locations": [
            {
              "line": 3,
              "column": 5
            }
          ],
          "path": [
            "system",
            "config"
          ]
        }
      ]
    }
  },
  "event.duration": 2337285
}

Example using format.json() bypass:

{
  "@timestamp": "2023-10-11T02:23:44.681Z",
  "client": {
    "address": "::1",
    "ip": "::1",
    "port": 58656
  },
  "ecs": {
    "version": "1.6.0"
  },
  "http": {
    "request": {
      "body": {
        "bytes": 136
      },
      "headers": {
        "accept": "*/*",
        "accept-encoding": "gzip, deflate, br",
        "accept-language": "en-US,en;q=0.9,ru;q=0.8",
        "authorization": "[REDACTED]",
        "connection": "keep-alive",
        "content-length": "136",
        "content-type": "application/json",
        "host": "localhost:5000",
        "origin": "http://localhost:5000",
        "referer": "http://localhost:5000/",
        "sec-ch-ua": "\"Google Chrome\";v=\"117\", \"Not;A=Brand\";v=\"8\", \"Chromium\";v=\"117\"",
        "sec-ch-ua-mobile": "?0",
        "sec-ch-ua-platform": "\"macOS\"",
        "sec-fetch-dest": "empty",
        "sec-fetch-mode": "cors",
        "sec-fetch-site": "same-origin",
        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
      },
      "method": "POST"
    },
    "response": {
      "headers": {
        "access-control-allow-credentials": "true",
        "vary": "Origin",
        "x-powered-by": "Express"
      },
      "status_code": 200
    },
    "version": "1.1"
  },
  "log.level": "info",
  "message": "Reference objects",
  "object": {
    "value": {
      "value": {
        "_body": true,
        "_consuming": true,
        "_dumped": false,
        ...
      }
   }
}

The ability to get successful logging and output bypassing ecsStringify points to it as the issue. I think that brings us back full circle to this PR. @elastic/ecs-winston-format depends on @elastic/ecs-helpers": "^1.0.0 which depends on fast-json-stringify": "^2.4.1 which uses const build = require('fast-json-stringify').

I am leaning towards changing away from fast-json-stringify to get the safety for JSON logging. Both pino and winston now using safe-stable-stringify, which is pretty good validation.

Seeing the issue here with fast-json-stringify, that seems wise.
The bypass method I'm hooked into comes from winston export import format = logform.format; : logform's format.json does indeed use safe-stable-stringify.
It looks like that helper package just needs updated, and the branch we're testing with would work. Related question, why doesn't the helper just use the same winston.format export to do it's work? Seems like asking for trouble.

Feel free to test out my repo to help confirm!