Nest: Custom Logger service not working as expected

[ervitis]

I'm submitting a...

[ ] Regression 
[X] Bug report
[ ] Feature request
[ ] Documentation issue or request
[ ] Support request => Please do not submit support request here, instead post your question on Stack Overflow.

Current behavior

• It doesn't print on console the message you send to the custom log function.
• The logger is always calling the log function inside the custom logger class. Also it doesn't print the message.

Expected behavior

Use the custom logger.

Minimal reproduction of the problem with instructions

Implement the following custom logger inside a project (I am using the cqrs project as an example):

logger.module.ts

import * as winston from 'winston'
import {Component, Logger, LoggerService} from '@nestjs/common';
import {DateTime} from 'luxon'

@Component()
export class MyLogger extends winston.Logger implements LoggerService {
    private winston

    constructor() {
        super()
        this.winston = new winston.Logger({
            transports: [
                new winston.transports.Console({
                    json: true,
                    colorize: true,
                    label: 'GameService',
                    timestamp: () => DateTime.local().toString(),
                    formatter: options => `${options.timestamp()} [${options.level.toUpperCase()}] ${options.label} - ${options.message}`,
                }),
            ],
        })
    }

    error(message: string, trace: string) {
        this.winston.log({
            level: 'error',
            message
        })
    }

    log(message: string) {
        this.winston.log({
            level: 'warn',
            message,
        })
    }

    warn(message: string) {
        this.winston.log({level: 'warn', message})
    }

    info(message: string) {
        this.winston.log({
            level: 'info',
            message
        })
    }
}

Then, in the heroes.module.ts import it:

import { CommandBus, EventBus, CQRSModule } from '@nestjs/cqrs'
import { ModuleRef } from '@nestjs/core'
import { HeroesGameController } from './heroes.controller';
import {Module, OnModuleInit} from '@nestjs/common';
import {HeroesGameService} from './heroes.service';
import {HeroesGameSagas} from './sagas/heroes.sagas';
import {CommandHandlers} from './commands/handlers';
import {EventHandlers} from './events/handlers';
import {HeroRepository} from './repository/hero.repository';
import {MyLogger} from './middlewares/logger/logger.module';

@Module({
    modules: [CQRSModule],
    controllers: [HeroesGameController],
    components: [
        HeroesGameService,
        HeroesGameSagas,
        ...CommandHandlers,
        ...EventHandlers,
        HeroRepository,
        MyLogger,
    ],
    exports: [MyLogger],
})
export class HeroesGameModule implements OnModuleInit {
    constructor(
        private readonly moduleRef: ModuleRef,
        private readonly command$: CommandBus,
        private readonly event$: EventBus,
        private readonly heroesGameSagas: HeroesGameSagas,
        private logger: MyLogger,
    ) {}

    onModuleInit() {
        this.command$.setModuleRef(this.moduleRef)
        this.event$.setModuleRef(this.moduleRef)

        this.event$.register(EventHandlers)
        this.command$.register(CommandHandlers)
        this.event$.combineSagas([this.heroesGameSagas.dragonKilled])
    }
}

I have tried adding it in the bootstrap function in main.ts

import { NestFactory } from '@nestjs/core';
import { ApplicationModule } from './app.module';
import {MyLogger} from './cqrs/modules/heroes/middlewares/logger/logger.module';

async function bootstrap() {
    const app = await NestFactory.create(ApplicationModule, {
        logger: new MyLogger(),
    })
    await app.listen(3000);
}
bootstrap();

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

We need to use our custom injectable logger.

Environment

Nest version: 4.6.5


For Tooling issues:
- Node version: v8.10.0
- Platform:  Linux xUbuntu 64bit 17.10

Another things

Related from: https://github.com/nestjs/nest/issues/247, https://github.com/nestjs/nest/issues/435

I think I am doing something wrong, so if you don't mind writing a little example please.

Thank you so much.

[cojack]

@ervitis did you try to use my example of winston logger implementation at #435?

[ervitis]

@cojack yep, that's right

[kamilmysliwiec]

@ervitis what's wrong with #435?

[shekohex]

Hmm, in my Daily projects I used to use my own logger, which i'd love to share it
it's fairly simple, and easy to use.

// logger.service.ts

import * as winston from 'winston';
import * as chalk from 'chalk';
import * as PrettyError from 'pretty-error'; // it's really handy to make your life easier
import { Env } from '@shared/utils'; // using typescript paths, you know !
import { LoggerInstance, LoggerOptions, Transport } from 'winston';

export class LoggerService {
  private readonly logger: LoggerInstance;
  private readonly prettyError = new PrettyError();
  public static loggerOptions: LoggerOptions = {
    transports: [
      new winston.transports.File({
        filename: Env('LOG_FILE', 'app.dev.log'), // i will explain this later
        json: true,
        prettyPrint: true,
        timestamp: true,
      }),
    ],
  };
  constructor(private context: string, transport?) {
    this.logger = (winston as any).createLogger(LoggerService.loggerOptions);
    this.prettyError.skipNodeFiles();
    this.prettyError.skipPackage('express', '@nestjs/common', '@nestjs/core');
  }
  get Logger(): LoggerInstance {
    return this.logger; // idk why i have this in my code !
  }
  static configGlobal(options?: LoggerOptions) {
    this.loggerOptions = options; 
  }
  log(message: string): void {
    const currentDate = new Date();
    this.logger.info(message, {
      timestamp: currentDate.toISOString(),
      context: this.context,
    });
    this.formatedLog('info', message);
  }
  error(message: string, trace?: any): void {
    const currentDate = new Date();
    // i think the trace should be JSON Stringified 
    this.logger.error(`${message} -> (${trace || 'trace not provided !'})`, {
      timestamp: currentDate.toISOString(),
      context: this.context,
    });
    this.formatedLog('error', message, trace);
  }
  warn(message: string): void {
    const currentDate = new Date();
    this.logger.warn(message, {
      timestamp: currentDate.toISOString(),
      context: this.context,
    });
    this.formatedLog('warn', message);
  }
  overrideOptions(options: LoggerOptions) {
    this.logger.configure(options);
  }
  // this method just for printing a cool log in your terminal , using chalk
  private formatedLog(level: string, message: string, error?): void {
    let result = '';
    const color = chalk.default;
    const currentDate = new Date();
    const time = `${currentDate.getHours()}:${currentDate.getMinutes()}:${currentDate.getSeconds()}`;

    switch (level) {
      case 'info':
        result = `[${color.blue('INFO')}] ${color.dim.yellow.bold.underline(time)} [${color.green(
          this.context,
        )}] ${message}`;
        break;
      case 'error':
        result = `[${color.red('ERR')}] ${color.dim.yellow.bold.underline(time)} [${color.green(
          this.context,
        )}] ${message}`;
        if (error && Env('NODE_ENV') === 'dev') this.prettyError.render(error, true);
        break;
      case 'warn':
        result = `[${color.yellow('WARN')}] ${color.dim.yellow.bold.underline(time)} [${color.green(
          this.context,
        )}] ${message}`;
        break;
      default:
        break;
    }
    console.log(result);
  }
}

I used to have a utils folder in my shared module, it helps me alot in my projects.

// env.util.ts
import { config } from 'dotenv';
import { isNil } from './shared.util';
declare const process: { // nevermind 
  env: {
    [key: string]: string;
  };
};
config(); // load .env file
// Get an env value by key
export const Env = (key: string, fallback: any = null) => {
  return isNil(process.env[key]) ? fallback : process.env[key];
};

in your bootstrap function

// main.ts
import { LoggerService } from '@shared/services';

const app = await NestFactory.create(AppModule, {
    logger: new LoggerService('Main'), // Main here is just the context
  });

and finally you can use it everywhere.

...
import { LoggerService } from '@shared/services';
@Controller('auth')
export class AuthController {
  private readonly logger: LoggerService = new LoggerService(AuthController.name);
  ...
  @Post('login')
  async login(@Body('mobileNumber') mobileNumber: string): Promise<any> {
    this.logger.log('logging in...');
    return await this.authService.loginByMobileNumber(mobileNumber);
  }
...
}

Here is how it looks like :smiley:

Anyway, it's easy to implement your own.
Hope this helped.

[ervitis]

@shekohex thank you! I will try it later. So you didn't need to call the interface LoginService like it was in the example from #435

[shekohex]

@ervitis , Yes you don't, I don't even know how or why, since you should, * maybe because it has the same signature ?*
but nevermind, it works :smile_cat:

[ervitis]

@shekohex Thank you so much for your example I could managed to write my little LoggingService, it helped me a lot with it:

So here is my logger.module.ts:

import * as winston from 'winston'
import { LoggerInstance, Logger } from 'winston'
import { DateTime } from 'luxon'

export class MyLoggerService {
    private readonly logger: LoggerInstance

    constructor(private context: string) {
        this.logger = new winston.Logger({
            transports: [
                new winston.transports.Console({
                    json: true,
                    timestamp: () => DateTime.local().toString(),
                    formatter: options => `${options.message}`,
                }),
            ],
        })
    }

    error(message: string, trace?: string) {
        this.logger.error(message, {
            context: this.context,
        })
    }

    log(message: string) {
        this.logger.log(message, {context: this.context})
    }

    warn(message: string) {
        this.logger.warn(message, {context: this.context})
    }

    info(message: string) {
        this.logger.info(message, {context: this.context})
    }
}

The file heroes.module.ts

import {Module, OnModuleInit} from '@nestjs/common';
import {HeroesGameService} from './heroes.service';
import {HeroesGameSagas} from './sagas/heroes.sagas';
import {CommandHandlers} from './commands/handlers';
import {EventHandlers} from './events/handlers';
import {HeroRepository} from './repository/hero.repository';

@Module({
    modules: [CQRSModule],
    controllers: [HeroesGameController],
    components: [
        HeroesGameService,
        HeroesGameSagas,
        ...CommandHandlers,
        ...EventHandlers,
        HeroRepository,
    ],
})
export class HeroesGameModule implements OnModuleInit {
    constructor(
        private readonly moduleRef: ModuleRef,
        private readonly command$: CommandBus,
        private readonly event$: EventBus,
        private readonly heroesGameSagas: HeroesGameSagas,
    ) {}

    onModuleInit() {
        this.command$.setModuleRef(this.moduleRef)
        this.event$.setModuleRef(this.moduleRef)

        this.event$.register(EventHandlers)
        this.command$.register(CommandHandlers)
        this.event$.combineSagas([this.heroesGameSagas.dragonKilled])
    }
}

And then to use it, for example inside the file kill-dragon.handler.ts:

import {CommandHandler, EventPublisher, ICommandHandler} from '@nestjs/cqrs';
import {KillDragonCommand} from '../impl/kill-dragon.command';
import {HeroRepository} from '../../repository/hero.repository';
import {MyLoggerService} from '../../middlewares/logger/logger.module';

const clc = require('cli-color')

@CommandHandler(KillDragonCommand)
export class KillDragonHandler implements ICommandHandler<KillDragonCommand> {
    private readonly logger = new MyLoggerService('KillDragonCommand')

    constructor(
        private readonly repository: HeroRepository,
        private readonly publisher: EventPublisher,
    ) {}

    async execute(command: KillDragonCommand, resolve: (value?) => void) {
        console.log(clc.greenBright('KillDragonCommand...'))

        this.logger.error('Killing the dragoooooon')
        const { heroId, dragonId } = command
        const hero = this.publisher.mergeObjectContext(
            await this.repository.findOneById(+heroId),
        )
        hero.killEnemy(dragonId)
        hero.commit()
        resolve()
    }
}

In the main.ts file:

import { NestFactory } from '@nestjs/core';
import { ApplicationModule } from './app.module';
import { MyLoggerService} from './cqrs/modules/heroes/middlewares/logger/logger.module';

async function bootstrap() {
    const app = await NestFactory.create(ApplicationModule, {
        logger: new MyLoggerService('HeroService'),
    })
    await app.listen(3000);
}
bootstrap();

And then, my messages are printed in the standard output:

{
  "context": "KillDragonCommand",
  "level": "error",
  "message": "Killing the dragoooooon",
  "timestamp": "2018-03-19T21:55:41.342+01:00"
}

The problem I had was when I extended the class MyLoggerService from the winston.Logger class, the messages weren't printed.

[et]

Does anyone have an example of doing the above but with a decorator for dependency injection into the constructor?

[kavitha1991dhiman]

@shekohex Your code really helped.
Can you share how this file is created
filename: Env('LOG_FILE', 'app.dev.log'), // i will explain this later

[shekohex]

hi @kavitha1991dhiman , the Env function return the value from .env file, then the winston lib will try to create it if not exist.

[KeithGillette]

@et:

Does anyone have an example of doing the above but with a decorator for dependency injection into the constructor?

We haven't migrated to NestJS yet, but I think that something like the following very simple constructor-injectable service which I modeled on the previous examples in this thread for a project using injection-js dependency injection (Angular's old Reflective injector) would also work with NestJS dependency injection:

import { Injectable } from 'injection-js';
import { createLogger, format, Logger, LoggerOptions, transports } from 'winston';
import 'winston-mongodb'; // importing Winston-MongoDB extends Winston `transports` with `transports.MongoDB` property
import { TransformableInfo } from 'logform';

export enum LogLevel {INFO = 'info', WARN = 'warn', ERROR = 'error'}

export const logTransportMongoDB = new transports['MongoDB']({
    db: process.env.MONGO_URL,
    handleExceptions: true,
    storeHost: true,
    options: {
        useNewUrlParser: true
    },
});

export const logTransportConsole = new transports.Console({
    handleExceptions: true,
    format: format.combine(
        format.timestamp(),
        format.printf((info: TransformableInfo) => {
            return `${info.timestamp} [${info.meta.context}] [${info.level.toLocaleUpperCase()}] ${info.message}`;
        })
    )
});

@Injectable()
export class LogService {
    private readonly logger: Logger;
    private contextName: string = 'DEFAULT';

    constructor() {
        this.logger = createLogger();
        this.logger.configure({
            transports: [logTransportConsole],
            exitOnError: false
        });
    }

    public configure(configuration: LoggerOptions, contextName?: string): void {
        this.logger.configure(configuration);
        this.contextName = contextName ? contextName : this.contextName;
    }

    public log(message: string): void {
        this.logger.log({level: LogLevel.INFO, message: message, meta: {context: this.contextName}});
    }

    public error(message: string, stackTrace?: any): void {
        this.logger.log({level: LogLevel.ERROR, message: message, meta: {context: this.contextName, stackTrace: stackTrace}});
    }

    public warn(message: string): void {
        this.logger.log({level: LogLevel.WARN, message: message, meta: {context: this.contextName}});

    }

    public info(message: string): void {
        this.logger.log({level: LogLevel.INFO, message: message, meta: {context: this.contextName}});
    }

}

Of course, when using constructor injection, the configuration set via LogService.configure will be shared across the entire injector context since the service will run as a singleton.

[lock[bot]]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.