Logger Error function in Nestjs causing duplication

[Karman40]

Is there an existing issue for this?

• I have searched the existing issues

Current behavior

I am encountering an issue with the logger.error function. Whenever I use the logger.error function, it correctly logs the message, but immediately after that, there is another log which says undefined.

The error is solved if I change error to warn or something else.

export class QueueNavService {
  private logger = new Logger(QueueNavService.name);

  ...

  // undefined log
  this.logger.error(`ERROR: ${QUEUE.NAV.NAME} / ${QUEUE.NAV.InvoiceDigest.NAME} / ${id}`);
  console.log('TEST MESSAGE')

  // good
  this.logger.warn(`ERROR: ${QUEUE.NAV.NAME} / ${QUEUE.NAV.InvoiceDigest.NAME} / ${id}`);
  console.log('TEST MESSAGE')
}

Minimum reproduction code

https://github.com/nestjs/nest

Steps to reproduce

No response

Expected behavior

I expect the logger.error function to correctly log the message without any subsequent log containing the undefined message. The message should be unique and accurate, without duplication.

Package

• I don't know. Or some 3rd-party package
• @nestjs/common
• @nestjs/core
• @nestjs/microservices
• @nestjs/platform-express
• @nestjs/platform-fastify
• @nestjs/platform-socket.io
• @nestjs/platform-ws
• @nestjs/testing
• @nestjs/websockets
• Other (see below)

Other package

No response

NestJS version

9.3.2

Packages versions

 _   _             _      ___  _____  _____  _     _____
| \ | |           | |    |_  |/  ___|/  __ \| |   |_   _|
|  \| |  ___  ___ | |_     | |\ `--. | /  \/| |     | |
| . ` | / _ \/ __|| __|    | | `--. \| |    | |     | |
| |\  ||  __/\__ \| |_ /\__/ //\__/ /| \__/\| |_____| |_
\_| \_/ \___||___/ \__|\____/ \____/  \____/\_____/\___/


[System Information]
OS Version     : Windows 10
NodeJS Version : v18.12.1
NPM Version    : 8.19.2 

[Nest CLI]
Nest CLI Version : 9.2.0

[Nest Platform Information]
platform-socket.io version : 9.3.2
platform-express version   : 9.3.2
websockets version         : 9.3.2
schematics version         : 9.0.4
throttler version          : 4.0.0
mongoose version           : 9.2.1
schedule version           : 2.2.0
testing version            : 9.3.2
common version             : 9.3.2
config version             : 2.3.0
axios version              : 2.0.0
bull version               : 0.6.2
core version               : 9.3.2
cli version                : 9.2.0

Node.js version

No response

In which operating systems have you tested?

• macOS
• Windows
• Linux

Other

No response

[micalevisk]

does that happen in v9.2 as well?

[Karman40]

@micalevisk no.

 _   _             _      ___  _____  _____  _     _____
| \ | |           | |    |_  |/  ___|/  __ \| |   |_   _|
|  \| |  ___  ___ | |_     | |\ `--. | /  \/| |     | |
| . ` | / _ \/ __|| __|    | | `--. \| |    | |     | |
| |\  ||  __/\__ \| |_ /\__/ //\__/ /| \__/\| |_____| |_
\_| \_/ \___||___/ \__|\____/ \____/  \____/\_____/\___/


[System Information]
OS Version     : Windows 10
NodeJS Version : v18.12.1
NPM Version    : 8.19.2 

[Nest CLI]
Nest CLI Version : 9.1.5

[Nest Platform Information]
platform-socket.io version : 9.2.1
platform-express version   : 9.2.1
websockets version         : 9.2.1
schematics version         : 9.0.3
throttler version          : 3.1.0
mongoose version           : 9.2.1
schedule version           : 2.1.0
testing version            : 9.2.1
common version             : 9.2.1
config version             : 2.2.0
axios version              : 1.0.1
bull version               : 0.6.2
core version               : 9.2.1
cli version                : 9.1.5

[micalevisk]

the reproduction:

I just reverted the changes made at #10531 (v9.3.0) and it start working as before again.

[jmcdo29]

Thank you for linking the PR @micalevisk. The reason this is happening is because when this.context is set (by calling new Logger('something')) then the optionalParameters becomes [undefined, this.context]. Later, Nest gets the last object of the optionalParameters array and checks isString() on it. If it is then we return an object like

{
	context: args[args.length -1]
    messages: args.splice(0, args.length-2)
}

Essentially returning

{
	context: AppService,
	messages: ['foo bar error', undefined]
}

https://github.com/nestjs/nest/blob/master/packages/common/services/console-logger.service.ts#L275

Then, we check for the stack trace from the messages by getting the last element there. If that element is a string (which it no longer is) then that's the stack trace, otherwise return messages as is.

Then in our printMessage method we loop over all the messages and write out the formatted log(s), in this case, the logs for 'foo bar error' and undefined.https://github.com/nestjs/nest/blob/master/packages/common/services/console-logger.service.ts#L177

Looks like we need to account for the undefined somehow without possibly interfering with this.logger.log(undefined) itself.

[jmcdo29]

I'm working on a fix for this at the moment. Gonna update the tests too to make sure we've got it right

[jmcdo29]

Okay. Let's track this here: #11081