How to setup production ready logging system in Nest.js
Logging is a very important part of deploying a production ready application. If you have more than 0 customers, it’s highly likely that something will break. How will you know something is broken? How will you know what broke it? How will you debug it? Let’s make this blog go from “explain me like I’m 5” to “just graduated Harvard”.
What is Logging?
When you are debugging a code, you must have put a console.log, print, fmt.Print or a printf statement, depending on your language. This way, if something goes wrong, you can look for that particular print statement in your terminal and debug the code.
This process of printing information on your terminal is called Logging (90% correct definition).
Why is Logging such a headache? Seems quite easy to me?
To understand this, let’s take an example of a findOrganisation function. The caller can pass an organisation ID and the function will return the organisation by fetching it from the database. Let’s say your function looks like this
async function getOrganisationById({ user, organizationId }: { user: User; organizationId: string }): Promise<Organization | null> {
if (user.isAdmin) {
return this.findOrganizationById({ organizationId });
} else {
return this.findOrganizationByUserAndId({ user, organizationId });
}
}There are better ways to implement this function, but for the sake of this blog, let’s just use this example.
Let’s say that the response from this function is undefined and now you’ve to debug this code. What will you do? What’s the first thing to do? You might want to check if the organisation ID passed to this function wasn’t null or falsy. Let’s say now you know that the organisation ID is correctly passed. The next obvious step is to check if both findOrganizationById and findOrganizationByUserAndId are working fine. But which function was triggered — findOrganizationByUserAndId or findOrganizationByUserAndId?
To find this out you will have to put a console.log(user) and check which function is getting triggered. Then you can get inside that particular function and debug further.
But there’s a pattern here, if you have noticed. The pattern is, to understand what’s going wrong you need to know the entire information about the caller, what information was passed in by the caller, all the parameters, the environment conditions, etc.
When you have a backend server running, you can’t wait for an incident to happen and then go back and add consoles. If you do this, then you will have to wait for the incident to happen again so you can gather information on what caused it.
So In case of backed servers, you need to log every request. One request is user hitting one of your API endpoint. So if someone sends one GET request, it’s considered as one request. In such you will want to print the entire request, including the user information, the resources they are trying to access, request body, query parameters, etc.
Wait, a backend server is not running on my machine. It is hosted on some platform. How will I see these logs?
Well you’re right. Technically you can run the server on your own machine to be able to see the logs, but that involves other technicalities. So let’s just say you’re a sane person and just like any other sane developer you choose to host your backend on a cloud service provider like AWS.
For AWS, let’s assume you use Elastic Beanstalk to host the server. To see the logs in this scenario you can simply open that beanstalk instance, and request “last 100 lines” or “log bundle”.
There’s one last problem with logs — Usability
When you have your logs like this in your hosted platform you can’t actually query them. There’s no single dashboard for you to see, exactly how many 404s or 403s you have. Sometimes you want alerts on certain conditions. For example : When more than 30% of the requests in a period of 15 minute have 500 status code, alert me on Slack. This way if a service is down, you will be alerted and you can respond on this quickly.
For this, we have Log handling softwares like Pm2, Datadog, LogRocket, etc. They make it easier for you to look at each request log separately. They provide other functionalities like filter, query, add alerts, etc.
When you connect a log service with your hosting platform, the hosting platform will send each line of log directly to your log holder. In our example: AWS Elastic beanstalk will send each log line to Datadog. Datadog will assume that each line is one request. But wait that’s not right.
But there’s still one last problem specific to Nest.js. One line is not one request.
When you do console.log(variable), and your variable is let’s say a JSON object, each line of that object is printed on a separate line.
Datadog will think that “{“ is one request, ‘path:”/api/v1/user/me”’ is one request, ‘“user”: {’ is one request. This is wrong. But how to fix this? Pattern here is, each request should be on one line. The entire JSON that you are printing, should come in one line.
By default Nest.js doesn’t provide a single line logging support. Hence, we need to use an external package. One such package is Apache Log4j. But we are not going to use that, and if you don’t know why, then you are truly new here. Read more about why not to use Log4j here.
Instead we are going to use Winston, it’s like Log4j but secure. What Winston does is, it takes your huge bulky multi-line log and transforms it into a single line log. Now each line is one request. Perfection!
So that’s it. Log every line and every request details. Are we good to go now?
I hope yes but no. Now we know we need to store our logs in a third party system like Datadog. Imagine if a user hits your /POST/user/ API endpoint to sign up and you are logging the entire request body. Then their email and password will also be logged along with other PII.
PII stands for Personal Identifiable Information and these are unique information that are very personal for the user and if leaked can be harmful for them. Examples of PII includes complete user name with their emails, contact details, their social security number, date of birth, etc. Why? Because if you have these PII it’s easy to breach into other accounts that user holds by social engineering, phishing attacks or other methods.
There are very strict laws regarding storing, processing and sharing of PII. For instance GDPR is very strict about this. But then GDPR is strict about everything. Moving on.
So If the endpoint is POST/user/ don’t log the request body. Simple?
Well that won’t work. What if you log their access token on some other endpoint? Selectively printing different logs for different endpoint is not a good solution. Also every time when you add an endpoint you will have to think about updating the logger.middleware.ts and that’s not a good DX either.
Enters Asymmetric Cryptography
The simplest solution is to print every request related detail but encrypt all user related data. Means the API endpoint, the IP address, the request headers, etc should be printed as plain string, but the request body should be encrypted.
Why asymmetric encryption?
Because let’s say something goes wrong or there’s a 500, you might need to take a look at the request body to determine what went wrong. For that you should be able to decrypt the request body, hence asymmetric encryption. The perfect choice is Rivest-Shamir-Adleman (RSA) encryption. You can use the public key to encrypt the request body, and let it get logged.
This way even if you accidentally release any PII in your logs and they get sent over to a third party holder, there’s no possibility of data breach. Whenever you need to take a look at the request body, you can always use the private RSA key to decrypt the body.
Okay, one line log + log all request data + encrypt request body asymmetrically. That’s it?
Yes, that’s probably it. It will be nice if you can also log the response body, it’s very helpful sometimes. It’s just a bit hard to do.
Anyways, here’ my implementation of a logger for Nest.js using Winston and RSA encryption.
import { Injectable, NestMiddleware } from "@nestjs/common";
import { Response, NextFunction } from "express";
import { ENVIRONMENT_NAMES } from "src/common/configuration/backend.config";
import { ENV_VARS } from "src/common/constants/envs";
import { encryptObject } from "src/common/helpers/transform-objects";
import { GuardedRequest } from "src/common/types/request.types";
import * as winston from "winston";
@Injectable()
export class LoggerMiddleware implements NestMiddleware {
private winstonLoggerErrorLevel = this.createSingleLineLogger("error");
private winstonLoggerInfoLevel = this.createSingleLineLogger("info");
createSingleLineLogger(logLevel: string) {
return winston.createLogger({
level: logLevel,
format: winston.format.json(),
transports: [new winston.transports.Console()],
});
}
isErroneousStatusCode(statusCode: number) {
return statusCode >= 400 && statusCode < 600;
}
encryptRequestBodyOnProduction(body: object) {
if (ENV_VARS.NODE_ENV === ENVIRONMENT_NAMES.PRODUCTION) {
return encryptObject(ENV_VARS.LOGGER_RSA_KEY_PUBLIC, body);
} else {
return body;
}
}
// In most cases this will be your express.js request type
// We overwrite our request and embed extra info into it
// so the type is GuardedRequest
use(request: GuardedRequest, response: Response, next: NextFunction): void {
if (process.env.NODE_ENV !== ENVIRONMENT_NAMES.LOCAL) {
const { ip, method, originalUrl } = request;
const userAgent = request.get("user-agent") || "";
response.on("finish", () => {
const { statusCode } = response;
const contentLength = response.get("content-length");
const basicRequestMetaInfo = {
method,
originalUrl,
statusCode,
contentLength,
userAgent,
ip,
timestamp: new Date(),
};
if (this.isErroneousStatusCode(statusCode)) {
const additionalRequestMetaInfo = {
body: this.encryptRequestBodyOnProduction(request.body),
query: request.query,
params: request.params,
headers: request.headers,
user: request.user,
};
this.winstonLoggerErrorLevel.error({ ...basicRequestMetaInfo, ...additionalRequestMetaInfo });
} else {
this.winstonLoggerInfoLevel.info(basicRequestMetaInfo);
}
});
}
next();
}
}This is the implementation of the encryptObject function.
import * as NodeRSA from "node-rsa";
export function encryptObject(publicKey: string, body: object) {
const key = new NodeRSA();
key.importKey(publicKey, "pkcs8-public-pem");
return key.encrypt(JSON.stringify(body), "base64");
}In Nest.js to create your own logger, you just need to create a middleware. Then in your app.module.ts you can consume it for every endpoint
export class AppModule implements NestModule {
configure(consumer: MiddlewareConsumer) {
consumer.apply(JWTAuthMiddleware).forRoutes("*");
consumer.apply(LoggerMiddleware).forRoutes("*");
}
}This will not convert your local console.error and console.log into single line logs. This implementation is only for logging your requests.
If you want that your console.error and console.logs are also logged as single line log. You need to implement your own logger class and everywhere in your code, instead of using console, use that logger. Nest.js have a good documentation on how to do this here.
But that’s it. This is all you need to do to have a production ready logging system setup.
