Winston: 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