All about Logging in Nodejs with Winston

Logging is one of the best things that happened to Developers. Loggin helps us for monitoring and troubleshoot our application. Logs are the first thing developers will look for to figure out the runtime error of the application.

In this article, we will learn all about Logging in Nodejs. We will be using Winston, one of the popular packages out there.

What is Logging?

Logging is the process of recording application events and data to a log file or any other sources, for the purpose of analysing the system.

Logs help developers to find the error, track the source of the bug and fix it.

While development we can use the console.log or debugger to get the flow of data in the system. But once the application is in production we cannot use the console.log. We can still get the existing logs if we had deployed using a process manager like pm2. Nodejs Deployment with SSL using PM2. But we cannot add or remove logs without stopping the node process.

As we see, the existing console log, may not fulfil our need, so we will be using a logging library called Winston.

What to and not to Log

The purpose of logging is Troubleshooting and Debugging, but its not limited to that, we can gather statistics as well.

We should log meaningful information, it should be balanced not too much not too less. Let's first talk about what we should not log.

We should not log the tokens, sensitive personal information, passwords, users session. Since log messages are stored in plain text, such data will be exposed if the logs fall into the wrong hands.

While Logging, we should include a descriptive message, Thus we can clearly understand based on that message alone. We should provide the right amount of context to the log as well, timestamp, the stack trace of error messages and data as well, to understand the flow.

Winston

Winston is a logging library for Javascript.

A logger for just about everything.

Winston is designed to be a simple and universal logging library, it supports multiple transports for log messages. Transports are the storage medium, they can be files (a log file), console (the standard output), database or any third-party system.

Log Levels in Winston

Winston supports multiple log levels. Log levels are represented by an integer. As specified by RFC5424, the severity of all levels is assumed to be numerically ascending from most important to least important.

Winston has a default log level called npm. Levels are prioritized from 0 to 6 (highest to lowest).


{
error: 0,
warn: 1,
info: 2,
http: 3,
verbose: 4,
debug: 5,
silly: 6
}

Winston allows you to define a level property on each transport which specifies the maximum level of messages that a transport should log.

If a transport is set for level debug, it will save all the logs with level error, warn, info, http, verbose and debug. And similarly, if a transport is set for level error, it will record logs with error level only.

Winston Supports different format for log messages. some build-in formats are

  • timestamp
  • splat
  • colorize
  • json
  • prettyPrint

Winston first example, Logging with Nodejs

Let first intitlize npm project, let's create a folder name 'utils' and create logger.js there. Let's first install winston with npm install winston.

in the logger.js


// utils/logger.js
const winston = require('winston');

const logger = winston.createLogger({
level: 'info',
transports: [
new winston.transports.Console()
]
})

module.exports = logger

In the above code we require the winston, created the logger using createLogger and provide a transport of Console. So, everything we log will be written in the console. The default format is json. As you can see the level is set to info.

In the index.js


// index.js
const logger = require("./utils/logger");

logger.info("Hello World");
logger.warn("Warning message");
logger.error("error message here")
logger.debug("Debug me")

We require the logger. then create some log messages with info, warn, error and debug. The response we got is:


{"level":"info","message":"Hello World"}
{"level":"warn","message":"Warning message"}
{"level":"error","message":"error message here"}

As we can see the "Debug me" is not written to the console.

Let's update the level of the logger. and log the debug again.

logger.level = 'debug';
logger.debug("Debug me")

Now we can get all the messages as well as debug message.

Q. When and how to change the log level?

A. We can create an endpoint, which can be accessed only locally. Where we can set any log level, We may want to get more logs while actively debugging, and error logs otherwise.

Multiple Transport in Winston

As we have already discussed, we can set multiple transport in Winston. Let's save the log on files as well as print them on the console. 

We will use different formats, for each transport. Format for console message, we will log level, message, date and stack if error and meta-objects if any.

// utils/logger.js
const winston = require('winston');

const myFormat = winston.format.printf(({
message,
level,
timestamp,
stack,
...meta
}) => {
let obj;

for (let key in meta) {
if (!obj) {
obj = {}
}
obj[key] = meta[key];
}
return `${timestamp} [${level}]: ${message} ${obj?'\n\t'+ JSON.stringify(obj):''} ${stack?'\n'+stack:''}`;
});


const logger = winston.createLogger({
level: 'info',
transports: [
new winston.transports.File({
filename: 'logs/log.log',
format: winston.format.combine(
winston.format.errors({
stack: true
}),
winston.format.timestamp(),
winston.format.json(),
)
}),
new winston.transports.Console({
format: winston.format.combine(
winston.format.colorize(),
winston.format.errors({
stack: true
}),
winston.format.timestamp({
format: 'Do MMM, YYYY hh:mm:ss a Z'
}),
myFormat,
)
})
]
})

module.exports = logger

For transport of file, we will provide the file name, and format, in this case, the file is log.log inside logs directory. for the format, we use winston.format.combine to compile, stack track for errors, timestamp and save in json.

For console transport, we display local time, colourized, and any objects as well.

To test this, let's log some messages


logger.info("Hello World", {
obj,
obj2
});
logger.warn("Warning message");


const testFunc = () => {
let test;
try {
test = Tester.rasdf();
} catch (error) {
logger.error("error on testFunc", error, {
asdf: "Asdf"
})

}
}
testFunc();

It will give the following output in the console.


14th Jan, 2022 09:46:33 pm +05:45 [info]: Hello World
{"obj":{"asdf":"Asdf"},"obj2":{"asdfasdf":"SAdfasdf"}}
14th Jan, 2022 09:46:33 pm +05:45 [warn]: Warning message
14th Jan, 2022 09:46:33 pm +05:45 [error]: error on testFunc Tester is not defined
ReferenceError: Tester is not defined
at testFunc (/home/devkota/Desktop/logging-in-nodejs/index.js:165:9)
at Object.<anonymous> (/home/devkota/Desktop/logging-in-nodejs/index.js:173:1)
at Module._compile (node:internal/modules/cjs/loader:1101:14)
at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)
at Module.load (node:internal/modules/cjs/loader:981:32)
at Function.Module._load (node:internal/modules/cjs/loader:822:12)
at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
at node:internal/main/run_main_module:17:47

Similarly, log.log file is created on the logs directory which contains.


{"level":"info","message":"Hello World","obj":{"asdf":"Asdf"},"obj2":{"asdfasdf":"SAdfasdf"},"timestamp":"2022-01-14T16:01:33.260Z"}
{"level":"warn","message":"Warning message","timestamp":"2022-01-14T16:01:33.261Z"}
{"level":"error","message":"error on testFunc Tester is not defined","stack":"ReferenceError: Tester is not defined\n at testFunc (/home/devkota/Desktop/logging-in-nodejs/index.js:165:9)\n at Object.<anonymous> (/home/devkota/Desktop/logging-in-nodejs/index.js:173:1)\n at Module._compile (node:internal/modules/cjs/loader:1101:14)\n at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)\n at Module.load (node:internal/modules/cjs/loader:981:32)\n at Function.Module._load (node:internal/modules/cjs/loader:822:12)\n at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n at node:internal/main/run_main_module:17:47","timestamp":"2022-01-14T16:01:33.268Z"}

Updating log level without restart, winston

As we have already discussed, we may not always want to log in debug level. We will set the server on default, info level. If we have to debug, we can set the process to debug level, once the debugging is done, we can set it back to info or error as needed.

To do so, we can create an endpoint, which is either authenticated or disabled from the internet. Using location directive in nginx, or any similar.

Here, we have an endpoint on /nnn/logs which can pass a query level to set the logger level.


app.get('/nnn/logs', (req, res, next) => {
const {
query
} = req;

logger.info("Updating log", {
query
});

logger.level = query.level;

res.status(200).json({
message: "Updated"
})

})

Then we can call "http://localhost:3000/nnn/logs?level=debug" to set it to debug level and "http://localhost:3000/nnn/logs?level=info" to set it to info level.

Child Logger, winston

We can create a child logger as well, Child logger will take a parameter and set it on every log message. We can use child logger in some internal services, so we can track the service as well.


const indexLogger = logger.child({
service: "Index"
})

indexLogger.info("Ha ha");

And the console log of that log is 


14th Jan, 2022 10:35:40 pm +05:45 [info]: Ha ha
{"service":"Index"}

It includes the service there.

Conclusion

We learn that Logging is the process of keeping a record of a running system, which can be used for debugging and troubleshooting. We should log enough data required for debugging, but we should avoid personal and sensitive information on the log. as Logs are saved in plain text. There are various log levels that can be used to log different kinds of information. With Winston, we can write logs on multiple locations at once.

You can find the code used in this article on this github repo.

Posted by Sagar Devkota

0 Comments