API with NestJS #50. Introduction to logging with the built-in logger and TypeORM

October 4, 2021

This entry is part 50 of 121 in the API with NestJS

As our application grows, more and more people start depending on it. At a time like this, it is crucial to ensure that our API works well. To do that, we could use a way to troubleshoot the application to detect anomalies and to be able to find their origin. This article serves as an introduction to how we can keep logs on what happens in our application.

Logger built into NestJS

Fortunately, NestJS comes with a logger built-in. Before using it, we should create its instance.

posts.service.ts

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

@Injectable()

export default class PostsService {

private readonly logger = new Logger(PostsService.name)

// ...

}

Although we could use the Logger we import from @nestjs/common directly, creating a brand new instance for every service is a good practice and allows us to supply the name of the service for the Logger constructor.

Log levels

A crucial thing about the Logger is that it comes with a few methods:

error
warn
log
verbose
debug

The above methods correspond with log levels that we can configure for our application.

main.ts

import { NestFactory } from '@nestjs/core';

import { AppModule } from './app.module';

import getLogLevels from './utils/getLogLevels';

async function bootstrap() {

const app = await NestFactory.create(AppModule, {

logger: getLogLevels(process.env.NODE_ENV === 'production')

});

// ...

}

bootstrap();

We don’t use the ConfigService above to read the environment variables because it isn’t initialized yet.

getLogLevels.ts

import { LogLevel } from '@nestjs/common/services/logger.service';

function getLogLevels(isProduction: boolean): LogLevel[] {

if (isProduction) {

return ['log', 'warn', 'error'];

}

return ['error', 'warn', 'log', 'verbose', 'debug'];

}

export default getLogLevels;

Because of the above setup, the debug and verbose methods won’t produce logs on production.

If we take a look at the isLogLevelEnabled function, we can notice that providing ['debug'] turns on all of the log levels, not only verbose. This is because NestJS assumes that if we want to display the verbose logs, we also want to display logs of all of the lower levels. Because of that, ['debug'] is the same as ['error', 'warn', 'log', 'verbose', 'debug'].

We can find the importance of each log level here.

After doing all of the above, let’s start using the logger.

posts.service.ts

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

import Post from './post.entity';

import { InjectRepository } from '@nestjs/typeorm';

import { Repository } from 'typeorm';

import PostNotFoundException from './exceptions/postNotFound.exception';

@Injectable()

export default class PostsService {

private readonly logger = new Logger(PostsService.name)

constructor(

@InjectRepository(Post)

private postsRepository: Repository<Post>,

) {}

async getPostById(id: number) {

const post = await this.postsRepository.findOne(id, { relations: ['author'] });

if (post) {

return post;

}

this.logger.warn('Tried to access a post that does not exist');

throw new PostNotFoundException(id);

}

// ...

}

Now we can see that passing PostsService.name caused PostService to appear as a prefix to our log message.

Using the logger in a middleware

Even though the above approach might come in handy, it might be cumbersome to write log messages manually. Thankfully, we can produce logs from middleware.

logs.middleware.ts

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

import { Request, Response, NextFunction } from 'express';

@Injectable()

class LogsMiddleware implements NestMiddleware {

private readonly logger = new Logger('HTTP');

use(request: Request, response: Response, next: NextFunction) {

response.on('finish', () => {

const { method, originalUrl } = request;

const { statusCode, statusMessage } = response;

const message = `${method} ${originalUrl} ${statusCode} ${statusMessage}`;

if (statusCode >= 500) {

return this.logger.error(message);

}

if (statusCode >= 400) {

return this.logger.warn(message);

}

return this.logger.log(message);

});

next();

}

export default LogsMiddleware;

Check out the MDN documentation to read more about HTTP response status codes.

Above, we gather information about the request and response and log it based on the status code. Of course, the request and response objects contain more helpful information, so feel free to make your logs even more verbose.

The last step is to apply our middleware for all of our routes.

app.module.ts

import { MiddlewareConsumer, Module } from '@nestjs/common';

import { PostsModule } from './posts/posts.module';

import { DatabaseModule } from './database/database.module';

import LogsMiddleware from './utils/logs.middleware';

@Module({

imports: [

PostsModule,

DatabaseModule,

// ...

})

export class AppModule {

configure(consumer: MiddlewareConsumer) {

consumer

.apply(LogsMiddleware)

.forRoutes('*');

}

Using the logger with TypeORM

Another helpful thing we can do is to log all SQL queries that happen in our application. To do that with TypeORM, we need to implement the Logger interface:

databaseLogger.ts

import { Logger as TypeOrmLogger } from 'typeorm';

import { Logger as NestLogger } from '@nestjs/common';

class DatabaseLogger implements TypeOrmLogger {

private readonly logger = new NestLogger('SQL');

logQuery(query: string, parameters?: unknown[]) {

this.logger.log(`${query} -- Parameters: ${this.stringifyParameters(parameters)}`);

}

logQueryError(error: string, query: string, parameters?: unknown[]) {

this.logger.error(`${query} -- Parameters: ${this.stringifyParameters(parameters)} -- ${error}`);

}

logQuerySlow(time: number, query: string, parameters?: unknown[]) {

this.logger.warn(`Time: ${time} -- Parameters: ${this.stringifyParameters(parameters)} -- ${query}`);

}

logMigration(message: string) {

this.logger.log(message);

}

logSchemaBuild(message: string) {

this.logger.log(message);

}

log(level: 'log' | 'info' | 'warn', message: string) {

if (level === 'log') {

return this.logger.log(message);

}

if (level === 'info') {

return this.logger.debug(message);

}

if (level === 'warn') {

return this.logger.warn(message);

}

private stringifyParameters(parameters?: unknown[]) {

try {

return JSON.stringify(parameters);

} catch {

return '';

}

export default DatabaseLogger;

The last step is to use the above class in our TypeORM configuration:

database.module.ts

import { Module } from '@nestjs/common';

import { TypeOrmModule } from '@nestjs/typeorm';

import { ConfigModule, ConfigService } from '@nestjs/config';

import DatabaseLogger from './databaseLogger';

@Module({

imports: [

TypeOrmModule.forRootAsync({

imports: [ConfigModule],

inject: [ConfigService],

useFactory: (configService: ConfigService) => ({

type: 'postgres',

logger: new DatabaseLogger(),

host: configService.get('POSTGRES_HOST'),

// ...

})

}),

})

export class DatabaseModule {}

When we start looking into the logs from TypeORM, we notice that it often produces quite lengthy queries. For example, the below query happens when we retrieve the data of the user that attempts to log in:

Saving logs into a PostgreSQL database

So far, we’ve only been logging all of the messages to the console. While that might work fine when developing the application on our machine, it wouldn’t make a lot of sense in a deployed application. There are a lot of services that can help us gather and manage logs, such as DataDog and Loggly. They are not free of charge, though. Therefore, in this article, we save logs into a PostgreSQL database.

For starters, let’s create an entity for our log:

log.entity.ts

import { Column, CreateDateColumn, Entity, PrimaryGeneratedColumn } from 'typeorm';

@Entity()

class Log {

@PrimaryGeneratedColumn()

public id: number;

@Column()

public context: string;

@Column()

public message: string;

@Column()

public level: string;

@CreateDateColumn()

creationDate: Date;

}

export default Log;

Above, we use the @CreateDateColum decorator. If you want to know more about dates in PostgreSQL, check out Managing date and time with PostgreSQL and TypeORM

Once we’ve got the above done, let’s create a service that allows us to create logs:

logs.service.ts

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

import { InjectRepository } from '@nestjs/typeorm';

import { Repository } from 'typeorm';

import Log from './log.entity';

import CreateLogDto from './dto/createLog.dto';

@Injectable()

export default class LogsService {

constructor(

@InjectRepository(Log)

private logsRepository: Repository<Log>

) {}

async createLog(log: CreateLogDto) {

const newLog = await this.logsRepository.create(log);

await this.logsRepository.save(newLog, {

data: {

isCreatingLogs: true

}

});

return newLog;

}

Above, you can notice that we pass isCreatingLogs: true when saving our logs to the database. The above is because we need to overcome the issue of an infinite loop. When we store logs in the database, it causes SQL queries to be logged. When we log SQL queries, they are saved to the database, causing an infinite loop. Because of that, we need to adjust our DatabaseLogger slightly:

databaseLogger.ts

import { Logger as TypeOrmLogger, QueryRunner } from 'typeorm';

import { Logger as NestLogger } from '@nestjs/common';

class DatabaseLogger implements TypeOrmLogger {

private readonly logger = new NestLogger('SQL');

logQuery(query: string, parameters?: unknown[], queryRunner?: QueryRunner) {

if (queryRunner?.data?.isCreatingLogs) {

return;

}

this.logger.log(`${query} -- Parameters: ${this.stringifyParameters(parameters)}`);

}

logQueryError(error: string, query: string, parameters?: unknown[], queryRunner?: QueryRunner) {

if (queryRunner?.data?.isCreatingLogs) {

return;

}

this.logger.error(`${query} -- Parameters: ${this.stringifyParameters(parameters)} -- ${error}`);

}

logQuerySlow(time: number, query: string, parameters?: unknown[], queryRunner?: QueryRunner) {

if (queryRunner?.data?.isCreatingLogs) {

return;

}

this.logger.warn(`Time: ${time} -- Parameters: ${this.stringifyParameters(parameters)} -- ${query}`);

}

logMigration(message: string) {

this.logger.log(message);

}

logSchemaBuild(message: string) {

this.logger.log(message);

}

log(level: 'log' | 'info' | 'warn', message: string, queryRunner?: QueryRunner) {

if (queryRunner?.data?.isCreatingLogs) {

return;

}

if (level === 'log') {

return this.logger.log(message);

}

if (level === 'info') {

return this.logger.debug(message);

}

if (level === 'warn') {

return this.logger.warn(message);

}

private stringifyParameters(parameters?: unknown[]) {

try {

return JSON.stringify(parameters);

} catch {

return '';

}

export default DatabaseLogger;

Above, we don’t log SQL queries if they are involved in creating logs.

Now we need to extend the logger built into NestJS and use the LogsService:

customLogger.ts

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

import { ConsoleLoggerOptions } from '@nestjs/common/services/console-logger.service';

import { ConfigService } from '@nestjs/config';

import getLogLevels from '../utils/getLogLevels';

import LogsService from './logs.service';

@Injectable()

class CustomLogger extends ConsoleLogger {

private readonly logsService: LogsService;

constructor(

context: string,

options: ConsoleLoggerOptions,

configService: ConfigService,

logsService: LogsService

) {

const environment = configService.get('NODE_ENV');

super(

context,

{

...options,

logLevels: getLogLevels(environment === 'production')

}

);

this.logsService = logsService;

}

log(message: string, context?: string) {

super.log.apply(this, [message, context]);

this.logsService.createLog({

message,

context,

level: 'log'

})

}

error(message: string, stack?: string, context?: string) {

super.error.apply(this, [message, stack, context]);

this.logsService.createLog({

message,

context,

level: 'error'

})

}

warn(message: string, context?: string) {

super.warn.apply(this, [message, context]);

this.logsService.createLog({

message,

context,

level: 'error'

})

}

debug(message: string, context?: string) {

super.debug.apply(this, [message, context]);

this.logsService.createLog({

message,

context,

level: 'error'

})

}

verbose(message: string, context?: string) {

super.debug.apply(this, [message, context]);

this.logsService.createLog({

message,

context,

level: 'error'

})

}

export default CustomLogger;

We also need to create the LoggerModule so that we can add it into our AppModule:

logger.module.ts

import { Module } from '@nestjs/common';

import CustomLogger from './customLogger';

import { ConfigModule } from '@nestjs/config';

import LogsService from './logs.service';

import { TypeOrmModule } from '@nestjs/typeorm';

import Log from './log.entity';

@Module({

imports: [ConfigModule, TypeOrmModule.forFeature([Log])],

providers: [CustomLogger, LogsService],

exports: [CustomLogger],

})

export class LoggerModule {}

The final step is to call the useLogger method to inject our custom logger into the application:

main.ts

import { NestFactory } from '@nestjs/core';

import { AppModule } from './app.module';

import CustomLogger from './logger/customLogger';

async function bootstrap() {

const app = await NestFactory.create(AppModule, {

bufferLogs: true,

});

app.useLogger(app.get(CustomLogger));

// ...

}

bootstrap();

We could store some data in separate columns. Fore example, we could do that with the HTTP methods to be able to query the logs looking only for POST request, for example.

Summary

In this article, we’ve gone through the basics of logging with NestJS and TypeORM. We’ve learned about various log levels and how we can log messages directly and through middleware. We’ve also learned how to save our logs into an SQL database. Doing that has some benefits. For example, we could store more data in separate columns and use them when querying the data.

Even if saving logs into an SQL database has some advantages, the performance might not be the best if we have a lot of logs. Also, it could fill up the available space of our database. Therefore, it might be a good idea to look into services such as DataDog and Loggly. However, it is a topic for another article, so stay tuned!

Series Navigation<< API with NestJS #49. Updating with PUT and PATCH with MongoDB and MongooseAPI with NestJS #51. Health checks with Terminus and Datadog >>

4 Comments

Oldest

Newest Most Voted

Inline Feedbacks

View all comments

Mitch

2 years ago

one little error. if is not indicated context the error is like so:
ERROR [AuthController] Data too long for column ‘password’ at row 1
ERROR [AuthController] undefined

two records is created and not one. why not use this.context

error (message: string, stack?: string) {
  super.error(message, stack, this.context)
  this.logsService.createLog({
   message,
   context: this.context,
   stack: stack,
   level: ‘error’
  })
}

Diliru

Hey can you please also demonstrate implementing logger to mongoose

Xdev

How would you limit logging to only specific routes

Last edited 2 years ago by Xdev

Phong

1 year ago

HI !

Thank you for your article but I am so confusing that in case we need to create brand new instance of Logger in service class, so why we need to setup in main.ts like below

const app = await NestFactory.create(AppModule, {
logger: console // or LogLevel or LogService,
});

why we need to do that, I have read the code and do not know how it can related in Service and in app

If we create brand new instance of Logger in each service how we can make sure that both are in same config