- A Guide to Node.js Logging
- Original post by Dkundel
- The Nuggets translation Project
- Permanent link to this article: github.com/xitu/gold-m…
- Translator: fireairforce
One of the first things you should learn when you start using JavaScript is how to log things to the console via console.log(). If you search for how to debug JavaScript, you’ll find hundreds of blog posts and StackOverflow articles that tell you it’s “easy” to debug using console.log(). Because this is a common practice, we even started using Linter rules, such as no-console, to make sure we didn’t leave unexpected logging in our production code. But what if we really want to record something that provides more information?
In this post, I’ll cover the various situations where you want to log information, the difference between console.log and console.error in Node.js, and how to send logs to the library without affecting the user console.
console.log(`Let's go! `);
Copy the codeTheory one: The important details of Node.js
While you can use console.log or console.error in your browser and node.js, there is one important thing to keep in mind when working with Node.js. Write the following code in a file called index.js:
console.log('Hello there');
console.error('Bye bye');
Copy the codeThen run it from the terminal using Node index.js, and you’ll see the two output directly below:
However, while these two may look the same, the system actually treats them differently. If you look at the console section of the Node.js documentation, you’ll see that console.log is printed using stdout and console.error is printed using stderr.
Each process can work with three streams by default. These are stdin, STdout, and stderr. Stdin stream to handle output relevant to your process. Such as pressing a button or redirecting output (which we’ll do in less than a second). The STdout stream is used for the output of your application. Finally, stderr is used for error messages. If you want to learn more about why stderr exists and when to use it, check out this article.
In short, this allows us to use the redirect (>) and a pipe (|) operator to disposal and the actual application results separate error and diagnostic information. While > allows us to redirect the output of the command to a file, 2> allows us to redirect the output of stderr to a file. For example, the following command passes “Hello there” to a file called hello.log and “Bye Bye” to a file called error.log.
node index.js > hello.log 2> error.log
Copy the code
When do you want to record it?
Now that we’ve looked at the basic logging aspects of logging, let’s talk about different use cases where you might want to log something. Typically these use cases fall into one of the following categories:
- Quickly debug unexpected behavior during development
- Browser-based analysis or diagnostic logging
- Use the server application’s logs to log incoming requests and any failures that may occur
- Library of optional debug logs to help users resolve problems
- Use the OUTPUT from the CLI to print processes, acknowledgement messages, or errors
This blog will skip the first two categories and focus on the last three based on Node.js
Log your server application
There are many reasons why you might want to log on the server. For example, logging incoming requests allows you to extract information from them, such as how many users are accessing 404, what those requests might be, or what user-agent is being used. You also want to know when something goes wrong and why.
If you want to try the following in this part of the article, be sure to create a folder first. Create a file called index.js in the project directory and initialize the entire project and install Express using the following code:
npm init -y
npm install express
Copy the codeThen set up a server with middleware that only needs console.log to serve each request. Put the following contents in the index.js file:
const express = require('express');
const PORT = process.env.PORT || 3000;
const app = express();
app.use((req, res, next) = > {
console.log('%O', req);
next();
});
app.get('/', (req, res) => {
res.send('Hello World');
});
app.listen(PORT, () => {
console.log('Server running on port %d', PORT);
});
Copy the codeWe use console.log(‘%O’, req) to record the entire object. Console. log uses util.format under the hood, which also supports other placeholders such as %O. You can read them in the Node.js documentation.
When you run the Node index.js execution server and navigate to http://localhost:3000, you’ll notice that it will print out a lot of information that we really don’t need.
If we change the code to console.log(‘%s’, req) to not print the entire object, we won’t get much information either.
We could write our own printing function that prints only what we care about, but let’s step back and talk about what we care about in general. While this information is often the focus of our attention, we may actually need other information as well. Such as:
- Timestamps – Used to tell when something happened
- Computer/server name – if you are running a distributed system
- Process ID – if you run multiple Node processes using a tool like PM2
- Message – An actual message that contains some content
- Stack trace – in case we log errors
- There may be some additional variables/information
Also, since we know that everything is going to stdout and STderr, we may need different logging levels and the ability to configure and filter logs based on them.
We can get this by accessing the various parts of the process and writing a bunch of JavaScript code, but the best thing about Node.js is that we get the NPM ecosystem, and there are already various libraries available for us to use. Some of them are:
pinowinstonroarr- Bunyan (note that this library hasn’t been updated in two years)
I personally like the Pino library because it runs fast and has a good ecosystem, so let’s take a look at how pino can help us log. We can also use the Express-Pino-Logger package to help us clean up our logging requests.
Install both PINO and Express-Pino-Logger:
npm install pino express-pino-logger
Copy the codeThen update the index.js file to use loggers and middleware:
const express = require('express');
const pino = require('pino');
const expressPino = require('express-pino-logger');
const logger = pino({ level: process.env.LOG_LEVEL || 'info' });
const expressLogger = expressPino({ logger });
const PORT = process.env.PORT || 3000;
const app = express();
app.use(expressLogger);
app.get('/', (req, res) => {
logger.debug('Calling res.send');
res.send('Hello World');
});
app.listen(PORT, () => {
logger.info('Server running on port %d', PORT);
});
Copy the codeIn this code snippet, we create a Logger instance by pino and pass it to Express-Pino-Logger to create a new middleware and invoke it via app.use. In addition, we replaced console.log with logger.info where the server started, and added a line of Logger.debug to our route to display an additional log level.
If you restart the server by running it again with Node index.js, you’ll see a completely different output that prints JSON for each line. Navigate to http://localhost:3000 again, and you’ll see that another line of JSON has been added.
If you examine the JSON, you will see that it contains all the information mentioned earlier, such as the timestamp. You may also notice that our logger.debug declaration is not printed. That’s because we have to change the default log level to make it visible. When we create logger instances, we set the value to process.env.log_level, which means we can change the value through it, or accept the default info. We can adjust the log level by running LOG_LEVEL=debug node index.js.
Before we do that, let’s get to grips with the fact that the output is not really readable right now. This is intentional. Pino follow a concept, in order to improve the performance, you should go through the pipe (|) output will be treated as log any move into a separate process. This includes making it readable or uploading it to a cloud host. We call these transmissions. Check the documentation on transfers to see why the error in PINO did not write stderr.
We’ll use Pino-Pretty to see the more readable version of the log. Running at a terminal:
npm install --save-dev pino-pretty
LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty
Copy the codeNow, you all log information using the | operator output to pino – pretty. If you ask http://localhost:3000 again. You should also see your debug messages.
There are many existing transport tools that can beautify or transform your logs. You can even display emojis by pino-colada. This will be useful for your local development. After running the server in a production environment, you may want to output the logs to another transport, write them to disk for later processing using >, or use a command like tee for simultaneous processing.
This document will also contain information on things like rotating log files, filtering, and writing logs to different files.
A log of your library
Now that we’ve explored how to log server applications efficiently, why not use the same techniques for the libraries we’ve written?
The problem is, your library may want to log for debugging purposes, but it shouldn’t clutter up the user’s application. Instead, if something needs to be debugged, the consumer should be able to enable logging. Your library should not handle this by default and leave writing to the user.
Express is a good example. There’s a lot to do with the Express framework, and you may want to take a look at it while debugging your application. If we query the Express documentation, you’ll notice that you can prefix your commands with DEBUG=express:* :
DEBUG=express:* node index.js
Copy the codeIf you run this command with an existing application, you’ll see a lot of other output that will help you debug the problem.
If you do not have debug logging enabled, you will not see any such logs. This is done by calling a package called DEBUG. It allows us to write messages under “namespace”, which it prints if the library’s user contains the namespace or matches its wildcard in its DEBUG environment variable. To use the Debug library, first install it:
npm install debug
Copy the codeLet’s try it out by creating a new file random-id.js that mimics our library call and putting code in it like this:
const debug = require('debug');
const log = debug('mylib:randomid');
log('Library loaded');
function getRandomId() {
log('Computing random ID');
const outcome = Math.random()
.toString(36)
.substr(2);
log('Random ID is "%s"', outcome);
return outcome;
}
module.exports = { getRandomId };
Copy the codeA Debug logger is created with the namespace mylib: RandomID, and both messages are logged to it. We then use it in the index.js file from the previous section:
const express = require('express');
const pino = require('pino');
const expressPino = require('express-pino-logger');
const randomId = require('./random-id');
const logger = pino({ level: process.env.LOG_LEVEL || 'info' });
const expressLogger = expressPino({ logger });
const PORT = process.env.PORT || 3000;
const app = express();
app.use(expressLogger);
app.get('/', (req, res) => {
logger.debug('Calling res.send');
const id = randomId.getRandomId();
res.send(`Hello World [${id}] `);
});
app.listen(PORT, () => {
logger.info('Server running on port %d', PORT);
});
Copy the codeIf you restart the server this time with DEBUG=mylib:randomid node index.js, it will print the DEBUG log for our “library”.
Interestingly, if users of your library want to add these debug methods to their PinO logs, they can use a library created by the Pino team called Pino-Debug to properly format these logs.
Use the following command to install the library:
npm install pino-debug
Copy the codePino-debug needs to be initialized once before we use it for the first time. The easiest way to do this is to use the node.js -r or –require identifier before starting the script. Use the following command to restart your server (assuming you have pino-Colada installed) :
DEBUG=mylib:randomid node -r pino-debug index.js | ./node_modules/.bin/pino-colada
Copy the codeYou can now view library debug logs in the same format as application logs.
Your CLI output
The final case I’ll cover in this blog post is the special case of logging for the CLI rather than the library. My idea is to separate logical logs from your CLI output “logs”. For any logical log, you should use a library like Debug. This allows you or someone else to reuse logic that is not tied to a particular use case of the CLI.
When you’re building a CLI using Node.js, you may want to make things look nice by adding colors, spinners, or formatting content in a visually appealing way. However, there are several things you should keep in mind when building the CLI.
In one case, your CLI might be used in the context of a continuous inheritance (CI) system, so you might want to remove colors or any fancy decorative output. Some CI systems set an environment flag called “CI”. If you want to check if you are in CI more securely, you can use packages that already support multiple CI systems, such as IS-CI.
Some libraries such as Chalk already detect CI for you and remove colors for you. Let’s see what it looks like.
Use NPM Install Chalk to install Chalk and create a file called cli.js. Put the following in:
const chalk = require('chalk');
console.log('%s Hi there', chalk.cyan('INFO'));
Copy the codeNow, if you run the script using Node cli.js, you’ll see the corresponding color output.
But if you run it with CI=true node cli.js, you’ll see the color removed:
Another scenario to keep in mind is whether stdout can run in terminal mode. It means to write something to a terminal. If this is the case, we can use something like Boxen to display all the nice output. If not, the output might be redirected to a file or transferred elsewhere.
You can check whether STdin, STdout, or stderr are in terminal mode by checking the corresponding stream properties of isTTY. For example: process.stdout.istty. In this case it is especially used for terminals, TTY stands for “teletype”.
Each of the three streams may have different values depending on how the Node.js process is started. You can learn more about it in the “Process I/O” section of the Node.js documentation.
Let’s look at how the value of process.stdout.istty changes under different circumstances. Update your cli.js file to check it:
const chalk = require('chalk');
console.log(process.stdout.isTTY);
console.log('%s Hi there', chalk.cyan('INFO'));
Copy the codeThen run it on your terminal using Nodecli.js and you’ll see true printing followed by our colored message.
Then run the same thing, but redirect the output to a file, and check the contents by running:
node cli.js > output.log
cat output.log
Copy the codeThis time you’ll see it prints undefined followed by a simple colorless message. Because stdout turns off stdout redirection in terminal mode. Because Chalk uses a supports color, isTTY on each stream is checked under the hood.
However, tools like Chalk already handle this behavior for you, and when you develop CLI, you should always be aware that your CLI may be running in CI mode or the output may be redirected. It can also help you take your CLI experience one step further. For example, you can arrange the data on the terminal in a nice way, and if isTTY is undefined, switch to a more parsed way.
conclusion
It’s quick to start using JavaScript and record your first line using console.log, but you should think about logging more when you take your code into production. This article covers only the various approaches and available logging solutions. It doesn’t contain everything you need to know. I suggest you check out some of your favorite open source projects to see how they address logging issues and the tools they use. Now go record everything, don’t print your log 😉
If you know of or find any tools THAT I should specifically mention, or if you have any questions, please feel free to contact me. I can’t wait to see what you do.
If you find any mistakes in your translation or other areas that need to be improved, you are welcome to the Nuggets Translation Program to revise and PR your translation, and you can also get the corresponding reward points. The permanent link to this article at the beginning of this article is the MarkDown link to this article on GitHub.
The Nuggets Translation Project is a community that translates quality Internet technical articles from English sharing articles on nuggets. The content covers Android, iOS, front-end, back-end, blockchain, products, design, artificial intelligence and other fields. If you want to see more high-quality translation, please continue to pay attention to the Translation plan of Digging Gold, the official Weibo, Zhihu column.