Context is lost when logging errors

[floretan-ebot7]

While debugging while certain log entries were missing the context property, I found out that it seems that the context is lost when calling the .error() method. Here is some example code:

import { Injectable, Logger } from '@nestjs/common';

@Injectable()
export class MyService {
  private logger = new Logger(this.constructor.name);

  constructor() {
    this.logger.log('this is a test log')
    this.logger.error('this is a test error')
  }
}

Which gives this output with the json formatter:

{"context":"MyService","label":"application-platform-latency-tester","level":"info","message":"this is a test log"}
{"label":"application-platform-latency-tester","level":"error","message":"this is a test error","stack":["MyService"]}

As you can see, the first log entry is fine. The second log entry with the error is putting the context in the stack property.

With the same code, the default Nest logger keeps the context in the right place:

[Nest] 82543  - 06/05/2022, 17:37:30     LOG [MyService] this is a test log
[Nest] 82543  - 06/05/2022, 17:37:30   ERROR [MyService] this is a test error

[faithfulojebiyi]

Your logger.error takes three arguments
Logger.error(message: any, stack?: string, context?: string),
You only passed the message to add your stack and context pass in the next arguments

You should have something like this.logger.error('a test error', error.stack, MyService.name)

[gremo]

I'm sorry for the very late response, I'm quite busy recently with my personal and working life. I'll try to follow more this library that, honestly, went so far and has been used by many. Didn't expected that 😄

@faithfulojebiyi you seems more on the point than me, can i close this?

[faithfulojebiyi]

@gremo we could update the docs to help others out. if I also notice any other irregularities I'd let you know. let's be sure it fixed @floretan-ebot7 issue then you can close it

[gremo]

@faithfulojebiyi provide a PR to clarify the docs then?

[faithfulojebiyi]

@gremo PR done

[xunziheng]

Your logger.error takes three arguments Logger.error(message: any, stack?: string, context?: string), You only passed the message to add your stack and context pass in the next arguments

You should have something like this.logger.error('a test error', error.stack, MyService.name)

But he passed in the context parameter through the constructor when new Logger(), doesn't it work?

[abrindam]

@xunziheng is correct. This is a bug. The cause of this is that the NestJS Logger class is delegating the error() message to WinstonLogger, and in the case that a stack trace is not provided, it will invoke error() with only two arguments (message, context).

This is supported by the type definition (stack is an optional parameter) and should work. However, WinstonLogger is erroneously treating this invocation as (message, stack) as opposed to (message, context), so the context winds up in the stack trace instead.

In the case that WinstonLogger.error() is invoked with two arguments, the second argument should be treated as context and not as stack. This matches the expectation that NestJS has of its loggers.

[abrindam]

I should note that this is all caused by the fact that Logger.error(message: any, stack?: string, context?: string) is ambiguous at invocation time due the presence of multiple optional parameters of the same type (string). This is not nest-winston's fault; they are merely following the interface nest itself designed.

In fact, the current behavior is quite defensible given that in most languages, if you have multiple optional parameters, it is the last one that gets omitted first - this would result in (message, stack) consistent with the current implementation.

The problem is that nest itself, in what I would call a questionable decision, has decided that invoking this method with (string, string) means (message, context), not (message, stack). As much as I question this decision, I think this project must follow the lead here and change it's implementation.

[faithfulojebiyi]

You can check the docs https://github.com/gremo/nest-winston#logger-methods usage is explained there

[abrindam]

Opened a PR with a fix: #513

Since things were already ambiguous, the fix has its downsides. Feel free to accept or reject.

[abrindam]

@faithfulojebiyi I have absolutely read the documentation if it wasn't already clear. The issue isn't the documentation, it is that when you implement a logger that works with Nest, you need to follow Nest's rules. And you're not. It is totally legitimate usage to do that the OP has done, and nothing the documentation says will change that!

To be perfectly honest, I spent a good deal of time writing up a carefully considered explanation of what is wrong here and why it is wrong, and it is concerning to receive what basically amounts to a pre-recorded reply of "please read the documentation."

[gremo]

@abrindam I think we should go for the Nest-like behavior, that is following that rules:

• We should improve this: https://github.com/gremo/nest-winston#logger-methods and explain how the error function works right now and why it's "confusing" for a Nest user

... then:

• We should release 2.0 because this is a BC
• We should add small section "Upgrade" in the documentation, to explain hot to move to 2.x because this BC

Feel free to upgrade #513 to reflect this changes, thanks!

[invakid404]

I can confirm that @ChrisiPK's pull request fixed this for me! It works fine now in NestJS 9.3.1 🥳

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days.

[github-actions]

This issue was closed because it has been stalled for 7 days with no activity.