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 是很是快的，但当你将代码部署到生产环境时，你应该要考虑更多关于记录的内容。

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

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