Translation: Crazy geek
Original: www.twilio.com/blog/guide-…
Disclaimer: Reprint is prohibited without permission
When you start developing in JavaScript, one of the first things you’ll probably learn is how to log content to the console using console.log. If you search for how to debug JavaScript, you’ll find hundreds of blog posts and StackOverflow articles that simply tell you to use console.log. Since this is such a common practice, we even use linter rules like no-console in our code to ensure that no unexpected log messages are left behind. But what if we really want to record something?
In this article, we’ll take a look at logging in various cases, what’s the difference between console.log and console.error in Node.js, and how to export logs from your library to the user console without clutter.
console.log(`Let's go! `);
Copy the codeTheory first: 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. When you write the following code in node.js to a file named index.js:
console.log('Hello there');
console.error('Bye bye');
Copy the codeExecute it in a terminal with Node index.js and you’ll see the output of both directly:
While they may look the same, they are actually treated differently by the system. If you look at the console section of the Node.js documentation, you’ll see that console.log is output to stdout and console. error is output to stderr.
Each process has three default streams available. Those are stdin, stdout and stderr. The stDIN stream is used to process input to the process. Such as pressing a button or redirecting output. The STdout stream is used for the output of the program. Finally, stderr is used for error messages. If you want to know why there are stderr exists, and when should use it, can be [see] this article (www.jstorimer.com/blogs/worki… – stdout).
In short, this allows us to use in shell redirection (>) and a pipe (|) to handle errors and diagnostic information, they are with the results of the actual output of the program are separated. 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 named hello.log and “Bye Bye” to a file named error.log.
node index.js > hello.log 2> error.log
Copy the code
When should I log?
Now that we’ve looked at the underlying techniques of logging, let’s talk about when you should log content. Usually it should be one of the following:
- Quickly debug unexpected behavior during development
- Browser-based analysis or diagnostic logging
- Log incoming requests to your server and any failures that may occur
- Use the library’s logging debug options to help users resolve problems
- Output progress, confirmation messages, or error messages on the CLI
We’ll skip the first two cases and focus on the latter three based on Node.js.
Server program log
There may be many reasons why you log on the server. Such as logging incoming requests and allowing you to extract statistics such as how many users clicked on a 404 error, or the user-agent of the User’s browser. You also want to know when and why things went wrong.
If you want to try the following, create a new project directory first. Create an index.js in the directory and run the following command to initialize the project and install Express:
npm init -y
npm install express
Copy the codeLet’s set up a server with middleware that outputs only console.log for each request. Copy the following into 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 codeConsole. log(‘%O’, req) is used here to record information about the entire object. Console. log uses util.format underneath to support % O placeholders. You can check them out in detail in the Node.js documentation.
When you run Node index.js to start your server and navigate to http://localhost:3000, it will print out a lot of information we really need but don’t know about.
If we change it to console.log(‘%s’, req) and don’t print the whole object, we won’t get any more information.
We could write our own logging functions to only print the things we care about, but wait, let’s talk about the things we care about in general. While this information is often the focus of our attention, other information may actually be needed:
- Time stamp – Know when something happened
- Computer/server name – if you are running a distributed system
- Process ID – If you use PM2 to run multiple Node processes
- Message – An actual message that contains something
- Other variables or information that may be required
Since everything is going to stdout and STderr, we might want different log levels, as well as the ability to configure and filter logs.
We can get all of this by relying on various parts of process and writing a bunch of JavaScript, but the good news about Node.js is that there is an ecosystem of NPM that already has all kinds of libraries for us to use. Some of them are:
pinowinstonroarrbunyan(Please note that this hasn’t been updated in 2 years)
I prefer pino because it’s very fast. Let’s see how pino can be used to help us log. We can also use express-Pino-Logger packages to log requests.
Install pinO and Express-Pino-Logger:
npm install pino express-pino-logger
Copy the codeUpdate your index.js file to use Logger and middleware with the following code:
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, we create an instance of Pino, Logger, and pass it to Express-Pino-Logger to create a new Logger middleware to call app.use. In addition, we replaced console.log at server startup with logger.info, and added an additional logger.debug to the route to display different log levels.
Run Node index.js again to restart the server, and you’ll see a completely different output that prints JSON per 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’ll see that it contains all the information mentioned earlier, such as timestamps, and so on. You may also notice that the logger.debug statement is not printed. That’s because we have to change the default log level to see it. When we create logger instances, we set the value to process.env.log_level, which means we can change the value with it, or accept the default info. You can adjust the log level by running LOG_LEVEL = debug node index.js.
Before we do that, we need to solve the problem that the current output is not suitable for human reading. Pino follow a philosophy, in order to improve the performance, you should go through the pipe (|) move the output of any processing in a separate process. This includes making it readable or uploading it to a cloud host. These are called Transports. You can look at the TranSports documentation to see why errors in PINO are not written to stderr.
Let’s use the tool Pino-Pretty to see a more readable version of the log. Run in your terminal:
npm install --save-dev pino-pretty
LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty
Copy the codeNow all of the log by using the | operator input to pino – pretty command, pass through your output should be beautification, and also contains some key information, and should be in colour. If you ask http://localhost:3000 again, you should also see the debug message.
There are various Transports to beautify or transform your journal. You can even display emojis with pino-colada. These are useful for your local development. After running the server in production, you may want to transfer the logs to another TranSports and write them to disk with > or a command like tee for later processing.
This document will also contain information on rotating log files, filtering, and writing logs to different files.
Library of log
Now that we’re discussing how to log our server program effectively, why not use the same technique for our library?
The problem is that your library may want to debug by logging, but it should not be confused with the user’s program. Users should be able to enable logging if they need to debug something. By default, your library should be silent and leave the decision of whether to output logs to the user.
A good example is Express. There’s a lot of stuff underneath Express that you might want to peek at while debugging your own programs. If we look at the Express documentation, we’ll notice that you can add DEBUG= Express :* before your own commands, as follows:
DEBUG=express:* node index.js
Copy the codeIf you run this command, you will see a number of other outputs that will help you debug problems in your program.
If you do not have debug logging enabled, you will not see any such logs. This is done through a package called DEBUG. It allows us to write log messages under “namespace” that are printed if the user of the library contains the namespace or matches its wildcard in the DEBUG environment variable. To use the Debug library, first install it:
npm install debug
Copy the codeLet’s emulate our library by creating a new file called random-id.js and copying the following code into it:
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 codeThis creates a new Debug logger with the namespace mylib: RandomID, and then prints the two messages to the log. Let’s use it earlier in index.js:
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 we re-run our server with DEBUG=mylib:randomid node index.js, it will print the DEBUG log from the previous “library”.
If users of your library want to put this debug information into their PINO logs, they can use a library developed by the PinO team called Pino-Debug to properly format these logs.
Install the library with the following command:
npm install pino-debug
Copy the codeBefore we can use Debug for the first time, we need to initialize pino-Debug. The easiest way to do this is to require the module using the Node.js -r or –require flag before launching the command of the javascript script. Run your server again with the following command (assuming you have pino-Colada installed) :
DEBUG=mylib:randomid node -r pino-debug index.js | ./node_modules/.bin/pino-colada
Copy the codeYou will now view the library debug logs in the same format as the program logs.
CLI output
The final case covered in this article is for the special case of CLI logging. My idea is to separate the “logical log” from the OUTPUT “log” of the CLI. For all logical logging, you should use a library like DEBUG. This allows you or someone else to reuse the logic without being tied to a particular use case of the CLI.
When you build a CLI with Node.js, you may want to add some nice colors or format information in a visually appealing way. However, there are a few things to keep in mind when building the CLI.
In one case, your CLI might be used in the context of a continuous integration (CI) system, so you might want to remove colors and fancy decorations from the output. Some CI systems set an environment flag named CI. If you want to make it safer to check if you are in CI, use a package like IS-CI to support a bunch of CI systems.
Libraries like 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. Copy the following into it:
const chalk = require('chalk');
console.log('%s Hi there', chalk.cyan('INFO'));
Copy the codeNow if you would run this script using node cli.js you’ll see colored output. Now if you run this script with Node cli.js, you’ll see 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 runs in terminal mode, that is, writing 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 piped somewhere.
You can check whether STdin, STdout, or stderr are in terminal mode by checking the isTTY property on the corresponding stream. For example, process.stdout.istty. TTY stands for “teletypewriter” and in this case is used exclusively for terminals.
Each of these 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 varies in different cases. Update your cli.js first:
const chalk = require('chalk');
console.log(process.stdout.isTTY);
console.log('%s Hi there', chalk.cyan('INFO'));
Copy the codeRun Nodecli.js on a terminal and you’ll see the output true colored.
Then run the same content, but redirect the output to a file, and check the content:
node cli.js > output.log
cat output.log
Copy the codeYou’ll see that this time it prints undefined followed by a simple colorless message because stdout’s redirection turns off its terminal mode. Because Chalk uses supports color, they check isTTY on the corresponding stream.
Tools like Chalk already handle this behavior for you, but when developing CLI, you should always be aware that the CLI might run in CI mode or redirect output. It can also help you get further into the CLI experience. For example, you can arrange data in terminals in a nice way. If isTTY is undefined, you can switch to a more parsed way.
conclusion
Logging your first line in console.log is pretty quick when you’re starting out in JavaScript development, but you should think more about logging when you’re putting your code into production. This article is purely an introduction to the various approaches and available logging solutions. I encourage you to take a look at some of your favorite open source projects to see how they address logging issues and the tools they use.
If you know or find a tool I didn’t mention, or have any questions, please leave a comment.
Welcome to pay attention to the front-end public number: front-end pioneer, access to front-end engineering practical toolkit.
