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.
1import { Injectable, Logger } from '@nestjs/common';
2import { PrismaService } from '../prisma/prisma.service';
3import { PostNotFoundException } from './exceptions/postNotFound.exception';
4
5@Injectable()
6export class PostsService {
7 constructor(private readonly prismaService: PrismaService) {}
8
9 async getPostById(id: number) {
10 const post = await this.prismaService.post.findUnique({
11 where: {
12 id,
13 },
14 });
15 if (!post) {
16 Logger.warn('Tried to get a post that does not exist');
17 throw new PostNotFoundException(id);
18 }
19 return post;
20 }
21
22 // ...
23}While the above approach works, the official documentation suggests creating an instance of the logger inside each class that uses it.
1import { Injectable, Logger } from '@nestjs/common';
2import { PrismaService } from '../prisma/prisma.service';
3import { PostNotFoundException } from './exceptions/postNotFound.exception';
4
5@Injectable()
6export class PostsService {
7 private readonly logger = new Logger(PostsService.name);
8
9 constructor(private readonly prismaService: PrismaService) {}
10
11 async getPostById(id: number) {
12 const post = await this.prismaService.post.findUnique({
13 where: {
14 id,
15 },
16 });
17 if (!post) {
18 this.logger.warn('Tried to get a post that does not exist');
19 throw new PostNotFoundException(id);
20 }
21 return post;
22 }
23
24 // ...
25}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.
1import { NestFactory } from '@nestjs/core';
2import { AppModule } from './app.module';
3import { LogLevel, ValidationPipe } from '@nestjs/common';
4import * as cookieParser from 'cookie-parser';
5
6async function bootstrap() {
7 const isProduction = process.env.NODE_ENV === 'production';
8 const logLevels: LogLevel[] = isProduction
9 ? ['error', 'warn', 'log']
10 : ['error', 'warn', 'log', 'debug', 'verbose'];
11
12 const app = await NestFactory.create(AppModule, {
13 logger: logLevels,
14 });
15
16 app.use(cookieParser());
17
18 app.useGlobalPipes(
19 new ValidationPipe({
20 transform: true,
21 }),
22 );
23
24 await app.listen(3000);
25}
26bootstrap();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.
1import {
2 Injectable,
3 NestInterceptor,
4 ExecutionContext,
5 CallHandler,
6 Logger,
7} from '@nestjs/common';
8import { Request, Response } from 'express';
9
10@Injectable()
11export class LoggerInterceptor implements NestInterceptor {
12 private readonly logger = new Logger('HTTP');
13
14 intercept(context: ExecutionContext, next: CallHandler) {
15 const httpContext = context.switchToHttp();
16 const request = httpContext.getRequest<Request>();
17 const response = httpContext.getResponse<Response>();
18
19 response.on('finish', () => {
20 const { method, originalUrl } = request;
21 const { statusCode, statusMessage } = response;
22
23 const message = `${method} ${originalUrl} ${statusCode} ${statusMessage}`;
24
25 if (statusCode >= 500) {
26 return this.logger.error(message);
27 }
28
29 if (statusCode >= 400) {
30 return this.logger.warn(message);
31 }
32
33 return this.logger.log(message);
34 });
35
36 return next.handle();
37 }
38}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.
1import { Body, Controller, Get, Query, UseInterceptors } from '@nestjs/common';
2import { PostsService } from './posts.service';
3import { AuthorIdQueryDto } from './dto/authorIdQuery.dto';
4import { PaginationParamsDto } from './dto/paginationParams.dto';
5import { LoggerInterceptor } from '../utils/logger.interceptor';
6
7@Controller('posts')
8export default class PostsController {
9 constructor(private readonly postsService: PostsService) {}
10
11 @Get()
12 @UseInterceptors(LoggerInterceptor)
13 async getPosts(
14 @Query() { authorId }: AuthorIdQueryDto,
15 @Query() paginationParams: PaginationParamsDto,
16 ) {
17 if (authorId !== undefined) {
18 return this.postsService.getPostsByAuthor(authorId, paginationParams);
19 }
20 return this.postsService.getPosts(paginationParams);
21 }
22
23 // ...
24}Alternatively, we can use it to decorate the entire controller.
1import { Controller, UseInterceptors } from '@nestjs/common';
2import { LoggerInterceptor } from '../utils/logger.interceptor';
3
4@Controller('posts')
5@UseInterceptors(LoggerInterceptor)
6export default class PostsController {
7 // ...
8}Finally, we can use the useGlobalInterceptors method to apply the interceptor to all our controllers.
1import { NestFactory } from '@nestjs/core';
2import { AppModule } from './app.module';
3import { LogLevel, ValidationPipe } from '@nestjs/common';
4import * as cookieParser from 'cookie-parser';
5import { LoggerInterceptor } from './utils/logger.interceptor';
6
7async function bootstrap() {
8 const isProduction = process.env.NODE_ENV === 'production';
9 const logLevels: LogLevel[] = isProduction
10 ? ['error', 'warn', 'log']
11 : ['error', 'warn', 'log', 'verbose', 'debug'];
12
13 const app = await NestFactory.create(AppModule, {
14 logger: logLevels,
15 });
16
17 app.use(cookieParser());
18
19 app.useGlobalPipes(
20 new ValidationPipe({
21 transform: true,
22 }),
23 );
24
25 app.useGlobalInterceptors(new LoggerInterceptor());
26
27 await app.listen(3000);
28}
29bootstrap();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.
1import { Injectable, OnModuleInit, OnModuleDestroy } from '@nestjs/common';
2import { PrismaClient, Prisma } from '@prisma/client';
3
4@Injectable()
5export class PrismaService
6 extends PrismaClient
7 implements OnModuleInit, OnModuleDestroy
8{
9 constructor() {
10 super({
11 log: ['query', 'info', 'warn', 'error'],
12 });
13 }
14
15 // ...
16}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.
1import {
2 Injectable,
3 OnModuleInit,
4 OnModuleDestroy,
5 Logger,
6} from '@nestjs/common';
7import { PrismaClient, Prisma } from '@prisma/client';
8
9@Injectable()
10export class PrismaService
11 extends PrismaClient<Prisma.PrismaClientOptions, Prisma.LogLevel>
12 implements OnModuleInit, OnModuleDestroy
13{
14 private readonly logger = new Logger(PrismaService.name);
15
16 constructor() {
17 super({
18 log: [
19 {
20 emit: 'event',
21 level: 'query',
22 },
23 {
24 emit: 'event',
25 level: 'error',
26 },
27 {
28 emit: 'event',
29 level: 'info',
30 },
31 {
32 emit: 'event',
33 level: 'warn',
34 },
35 ],
36 });
37 }
38
39 // ...
40}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.
1import {
2 Injectable,
3 OnModuleInit,
4 OnModuleDestroy,
5 Logger,
6} from '@nestjs/common';
7import { PrismaClient, Prisma } from '@prisma/client';
8
9@Injectable()
10export class PrismaService
11 extends PrismaClient<Prisma.PrismaClientOptions, Prisma.LogLevel>
12 implements OnModuleInit, OnModuleDestroy
13{
14 private readonly logger = new Logger(PrismaService.name);
15
16 async onModuleInit() {
17 await this.$connect();
18 this.$use(this.categorySoftDeleteMiddleware);
19 this.$use(this.categoryFindMiddleware);
20
21 this.$on('error', ({ message }) => {
22 this.logger.error(message);
23 });
24 this.$on('warn', ({ message }) => {
25 this.logger.warn(message);
26 });
27 this.$on('info', ({ message }) => {
28 this.logger.debug(message);
29 });
30 this.$on('query', ({ query, params }) => {
31 this.logger.log(`${query}; ${params}`);
32 });
33 }
34
35 // ...
36}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.