【译】Node.js 日志打印指南

15,232 阅读7分钟

当你开始使用JavaScript开发时,可能要学习的第一个技能就是如何使用console.log将内容打印到控制台。如果你搜索如何调试JavaScript,将会发现数百篇博客和StackOverflow文章指向console.log。因为这是一种很常见的方法,我们甚至开始使用像no-console这样的linter规则来确保我们不会在生产代码中留下意外的日志语句。但是如果我们真的想通过打印一些东西来提供更多的信息呢?

在这篇文章中,我们将探讨各种需要打印信息的场景;Node.js中console.logconsole.error之间有什么区别;以及如何在不扰乱用户控制台的情况下在库中记录日志。

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

首要理论:Node.js的重要细节

假如我们能在浏览器或者Node.js中使用console.logconsole.error,那么在使用Node.js时,有一件重要的事情是要记住的。在一个名为index.js的文件中使用Node.js编写以下代码时:

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

并在终端使用node index.js执行它,你会看到它们并排输出了:

然而,尽管这两者看起来相同,但实际上系统对它们的处理是不同的。查看Node.js文档关于console的介绍,我们可以看到,console.log输出到stdoutconsole.error输出到stderr

每个进程默认有三个可以使用的流:stdin, stdoutstderrstdin流处理进入程序的输入。例如,按钮按下或重定向输出(我们稍后会讲到)。stdout流用于应用程序的输出。最后,stderr用于错误消息。如果你想了解为什么存在stderr以及何时使用它,请参阅这篇文章

简而言之,我们可以使用重定向(>)和管道(|)操作符将应用程序的错误和诊断信息结果分离显示。>操作符允许我们将stdout的输出重定向到文件中,而2>允许我们将stderr的输出重定向到文件中。例如,这个命令将“Hello there”导入一个名为Hello.log的文件,并将“Bye Bye”导入一个名为error.log的文件。

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

什么情况下我们需要log?

既然我们已经了解了一些关于日志的底层技术方面的知识,那么接下来让我们来讨论一下可能需要记录日志的场景。通常这些场景包含以下类别:

  • 开发过程中快速调试异常
  • 基于浏览器的日志记录,用于分析或诊断
  • 记录服务应用日志,以记录传入的请求以及可能发生的任何故障
  • 库的可选调试日志,以协助用户排查问题
  • 通过CLI打印进度、确认信息或错误

下面的内容我们将跳过的前两个场景,重点介绍跟Node.js有关的后面三个场景。

服务应用日志

在服务器上记录日志的原因可能有很多。例如,通过记录传入的请求我们可以用来做信息统计,比如用户遇到有多少404请求,这些请求可能是什么,或者正在使用什么User-Agent。我们也想知道什么时候出了问题,原因是什么。

如果你想尝试本文下面内容,请创建一个新的项目目录。在项目目录中创建index.js用于编写代码的程序运行入口。运行以下代码初始化项目并安装express:

npm init -y
npm install express

让我们设置一个带有console.log的中间件的服务器。将以下内容放入index.js文件中:

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('$0',req)用于记录整个对象。console.log底层使用util.format方法支持%O占位符。详细信息可以在Node.js官方文档中了解。

当执行node index.js来执行服务器并访问http://localhost:3000时,你会注意到它将打印出许多我们并不真正需要的信息。

即使我们将其更改为console.log('%s', req)不打印整个对象,也不会得到太多有用的信息。

我们可以写我们自己的log函数,只输出我们关心的东西。但是在此之前,我们先讨论下通常需要关心什么。虽然太多信息分散我们注意力的集中,但实际上我们也需要充分的信息。如:

  • 时间戳——知道事情发生的时间
  • 计算机/服务器名称——如果你正在运行一个分布式系统
  • 进程ID——如果你正在使用类似pm2的东西运行多个节点进程
  • 消息——包含一些内容的实际消息
  • 堆栈跟踪——用于记录错误的场景
  • 其他一些额外的变量/信息

此外,既然我们已经知道所有内容都将进入stdout和stderr流,那么我们可以借助它们实现不同级别的日志,以及根据它们配置和筛选日志的能力。

我们可以通过访问进程的各个部分并编写一堆JavaScript来实现所有这些功能,但Node.js最棒的一点是,拥有npm生态系统,而且已经有各种库可供我们使用。例如:

  • pino
  • winston
  • roarr
  • bunyan (注意:这个已经两年没有更新了)

我个人喜欢pino,因为它速度快,生态也很好。让我们看看如何使用pino帮助我们进行日志记录。奇妙的是已经有一个express-pino-logger包,我们可以使用它来记录请求。

安装pinoexpress-pino-logger:

npm install pino express-pino-logger

然后更新index.js文件,使用日志记录器和中间件:

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

在这个代码片段中,我们创建了一个pino的日志程序实例,并将其传递到express-pino-logger中来创建一个新的日志程序中间件以便app.use调用。此外,我们在服务启动的时候用logger.info替换console.log,并向路由添加了一个额外的logger.debug,以显示不同级别的日志。

如果通过再次运行node index.js启动服务器。你会看到一个非常不同的输出,它每一行输出一个JSON。再次访问http://localhost:3000,你将看到添加了一行新的JSON。

如果检查这个JSON,你将看到它包含前面提到的所有信息,比如时间戳。你还可能注意到我们的logger.debug语句没有打印出来。这是因为我们使用了默认的日志级别。创建logger实例时,我们通过设置process.env.LOG_LEVEL的值改变日志级别,默认值为info。通过运行LOG_LEVEL=debug node index.js,我们可以调整日志级别显示debug类型的日志。

在此之前,让我们先讨论这样一个事实:现在的输出实际上可读性很差。然而这是故意的。pino遵循一种原则,即更高的性能。我们也可以通过管道(使用|)将所有进程的日志移动到一个单独的进程中,用于提高其可读性或将数据上载到云服务器。这个过程叫做transports。查看关于transports的文档,还可以了解为什么pino中的错误没有被写入stderr

让我们使用工具pino-pretty查看更具可读性的日志版本。在终端执行一下命令:

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

现在,使用|操作符,所有的日志将通过管道传输到pino-pretty,你的输出应该变得清晰,包含了关键信息并且被着色。再次访问http://localhost:3000,还应该能看到debug级别的消息。

有许多现成的传输工具可以美化或转换日志。你甚至可以用pino-colada工具使其支持表情符号的显示。这些将对你本地的开发非常有用。在生产环境中运行服务器之后,你可能希望将日志导入到另一个传输中,使用>将日志写入磁盘,以便稍后处理它们,或者使用tee之类的命令进行处理。

官方文档还介绍关于日志文件归档、过滤和将日志写入不同文件等内容。

你的库日志

既然我们已经了解了如何为服务器应用程序高效地编写日志,为什么不为我们编写的库使用相同的技术呢?

问题是,我们希望打印出库用于调试的内容,但也不能混淆使用者的应用程序。如果需要调试某些东西,使用者应该能够启用日志。你的库在默认情况下应该是静默的,并将是否打印日志留给使用者决定。

express就是一个很好的例子。express的底层做了很多事情,在调试应用程序时,你可能想了解一下底层的情况。如果我们查阅express文档,便会注意到启动相关日志只需要在命令前加上DEBUG=express:*:

DEBUG=express:* node index.js

使用现有的应用程序运行该命令,你将看到许多额外的输出,这些输出将帮助你调试问题。

如果没有启用调试日志记录,就不会看到这些。这是是通过一个名为debug的包来实现的。它允许我们在指定“名称空间”下编写消息,如果库的使用者在调试环境变量中包含与之匹配的名称空间或通配符,它将输出这些消息。

要使用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的新调试日志实例,其打印了两条消息。让我们在上一章的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,它将打印我们的“库”的调试日志。

有趣的是,如果你的库使用者希望将此调试信息放入他们的pino日志中,他们可以使用pino团队提供的pino-debug库来正确格式化这些日志。

使用以下方法安装库:

npm install pino-debug

在第一次使用debug之前,需要初始化pino-debug。最简单的方法是在启动脚本之前使用Node.js的-r——require标志来引入模块。使用如下命令重新运行服务器(假设已经安装了pino-colada):

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

现在,你将看到库的调试日志与应用程序日志的格式相同。

CLI(命令行界面)输出

在这篇文章中,我们将讨论的最后一种情况是CLIs而不是库的特殊日志记录情况。我的原则是将逻辑日志与CLI输出的“日志”分开。对于任何逻辑日志,都应该使用debug之类的库。这样,你或其他人就可以重用逻辑,而不受CLI特定用例的限制。

当你的Node.js应用采用CLI构建时,你可能希望通过添加颜色、标记或以一种特定的具有视觉吸引力的方式格式化内容,使其看起来更漂亮。然而,在使用CLI构建时,你应该记住以下几个场景。

一种场景是,你的CLI可能在持续集成(CI)系统的上下文中使用,因此你可能希望删除颜色或任何花哨的装饰输出。一些CI系统设置了一个称为CI的环境标志。如果你想更安全地检查你是否在CI中,可以使用is-CI这样的包,它已经支持许多CI系统。

一些库,如chalk,已经为你检测是否CI环境并为你删除颜色。接下来让我们一起看下使用它之后的样子。

使用npm安装chalk并创建一个名为clip .js的文件。放入以下代码:

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

现在,如果你使用node clip.js运行这个脚本,你将看到彩色的输出。

但是如果你用CI=true node clip .js运行它,你会看到颜色被抑制了:

你要记住的另一个场景是,如果你的stdout运行在终端模式中,表示内容写入终端。如果是这种情况,我们可以使用boxen之类的东西来显示所有漂亮的输出。如果不是,很可能输出被重定向到文件或管道的某个地方。

你可以通过检查相应流上的isTTY属性来检查stdinstdoutstderr是否处于终端模式,例如:process.stdout.isTTY。TTY代表“teletypewriter(电传打字机)”,在本例中特指终端。

根据Node.js进程的启动方式,这三个流的值可能有所不同。你可以在Node.js文档的“process I/O”部分了解更多。

让我们看看process.stdout的值。isTTY在不同的情况下是不同的。更新你的clil.js文件,以检查它:

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

现在在你的终端中运行node clip.js,你会看到true后面跟着我们的彩色消息。

之后运行相同的东西,但重定向输出到一个文件,并检查内容后运行:

node clip .js > output.log
cat output.log

你将看到,这一次它打印的是undefined,后面跟着一条纯色的消息,因为stdout的重定向关闭了stdout的终端模式。chalk使用了support-color检查相应流上是否支持TTY。

类似chalk这样的工具已经为你处理了这种场景。但是,在开发CLI时,你应该始终了解CLI可能在CI模式下运行或重定向输出的情况。它还可以帮助您进一步获得CLI的体验。例如,你可以在终端中以漂亮的方式排列数据,如果isTTY未定义,则切换到更容易解析的方式。

总结

开始使用JavaScript并使用console.log记录第一行代码非常快,但是当你将代码投入生产时,你应该考虑更多关于日志的内容。这篇文章仅仅介绍了各种方法和可用的日志解决方案。但它不包含你需要知道的一切。我建议你查看一些你最感兴趣的开源项目,了解它们如何解决日志记录问题以及使用哪些工具。现在去记录所有的信息,而不是仅仅打印日志吧😉。

原文:A Guide to Node.js Logging