API with NestJS #86. Logging with the built-in logger when using raw SQL - wanago.io

December 12, 2022

This entry is part 86 of 168 in the API with NestJS

Troubleshooting a deployed application can be challenging. We can’t use the debugger and stop an application used by other people. Instead, we need to implement logs that we can inspect if we suspect that our API is not working as expected. In this article, we look at the logger built into NestJS and use it in different cases.

Logger available in NestJS

NestJS is equipped with a logger ready to use out of the box. The official documentation suggests creating an instance of the logger on top of each class we want to use it in.

users.service.ts

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

import UsersRepository from './users.repository';

@Injectable()

class UsersService {

private readonly logger = new Logger();

// ...

}

export default UsersService;

Log levels

A crucial concept we need to learn is the level of the log. There are a few to choose from, sorted by severity:

error
warn
log
verbose
debug

Each logger instance has a set of methods that correspond with the above levels.

users.service.ts

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

import { CreateUserDto } from './dto/createUser.dto';

import UsersRepository from './users.repository';

import UserAlreadyExistsException from './exceptions/userAlreadyExists.exception';

@Injectable()

class UsersService {

private readonly logger = new Logger(UsersService.name);

constructor(private readonly usersRepository: UsersRepository) {}

async create(user: CreateUserDto) {

try {

return await this.usersRepository.create(user);

} catch (error) {

if (error instanceof UserAlreadyExistsException) {

this.logger.warn(error.message);

}

throw error;

}

// ...

}

export default UsersService;

The more severe a particular log, the more alarmed we should be. For example, a user trying to sign up using an occupied email address is not a reason to panic. Because of that, above, we use the logger.warn function.

We can specify what levels of logs we want to appear in our terminal. To do that, we need to adjust our bootstrap() function.

main.ts

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

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

import * as cookieParser from 'cookie-parser';

async function bootstrap() {

const app = await NestFactory.create(AppModule, {

logger: ['error', 'warn', 'log', 'verbose', 'debug'],

});

app.use(cookieParser());

await app.listen(3000);

}

bootstrap();

It is a common approach to disregard some of the logs in the production environment. We might want to avoid having too many logs in production so that we see a potential issue more clearly.

main.ts

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

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

import * as cookieParser from 'cookie-parser';

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

async function bootstrap() {

const isProduction = process.env.NODE_ENV === 'production';

const logLevels: LogLevel[] = isProduction

? ['error', 'warn', 'log']

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

const app = await NestFactory.create(AppModule, {

logger: logLevels,

});

app.use(cookieParser());

await app.listen(3000);

}

bootstrap();

A surprising thing might be that providing ['debug'] turns on all of the log levels. When we look at the isLogLevelEnabled function we can see that NestJS looks for the highest severity included in the array and turns on all of the logs with the lower severity too. Above, we provide a full array for the sake of readability.

Once we do the above, logs start appearing in our terminal. There we can see that thanks to providing the name of the service with new Logger(UsersService.name), the name appears at the beginning of the log.

Using the logger in an interceptor

The above approach can be handy when handling some specific cases. Unfortunately, covering all possible situations with logs would be pretty demanding. Fortunately, we can use the power of interceptors that NestJS offers us. Let’s write an interceptor that allows us to cover a particular endpoint with a wide variety of logs.

authentication.controller.ts

import {

Body,

Controller,

Post,

ClassSerializerInterceptor,

UseInterceptors,

} from '@nestjs/common';

import { AuthenticationService } from './authentication.service';

import RegisterDto from './dto/register.dto';

import { LoggerInterceptor } from '../utils/logger.interceptor';

@Controller('authentication')

@UseInterceptors(ClassSerializerInterceptor)

export class AuthenticationController {

constructor(private readonly authenticationService: AuthenticationService) {}

@Post('register')

@UseInterceptors(LoggerInterceptor)

async register(@Body() registrationData: RegisterDto) {

return this.authenticationService.register(registrationData);

}

// ...

}

The job of the LoggerInterceptor is to gather information bout the request and response. We can write an interceptor that binds some logic before the method execution.

If you want to know more about interceptors, check out API with NestJS #5. Serializing the response with interceptors

logger.interceptor.ts

import {

Injectable,

NestInterceptor,

ExecutionContext,

CallHandler,

Logger,

} from '@nestjs/common';

import { Request, Response } from 'express';

@Injectable()

export class LoggerInterceptor implements NestInterceptor {

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

intercept(context: ExecutionContext, next: CallHandler) {

const httpContext = context.switchToHttp();

const request = httpContext.getRequest<Request>();

const response = httpContext.getResponse<Response>();

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);

});

return next.handle();

}

Above a few important things happen:

we get the request and response object associated with a particular request,
we wait for the finish event emitted by NodeJS
we use the appropriate log level based on the status code.

If we want our interceptor to apply to every method in a given controller, we can apply it to the whole class.

authentication.controller.ts

import {

Controller,

ClassSerializerInterceptor,

UseInterceptors,

} from '@nestjs/common';

import { LoggerInterceptor } from '../utils/logger.interceptor';

@Controller('authentication')

@UseInterceptors(ClassSerializerInterceptor)

@UseInterceptors(LoggerInterceptor)

export class AuthenticationController {

// ...

}

If we would like to apply the above logic to all of our controllers, we can use our interceptor globally with the useGlobalInterceptors method.

main.ts

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

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

import * as cookieParser from 'cookie-parser';

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

import { LoggerInterceptor } from './utils/logger.interceptor';

async function bootstrap() {

const isProduction = process.env.NODE_ENV === 'production';

const logLevels: LogLevel[] = isProduction

? ['error', 'warn', 'log']

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

const app = await NestFactory.create(AppModule, {

logger: logLevels,

});

app.use(cookieParser());

app.useGlobalInterceptors(new LoggerInterceptor());

await app.listen(3000);

}

bootstrap();

Logging SQL queries

A helpful thing to do might be to log all SQL queries in our application. Unfortunately, the node-postgres library does not offer any logging functionalities.

Thankfully, it’s pretty easy to inject logging functionalities into our DatabaseService when performing simple queries.

database.service.ts

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

import { Pool, PoolClient } from 'pg';

import { CONNECTION_POOL } from './database.module-definition';

@Injectable()

class DatabaseService {

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

constructor(@Inject(CONNECTION_POOL) private readonly pool: Pool) {}

async runQuery(query: string, params?: unknown[]) {

return this.queryWithLogging(this.pool, query, params);

}

getLogMessage(query: string, params?: unknown[]) {

if (!params) {

return `Query: ${query}`;

}

return `Query: ${query} Params: ${JSON.stringify(params)}`;

}

async queryWithLogging(

source: Pool | PoolClient,

query: string,

params?: unknown[],

) {

const queryPromise = source.query(query, params);

// message without unnecessary spaces and newlines

const message = this.getLogMessage(query, params)

.replace(/\n|/g, '')

.replace(/ +/g, ' ');

queryPromise

.then(() => {

this.logger.log(message);

})

.catch((error) => {

this.logger.warn(message);

throw error;

});

return queryPromise;

}

// ...

}

export default DatabaseService;

The problem arises when we perform transactions and implement the getPoolClient function.

If you want to know more about transactions check out API with NestJS #76. Working with transactions using raw SQL queries

database.service.ts

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

import { Pool } from 'pg';

import { CONNECTION_POOL } from './database.module-definition';

@Injectable()

class DatabaseService {

constructor(@Inject(CONNECTION_POOL) private readonly pool: Pool) {}

async getPoolClient() {

return this.pool.connect();

}

// ...

}

export default DatabaseService;

Once we return the client, we no longer control how it executes queries. Fortunately, we can deal with the above problem using a proxy.

If you want to know more about proxies, check out Understanding JavaScript Proxy. Preserving backward compatibility in a library

database.service.ts

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

import { Pool, PoolClient } from 'pg';

import { CONNECTION_POOL } from './database.module-definition';

@Injectable()

class DatabaseService {

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

constructor(@Inject(CONNECTION_POOL) private readonly pool: Pool) {}

async runQuery(query: string, params?: unknown[]) {

return this.queryWithLogging(this.pool, query, params);

}

getLogMessage(query: string, params?: unknown[]) {

if (!params) {

return `Query: ${query}`;

}

return `Query: ${query} Params: ${JSON.stringify(params)}`;

}

async queryWithLogging(

source: Pool | PoolClient,

query: string,

params?: unknown[],

) {

const queryPromise = source.query(query, params);

// message without unnecessary spaces and newlines

const message = this.getLogMessage(query, params)

.replace(/\n|/g, '')

.replace(/ +/g, ' ');

queryPromise

.then(() => {

this.logger.log(message);

})

.catch((error) => {

this.logger.warn(message);

throw error;

});

return queryPromise;

}

async getPoolClient() {

const poolClient = await this.pool.connect();

return new Proxy(poolClient, {

get: (target: PoolClient, propertyName: keyof PoolClient) => {

if (propertyName === 'query') {

return (query: string, params?: unknown[]) => {

return this.queryWithLogging(target, query, params);

};

}

return target[propertyName];

});

}

export default DatabaseService;

Thanks to the above approach, as soon as some other service gets a pool client and runs a query, it runs through our proxy first and logs the appropriate message.

Summary

In this article, we’ve learned how to work with the logger built into NestJS. We’ve covered a variety of cases in which we might need logging. It included logging messages automatically for specific endpoints and SQL queries. A thorough approach to logging can help us when there is a problem in our application, so it is worth spending some time on.

Series Navigation<< API with NestJS #85. Defining constraints with raw SQLAPI with NestJS #87. Writing unit tests in a project with raw SQL >>