Support for implicit contextual parameters

[rraziel]

I'm submitting a...

[ ] Regression (a behavior that used to work and stopped working in a new release)
[ ] Bug report
[ ] Performance issue
[x] Feature request
[ ] Documentation issue or request
[ ] Support request
[ ] Other... Please describe:

Current behavior

The logger requires explicit parameters.

Expected behavior

Having the ability for logs to be augmented with implicit contextual information, e.g.:

interface ContextualInformationResolver {
  resolveContextualInformation(): Promise<Record<string, unknown>>;
}

@Injectable({
  providedIn: 'root'
})
class MyContextualInformationResolver implements ContextualInformationResolver {
  async resolveContextualInformation(): Promise<Record<string, unknown>> {
    return {
      // context
    };
  }
}

The contextual information would not used in the log message itself but rather as a separate context (that could still be used when formatting the log though, just like a timestamp).

Minimal reproduction of the problem with instructions

n/a

What is the motivation / use case for changing the behavior?

There is often information that would be useful to see with a log message but is not readily available where the message is logged (not to mention it could lose some of its structure if passed in the message itself).

Typical use cases would be:

• a correlation identifier
• a span/parent identifier
• (not relevant if the library is only used on the front-end) a user identifier, a tenant identifier, etc.

This can make it much easier to filter logs based on such information without having to pass it manually each time a log is created in the user code.

Some examples:

• Node implementation (using continuation local storage)
• Logback (JVM logger implementation, using thread local storage)

Moreover, most protocols/tools related to logging support passing such contextual information (e.g. Logstash, Kibana, etc.).

Environment

n/a

[LayZeeDK]

Thanks for your suggestion, @rraziel.

Do you imagine such a resolver to be called for each log entry? If so, we would lose the ability to log synchronously. We really don't want our log API to become a bottleneck, blocking the rest of the app.

If we buffered log messages to keep a synchronous API and resolved the context asynchronously, the context would be gone before we could resolve it.

[rraziel]

I made it return a Promise in the example but that's mostly because... habits 😅
I'm pretty sure a synchronous resolver would work for 99.9% of use cases.

But yes it would be called for each log entry.

In most other libraries that have something similar, the resolver is done when logging - otherwise you'd indeed no longer have access to the information needed anyway - but then the built "full" log message (message, parameters, context, timestamp, etc) are put in a buffer/queue.

Actually, going even further than the no-need-for-asynchronous-resolver, it probably wouldn't any difference (when it comes to real world scenarios) if it was a simple Map<string, unknown>-like API exposed by the library.

This way the user code is limited to setting values (no possibly expensive computation from the resolver) and the library knows when the values change if that's something useful (such as avoiding copies).

[LayZeeDK]

I actually don't understand what the Record or Map is for. Is it mapping over correlation ID -> context?

Could you explain your last two paragraphs more in detail?

[rraziel]

The basic idea:

function main() {
  logger.set('correlationId', uuid());
  logger.set('userId', 'abcd');
  logger.log('hello world'); // { message: 'hello world', context: { 'correlationId', 'xx', 'userId': 'abcd' } }
  logger.log('hello again'); // { message: 'hello again', context: { 'correlationId', 'xx', 'userId': 'abcd' } }
}

Here the example is fairly self-explanatory I think: you get a contextual map of data you don't need to know about when logging a message, I'm pretty sure that part was understood already.

Now in classical multi-threaded, synchronous code (i.e. not the browser or Node), that logger.set() would use thread-local storage: each thread gets its own independent version of the contextual map, and when a message is logged it will automatically pick the "right" contextual map based on the current thread.

So for example when handling requests:

let counter = 0;
function onRequest() {
  logger.set('correlationId', ++counter);
  doSomething();
  logger.log('hello');
}

You won't have issues with concurrent requests because, even though they may be running in parallel, logger.set() will save the value using a thread-local map rather than global, so in practice you have no issue, e.g.:

1. [req1] enters the function
2. [req1] logger.set, which is bound to thread-1
3. [req1] doSomething()
4. [req2] enters the function
5. [req2] logger.set, which is bound to thread-2 (so it does not override the value in thread-1)
6. [req2] doSomething()
7. [req1] doSomething() has returned, logger.log logs a message that will use the map from thread-1
8. [req2] doSomething() has returned, logger.log logs a message that will use the map from thread-2

{ "message": "hello", "context": { "correlationId", 1 } }
{ "message": "hello", "context": { "correlationId", 2 } }

Now the same example with asynchronous code and a single thread:

let counter = 0;
async function onRequest() {
  logger.set('correlationId', ++counter);
  await doSomething();
  logger.log('hello');
}

If two requests arrive at roughly the same time, you will eventually override the context value and pick the "wrong" (or latest) value instead when logging, e.g.:

1. [req1] enters the function
2. [req1] logger.set, which is global (or local to the logger, does not really make a difference)
3. [req1] doSomething()
4. [req2] enters the function
5. [req2] logger.set, which is global and thus overrides the one done on step 2
6. [req2] doSomething()
7. [req1] doSomething() has returned, logger.log logs a message that will use the global map (so the 2nd set)
8. [req2] doSoemthing() has returned, logger.log logs a message that will use the global map (so the 2nd set)

{ "message": "hello", "context": { "correlationId", 2 } }
{ "message": "hello", "context": { "correlationId", 2 } }

One way around this is to use continuation local storage, which will basically bind the contextual map to the sequence of asynchronous calls, so when you log something it'll pick the "right" context map.

I hope that's a bit clearer.

[LayZeeDK]

Thank you for your explanation, @rraziel.

Please feel free to continue improving API drafts and possible solutions for this proposal. I was thinking about something like this for being able to integrate a log driver with Azure Application Insights.

[LayZeeDK]

Hi @rraziel,

We have added the option to attach log payloads with application- or log driver-defined properties in Lumberjack version 2 (currrently at 2.0.0-rc.0). We added LumberjackLogger and ScopedLumberjackLogger as well as LumberjackLogBuilder to make it easier to add a log payload and other log properties.

What do you think? Can this be used to do what you're asking for?

[rraziel]

Ahoy,

I think it helps for the lower-level part (i.e. drivers being able to forward that information to wherever they're storing/sending it) and for some cases where you want to send structured data with a log message, although those tend to have a schema per log message rather than a global one.

But for contextual information from user-land, it'd still require passing the information in every single message, whereas above I mentioned a context that could be set on the logger and attached to all logged messages:

logger.set('userId', '1234');
logger.set('siteId', '5678');
logger.set('spanId', '9abc');
logger.set('parentSpanId', 'def0');

logger.log('x'); // also logs the userId/siteId/etc

The tricky part being asynchronous behavior potentially changing that contextual information while using the same logger.

[LayZeeDK]

The log payload is not necessarily meant to have a global interface across the application. Loggers--that is services extending LumberjackLogger or ScopedLumberjackLogger--can have a static payload defined at logger method creation time or resolve payloads dynamically at log creation time as they have access to dependency injection to retrieve this information.

The LumberjackService is even more low level and can be combined with the LumberjackLogBuilder so it should be possible to fit services to your need. Let us know if you do experiments with any of this. We'll be happy to give feedback.