API with NestJS #113. Logging with Prisma

June 19, 2023

This entry is part 113 of 148 in the API with NestJS

Using a debugger with an application running locally on our machine is a great way to troubleshoot. Unfortunately, we can’t do that with a deployed app. To be able to investigate any potential issues, we need to implement a logging functionality. In this article, we use the logger built into NestJS and integrate it with Prisma.

Logger provided by NestJS

Fortunately, NestJS provides logging functionalities that we can use. One of its crucial concepts is the log level. Sorted by severity, those are the log levels we can choose:

error
warn
log
debug
verbose

Recently, the debug and verbose log levels switched places with this pull request.

To use them, we need to take advantage of the Logger class. The most straightforward way of using it is simply importing it from the @nestjs/common library.

posts.service.ts

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

import { PrismaService } from '../prisma/prisma.service';

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

@Injectable()

export class PostsService {

constructor(private readonly prismaService: PrismaService) {}

async getPostById(id: number) {

const post = await this.prismaService.post.findUnique({

where: {

id,

});

if (!post) {

Logger.warn('Tried to get a post that does not exist');

throw new PostNotFoundException(id);

}

return post;

}

// ...

}

While the above approach works, the official documentation suggests creating an instance of the logger inside each class that uses it.

posts.service.ts

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

import { PrismaService } from '../prisma/prisma.service';

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

@Injectable()

export class PostsService {

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

constructor(private readonly prismaService: PrismaService) {}

async getPostById(id: number) {

const post = await this.prismaService.post.findUnique({

where: {

id,

});

if (!post) {

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

throw new PostNotFoundException(id);

}

return post;

}

// ...

}

Thanks to the above adjustment, NestJS prints the name of our service in square brackets. This makes our logs a lot easier to read.

Dealing with log levels

As mentioned before, the logs we produce are grouped by severity and assigned a log level. The more severe a particular log is, the more alarmed we should be. For example, a user trying to access a post that does not exist is probably not a reason to wake the development team at night. Because of that, we use the “warn” level instead of the “error”.

We can filter out certain levels to avoid cluttering our logs. One way of doing that is to disregard some of the logs in the production environment to see the potential issues more clearly.

main.ts

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

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

import { LogLevel, ValidationPipe } from '@nestjs/common';

import * as cookieParser from 'cookie-parser';

async function bootstrap() {

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

const logLevels: LogLevel[] = isProduction

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

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

const app = await NestFactory.create(AppModule, {

logger: logLevels,

});

app.use(cookieParser());

app.useGlobalPipes(

new ValidationPipe({

transform: true,

}),

);

await app.listen(3000);

}

bootstrap();

A thing that my surprise you is that providing ['verbose'] turns on all log levels. Taking a look at the isLogLevelEnabled function reveals that NestJS searches for the highest severity included in the array and turns on the logs with the lower severity too. For the sake of readability, we provide the complete array.

Creating a logging interceptor

While manually covering all cases with logs can produce the best results, it can be pretty demanding. A good alternative is writing a NestJS interceptor that covers a particular endpoint with various logs.

logging.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, we get the information about a particular HTTP request and wait for it to finish. Finally, we base the log level on the response’s status code.

There are a few ways to use our interceptor. First, we can decorate a particular method with it.

posts.controller.ts

import { Body, Controller, Get, Query, UseInterceptors } from '@nestjs/common';

import { PostsService } from './posts.service';

import { AuthorIdQueryDto } from './dto/authorIdQuery.dto';

import { PaginationParamsDto } from './dto/paginationParams.dto';

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

@Controller('posts')

export default class PostsController {

constructor(private readonly postsService: PostsService) {}

@Get()

@UseInterceptors(LoggerInterceptor)

async getPosts(

@Query() { authorId }: AuthorIdQueryDto,

@Query() paginationParams: PaginationParamsDto,

) {

if (authorId !== undefined) {

return this.postsService.getPostsByAuthor(authorId, paginationParams);

}

return this.postsService.getPosts(paginationParams);

}

// ...

}

Alternatively, we can use it to decorate the entire controller.

posts.controller.ts

import { Controller, UseInterceptors } from '@nestjs/common';

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

@Controller('posts')

@UseInterceptors(LoggerInterceptor)

export default class PostsController {

// ...

}

Finally, we can use the useGlobalInterceptors method to apply the interceptor to all our controllers.

main.ts

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

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

import { LogLevel, ValidationPipe } from '@nestjs/common';

import * as cookieParser from 'cookie-parser';

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.useGlobalPipes(

new ValidationPipe({

transform: true,

}),

);

app.useGlobalInterceptors(new LoggerInterceptor());

await app.listen(3000);

}

bootstrap();

Feel free to add more data into the above logs if you need, such as the POST request body.

Logging SQL queries with Prisma

Logging SQL queries that happen in our application can help us investigate what happens under the hood of Prisma and notice eventual bottlenecks. Fortunately, Prisma has logging functionalities built-in. To use them, let’s modify our PrismaService.

prisma.service.ts

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

import { PrismaClient, Prisma } from '@prisma/client';

@Injectable()

export class PrismaService

extends PrismaClient

implements OnModuleInit, OnModuleDestroy

{

constructor() {

super({

log: ['query', 'info', 'warn', 'error'],

});

}

// ...

}

The downside of the above approach is that the logs produced by Prisma look different than those created by NestJS. We can deal with this problem using the built-in logger from NestJS with Prisma.

By default, Prisma prints the logs to the standard output. Instead, we can ask it to emit events whenever Prisma logs something by passing emit: 'event' with the particular log level.

prisma.service.ts

import {

Injectable,

OnModuleInit,

OnModuleDestroy,

Logger,

} from '@nestjs/common';

import { PrismaClient, Prisma } from '@prisma/client';

@Injectable()

export class PrismaService

extends PrismaClient<Prisma.PrismaClientOptions, Prisma.LogLevel>

implements OnModuleInit, OnModuleDestroy

{

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

constructor() {

super({

log: [

{

emit: 'event',

level: 'query',

{

emit: 'event',

level: 'error',

{

emit: 'event',

level: 'info',

{

emit: 'event',

level: 'warn',

});

}

// ...

}

An important thing above is that we are passing additional arguments to the PrismaClient generic type. To be able to subscribe to the query, error, info, and warn event, we need to explicitly let TypeScript know that such events might be emitted using Prisma.LogLevel type.

Once we do the above, we can subscribe to the events.

import {

Injectable,

OnModuleInit,

OnModuleDestroy,

Logger,

} from '@nestjs/common';

import { PrismaClient, Prisma } from '@prisma/client';

@Injectable()

export class PrismaService

extends PrismaClient<Prisma.PrismaClientOptions, Prisma.LogLevel>

implements OnModuleInit, OnModuleDestroy

{

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

async onModuleInit() {

await this.$connect();

this.$use(this.categorySoftDeleteMiddleware);

this.$use(this.categoryFindMiddleware);

this.$on('error', ({ message }) => {

this.logger.error(message);

});

this.$on('warn', ({ message }) => {

this.logger.warn(message);

});

this.$on('info', ({ message }) => {

this.logger.debug(message);

});

this.$on('query', ({ query, params }) => {

this.logger.log(`${query}; ${params}`);

});

}

// ...

}

Watch out, because there is an open issue right now on GitHub that indicates that there might be some issue with emitting the info event.

Thanks to this approach, we can see the SQL queries logged using the NestJS logger.

Summary

In this article, we’ve gone through using the logger built into NestJS. We’ve covered using it both manually and through a custom interceptor that logs various messages automatically. On top of that, we learned how logging works with Prisma and how to incorporate the NestJS logger into it.

With a comprehensive approach to logging, we can have a much easier type investigating a problem in our application. Therefore, it is definitely worth learning and including in our stack.

Series Navigation<< API with NestJS #112. Serializing the response with PrismaAPI with NestJS #114. Modifying data using PUT and PATCH methods with Prisma >>