Node.js 日志输出指南

原文地址: https://www.twilio.com/blog/g...

原文作者: DOMINIK KUNDEL

翻译作者: icepy

翻译出处: https://github.com/lightningm...

当你开始使用 JavaScript 做开发时，你可能学习到的第一件事情就是如何使用 console.log 将内容打印到控制台。如果你搜索如何调试 JavaScript，你会发现数百个博客文章和 StackOverflow 的文章都指向简单的 console.log 。因为这是一种常见的做法，我们甚至可以使用 no-console 这样的规则来确保生产环境不会留下日志。但是，如果我们真的想要记录这些信息呢？

在这篇博文中，我们将介绍你想要记录信息的各种情况，Node.js 中的 console.log 和 console.error 之间的区别是什么，以及如何在不使用户控制台混乱的情况下在库中发送日志记录。

console.log(`Let's go!`);

Theory First: Important Details for Node.js

虽然你可以在浏览器和 Node.js 环境中使用 console.log 和 console.error，但在 Node.js 中使用时一定要记住一件重要的事情。

将如下代码写入到 index.js 文件中，并在 Node.js 环境里执行：

console.log('Hello there');
console.error('Bye bye');

如图：

虽然这两个输出看起来可能一样，但系统实际上对它的处理方式有不同。如果你检查一下 console section of the Node.js documentation 你会发现 console.log 使用 stdout 打印而 console.error 则使用 stderr。

每一个进程都有三个可以使用的默认 streams，它们是 stdin ，stdout 和 stderr。 stdin 可以处理进程的输入，例如按下按钮或重定向输出。stdout 可以用于处理进程的输出。最后 stderr 则用于错误消息。如果你想了解 stderr 为什么存在以及何时使用它，可以访问：When to use STDERR instead of STDOUT。

简而言之，这允许我们使用重定向 > 和管道 | 运算符来处理与应用程序的实际结果分开的错误和诊断信息。而 > 允许我们将命令的输出重定向到文件，2> 允许我们将 stderr 的输出重定向到文件。我们来看一个例子，它会将 Hello there 重定向输出到 hello.log ，Bye bye 重定向输出到 error.log。：

$ node index.js > hello.log 2> error.log

如图：

When Do You Want to Log?

现在我们已经了解了日志记录的基础技术，那么让我们来谈谈你可能想要记录某些内容的不同例子，通常这些例子都属于以下类别之一：

• 快速调试开发阶段的意外行为
• 基于浏览器的分析和诊断日志记录
• 记录服务器应用程序传入的请求以及可能发生的任何故障
• 某些库的可选调试日志
• CLI的进度输出

我们将跳过本博文中的前两篇文章，并将重点介绍基于Node.js的三篇文章。

Your Server Application Logs

你希望在服务器上记录内容的原因可能有多种，例如：记录传入的请求，统计信息，有多少404用户正在访问，另外你也想知道什么时候出错以及为什么。

初始化项目：

$ npm init -y
$ npm install express

让我们设置一个带有中间件的服务器，只需要 console.log 为你的请求提供打印：

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);
});

这里我们使用 console.log('%o', req); 来记录整个对象。

当你运行 node index.js 并访问 http://localhost:3000 你会注意到打印的很多信息并不是我们需要的。

如果将起更改为 console.log（'％s'，req） 我们也不会获取太多的信息。

我们可以编写自己的日志功能，只打印我们关心的信息。但让我们先退一步，谈谈我们通常关心的事情。虽然这些信息经常成为我们关注的焦点，但实际上我们可能需要其他信息，例如：

• 时间戳-知道事情何时发生
• 计算机/服务器名称-如果你运行的是分布式系统的话
• 进程ID-如果你使用 pm2 运行着多个 Node.js 进程
• 消息-包含某些内容的实际消息
• 堆栈追踪
• 也许是一些额外的变量或信息

另外，既然我们知道打印最后都会落到 stdout 和 stderr 上，那么我们可能想要不同日志级别的记录以及过滤它的能力。

我们可以通过访问流程的各个部分并编写一堆 JavaScript 代码来获取上述的信息，但 npm 生态已经给我们提供了各种各样的库来使用，例如：

• pino
• winston
• roarr
• bunyan

我个人喜欢 pino，因为它速度快，生态全。那么，让我们来看一看 pino 是如何帮助我们记录日志的。

$ npm install pino express-pino-logger

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);
});

运行 node index.js 并访问 http://localhost:3000 你可以看到一行一行的 JSON 输出：

如果你检查此 JSON ，你会看到前面提到的时间戳。你可能还注意到了我们 logger.debug 语句并未打印，那是因为我们必须更改默认日志级别才能使其可见，试试 LOG_LEVEL=debug node index.js 来调整日志级别。

在此之前我们还需要解决一下日志信息的可读性，pino 遵循了一个理念，就是为了性能，你应该通过管道将输出的处理移动到单独的进程中，你可以去查看一下文档，了解其中 pino 的错误为什么不会写入 stderr。

让我们使用 pino-pretty 工具来查看更易读的日志：

$ npm install --save-dev pino-pretty
$ LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty

运行 LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty 并访问 http://localhost:3000。

如图：

另外还有各种各样的库可以来美化你的日志，甚至你可以使用 pino-colada 用 emojis 来显示它们。这些对于你的本地开发非常有用，在运行到生产服务器之后，你可能希望将日志的管道转移到另外一个管道，使用 > 将它们写入硬盘以便稍后处理它们。

比如：

$ LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty | > success.log 2> s_error.log

Your Library Logs

既然我们研究了如何有效的为服务器应用程序编写日志，那么为什么不能将它用在我们的某些库中呢？问题是，你的库可能希望记录用于调试的内容，但实际上不应该让使用者的应用程序变得混乱。相反，如果需要调试某些东西，使用者应该能够启动日志。你的库默认情况下不会处理这些，并将输入输出的操作留给使用者。

express 就是一个很好的例子。

在 express 框架下有很多事情要做，在调试应用程序时，你可能希望了解一下框架的内容。如果我们查询文档，你会注意到你可以在命令行的前面加上 DEBUG=express:* 来启动。

$ DEBUG=express:* node index.js

如图：

如果你没有启动调试日志，则不会看到任何这样的日志输出。这是通过一个叫 debug 的包来完成的。

$ npm install debug

让我们创建一个新的文件 random-id.js 来使用它：

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 };

这里会创建一个带有命名空间为 mylib:randomid 的 debug 记录器，然后会将这两种消息记录上去。

我们可以在 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);
});

然后使用 DEBUG=mylib:randomid node index.js 来重新运行你的 index.js 文件，如图：

有意思的是，如果你的库使用者想把这些调试信息集成到自己的 pino 日志中去，那么他们可以使用一个叫 pino-debug 的库来正确的格式化这些日志。

$ npm install pino-debug

pino-debug 在我们第一次使用之前需要初始化一次 debug，最简单的方法就是在启动之前使用 Node.js 的 -r 或 --require 命令来初始化。

$ DEBUG=mylib:randomid node -r pino-debug index.js | ./node_modules/.bin/pino-colada

如图：

Your CLI Output

我将在这篇博文中介绍最后一个案例，针对 CLI 的日志记录。我的理念是将逻辑日志和你的 CLI 输出分开。对于任何逻辑日志来说，你应该使用类似 debug 这样的包。这样你或其他人就可以重写逻辑，而不受 CLI 的约束。

一种情况是你的 CLI 在持续集成的系统中被使用，因此你可能希望删除各种花里胡哨的输出。有些 CI 系统设置了一个被称为 CI 的环境标志。如果你想更安全的检查自己是否在 CI 系统中，你可以使用 is-ci 这个库。

有些库例如 chalk 已经为你检查了 CI 并帮你删除了颜色。

$ npm install chalk

const chalk = require("chalk");

console.log('%s Hi there', chalk.cyan('INFO'));

运行 node cli.js，如图：

当你运行 CI=true node cli.js，如图：

你要记住的是另外一个场景 stdout 能否在终端模式中运行。如果是这种情况，我们可以使用类似 boxen 的东西来显示所有漂流的输出。但如果不是，则可能会将输出重定向到文件或输出到其他地方。

你可以使用 isTTY 来检查 stdout，stdin，stderr 是否在终端模式。

如：

process.stdout.isTTY

根据 Node.js 的启动方式，这个三个的值可能不同。你可以在文档中找到更多关于它的信息。

让我们看看 process.stdout.isTTY 在不同情况下的变化：

const chalk = require("chalk");
console.log(process.stdout.isTTY);
console.log('%s Hi there', chalk.cyan('INFO'));

然后运行 node index.js ，如图：

之后运行相同的内容，但将其输出重定向到一个文件中，这次你会看见它会打印一个 undefined 后面跟着一个简单的无色消息。

这是因为 stdout 关闭了终端模式下 stdout 的重定向。

chalk 使用了 supports-color ，它会在引擎里检查各个流的 isTTY。

像 chalk 这样的库已经帮你处理了这些行为，但在开发 CLI 的过程中还是要注意，在 CI 模式下运行或输出被重定向的问题。

例如，你可以在终端以一种漂亮的方式来排列数据，如果 isTTY 为 undefined 时，则切换到更容易解析的方式上。

In Summary

在 JavaScript 中使用 console.log 是非常快的，但当你将代码部署到生产环境时，你应该要考虑更多关于记录的内容。

本文仅仅是介绍了各种方法和可用的日志记录解决方案，它不包含你需要知道的一切。

因此我建议你多看一看你喜欢的开源项目，看看它们是如何解决日志记录问题以及它们所使用的工具。