Extended ConsoleLogger prints undefined on every log message

czioutas commented 8 months ago

Is there an existing issue for this?

[X] I have searched the existing issues

Current behavior

When extending the ConsoleLogger and then consuming the extended Logger class via injection we are seeing that the overridden methods log an extra line of just undefined.

Minimum reproduction code

https://github.com/czioutas/plauground

Steps to reproduce

yarn install
yarn start:dev
visit http://localhost:3000/
check console output

Expected behavior

When we are consuming the custom logger (AppLogger) via the AppController (or any service/controller) and executing the statement this.logger.log('some message' we expect only this message to be printed.

Expected output [Nest] 94728 - 02/15/2024, 11:45:36 AM LOG [AppController] some message

However we are seeing an extra line being logged as bellow [Nest] 94728 - 02/15/2024, 11:45:36 AM LOG [AppController] some message [Nest] 94728 - 02/15/2024, 11:45:36 AM LOG [AppController] undefined <--

Package

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

Other package

No response

NestJS version

^10.0.0

Packages versions

{
  "name": "playground",
  "version": "0.0.1",
  "description": "",
  "author": "",
  "private": true,
  "license": "UNLICENSED",
  "scripts": {
    "build": "nest build",
    "format": "prettier --write \"src/**/*.ts\" \"test/**/*.ts\"",
    "start": "PORT=9090 NODE_ENV=development nest start",
    "start:dev": "nest start --watch",
    "start:debug": "nest start --debug --watch",
    "start:prod": "node dist/main",
    "lint": "eslint \"{src,apps,libs,test}/**/*.ts\" --fix",
    "test": "jest",
    "test:watch": "jest --watch",
    "test:cov": "jest --coverage",
    "test:debug": "node --inspect-brk -r tsconfig-paths/register -r ts-node/register node_modules/.bin/jest --runInBand",
    "test:e2e": "jest --config ./test/jest-e2e.json"
  },
  "dependencies": {
    "@nestjs/common": "^10.0.0",
    "@nestjs/core": "^10.0.0",
    "@nestjs/platform-express": "^10.0.0",
    "nest-winston": "^1.9.4",
    "reflect-metadata": "^0.2.0",
    "rxjs": "^7.8.1",
    "winston": "^3.11.0"
  },
  "devDependencies": {
    "@nestjs/cli": "^10.0.0",
    "@nestjs/schematics": "^10.0.0",
    "@nestjs/testing": "^10.0.0",
    "@types/express": "^4.17.17",
    "@types/jest": "^29.5.2",
    "@types/node": "^20.3.1",
    "@types/supertest": "^6.0.0",
    "@typescript-eslint/eslint-plugin": "^6.0.0",
    "@typescript-eslint/parser": "^6.0.0",
    "eslint": "^8.42.0",
    "eslint-config-prettier": "^9.0.0",
    "eslint-plugin-prettier": "^5.0.0",
    "jest": "^29.5.0",
    "prettier": "^3.0.0",
    "source-map-support": "^0.5.21",
    "supertest": "^6.3.3",
    "ts-jest": "^29.1.0",
    "ts-loader": "^9.4.3",
    "ts-node": "^10.9.1",
    "tsconfig-paths": "^4.2.0",
    "typescript": "^5.1.3"
  },
  "jest": {
    "moduleFileExtensions": [
      "js",
      "json",
      "ts"
    ],
    "rootDir": "src",
    "testRegex": ".*\\.spec\\.ts$",
    "transform": {
      "^.+\\.(t|j)s$": "ts-jest"
    },
    "collectCoverageFrom": [
      "**/*.(t|j)s"
    ],
    "coverageDirectory": "../coverage",
    "testEnvironment": "node"
  }
}

Node.js version

v18.19.0

In which operating systems have you tested?

[X] macOS
[ ] Windows
[ ] Linux

Other

full output. We added a console.log for further debugging.

[Nest] 94728  - 02/15/2024, 11:38:40 AM     LOG [NestApplication] Nest application successfully started +1ms
error test undefined undefined
[Nest] 94728  - 02/15/2024, 11:45:36 AM   ERROR [AppController] error test
[Nest] 94728  - 02/15/2024, 11:45:36 AM   ERROR [AppController] undefined
I am a random test test undefined
[Nest] 94728  - 02/15/2024, 11:45:36 AM     LOG [AppController] I am a random test test
[Nest] 94728  - 02/15/2024, 11:45:36 AM     LOG [AppController] undefined

Other debugging attempts:

a) we tried to adapt the super.error function call to change the stack parameter as follows super.error(modifiedMessage, { "hey": "you" }, context); what we saw next is that it logged the message and then the object, so I cannot but I assume that undefined is coming from an undefined stack. Although I am not sure why it would print undefined.

b) if we do not pass context in super.log and only message then it does not print the context but also no undefined.

czioutas commented 8 months ago

I updated the reproduce repo with a logSafe function which essentially checks if context is undefined before sending it to super. I assumed that this functionality would be handled from the core logic. app-logger.service.ts

  logSafe(message: any, context?: string) {
    const modifiedMessage = `${message} test`;

    console.log(modifiedMessage, context);

    if (context === undefined) {
      super.log(modifiedMessage);
    } else {
      super.log(modifiedMessage, context);
    }
  }

kamilmysliwiec commented 8 months ago

https://github.com/nestjs/nest/blob/033f18161fb4d391aab0dac22f71209b97c94993/packages/common/services/console-logger.service.ts#L67-L78

Since log() method lets you pass multiple messages (separated by ,) to write to the stdout, second parameter won't necessarily represent a "context" (https://github.dev/nestjs/nest/blob/033f18161fb4d391aab0dac22f71209b97c94993/packages/common/services/console-logger.service.ts#L295) - that's why undefined is logged down too. While this may not be the most straightforward, we can't really do anything on our side without introducing a breaking change

nestjs / nest