Request: Functions in Default Metadata

[kjin]

The underlying issue here is somewhat complex so I'll summarize what we're asking for up here -- we would be interested in seeing the ability for defaultMetadata to include dynamically generated values by providing a function as a field. For example:

const logger = createLogger({
  defaultMeta: {
    // Function to be evaluated every time a log is written.
    timeWritten: () => { return `Date.now()`; }
  },
  // ...
});

For a full justification see below.

Please tell us about your environment:

• winston version?
  • [ ] winston@2
  • [x] winston@3
• node -v outputs: v10.15.2
• Operating System? macOS (irrelevant)
• Language? ES7 (irrelevant)

What is the problem?

As authors of the Stackdriver Logging Transport for Winston, we would like to support log-request correlation. The async_hooks module gives us the ability to store request-specific information such as a request ID. However, we don't have a means of reliably retrieving it on the Transport side.

The problem is best described by example. The following code produces this output when ~100 requests are made in quick succession:

const ah = require('async_hooks');
const express = require('express');
const { createLogger } = require('winston');
const TransportStream = require('winston-transport');

// Activate async hooks.
let requestIdHighWater = 0;
const requestIdTable = {};
ah.createHook({
  init: (child, resource, parent) => {
    requestIdTable[child] = requestIdTable[parent];
  }
}).enable();

// OUR CODE

class MyTransport extends TransportStream {
  log(info, next) {
    // From the transport, the request ID is not reliable.
    const actualRequestId = requestIdTable[ah.executionAsyncId()];
    console.log(`Expected: ${info.expectedRequestId}, Actual: ${actualRequestId}`);
    setImmediate(next);
  }
}

// OUR USER'S CODE

const logger = createLogger({
  transports: [new MyTransport()]
});

const app = express();

app.get('/', async (req, res) => {
  // Store a request ID.
  const requestId = requestIdHighWater++;
  requestIdTable[ah.executionAsyncId()] = requestId;
  logger.info('hello', { expectedRequestId: requestId });
  res.sendStatus(200);
});

app.listen(3000);

Note the mistmatch in "expected" and "actual" request IDs. If we are the author of MyTransport, we would have no way of accurately getting the correct request ID by consulting the current execution ID ("actual"). Instead, we must rely on the user passing in the correct request ID as metadata ("expected"). This is because Winston 3 batches logs (via readable-stream) when a Transport defers its invocation of its log callback.

The problem is that we don't want to rely on users passing in a request ID for us; we want it to happen automatically. After all, users would probably want to just write

app.get('/', async (req, res) => {
  logger.info('hello');
  res.sendStatus(200);
});

and leave to rest up to us.

What do you expect to happen instead?

The expected and actual request IDs (from the linked output) match up.

Other information

It's infeasible to fix the code so that actual request IDs match up, so a solution to this problem would be to allow users to specify functions as fields on defaultMetadata that get invoked when the logger gets called. That way, the code would change to this, which allows users to write their code without any awareness of request ID, with the small caveat that they provide a thunk as a defaultMetadata field (that maybe our module would provide for them to use).

[ofrobots]

so a solution to this problem would be to allow users to specify functions as fields on defaultMetadata

I was thinking that this could be implemented similar to redux thunks. Instead of having a function-valued property in defaultMetadata, was thinking that defaultMetadata itself could be a optionally a function. Like a thunk, winston would use the value returned by invoking defaultMetadata in such a case. In other words:

const logger = createLogger({
  defaultMeta: () => {
    // Function to be evaluated every time a log is written.
    return {
       timeWritten: Date.now();
       // ..
    }
  }
  // ...
});

[Alexsey]

I have found a workaround that can be used until the proposed solution would be implemented - use getters:

const logger = createLogger({
  defaultMeta: {
    get timeWritten () { return `Date.now()`; }
  },
  // ...
});

UPD: fixed the bug mentioned by @mooski

[mooski]

~Great solution @Alexsey - for anyone using this code just be aware that the colon after timeWritten shouldn't be there.~

Update: fixed by @Alexsey

[maverick1872]

@kjin If I'm understanding this issue correctly it appears that this is a feature request. Is that correct?

Edit: Ignore me - didn't pay attention to issue title 😩

[intentionally-left-nil]

I still think that winston needs some code changes to support this feature properly, even with using the getter syntax.

The getters are captured/realized at different places depending on the codepath. This is important because the callstack is something that a logger might want to log & the frames are inconsistent.

I've fixed this in our fork by replacing Object.assign with the following function:

function assignWithGetters(target, ...sources) {
  // eslint-disable-next-line no-shadow
  return sources.reduce((target, source) => {
    // eslint-disable-next-line eqeqeq
    if (source != null) {
      const enumerableKeys = Object.keys(source);
      const symbolKeys = Object.getOwnPropertySymbols(source);
      // Don't use Reflect.ownKeys here because we only want to assign enumerable ones
      for (const key of enumerableKeys.concat(symbolKeys)) {
        Object.defineProperty(target, key, Object.getOwnPropertyDescriptor(source, key));
      }
    }
    return target;
  }, target);
}```
which preserves the getters when copying to the target, and then calling `Object.assign({}, msg)` in write() to consistently call the logger.

I can open a PR to address this if the maintainers feel that JS getters are the preferred approach here (rather than creating some new functionality for dynamic metadata)

[luiscabus]

@Alexsey solution is clever, but my use case is slightly special with New Relic and APM.

First, I notice it will forward the log before winston's format is called, decorating and adding more data to it using it's agent. I use express-http-context and was getting the req.id on the log formatter, while also adding other property there, but these new attributes never make it to newrelic.

Then I followed @Alexsey suggestion to add the request_id to the defaultMeta as a getter, but that didn't work, I first see a log with the request id, and the log gets to the vm/pm2 logs. But I believe when newrelic is forwarding it I see another log where Request ID: undefined.

So it get's called, but at that moment the context is lost =/.

get request_id() {
                    const requestId = httpContext.get('request_id')
                    console.warn('Request ID:', requestId) // Debug log
                    return httpContext.get('request_id') || 'unknown_request_id_' + uuidv4()
                },