如何在 Node.js 中正确的使用日志对象

地址：https://mp.weixin.qq.com/s/Pb51aYdrxAALM_wR4asDgg

日志，是开发者排查问题的非常重要的手段，有时候甚至是唯一的，所以如何合理并正确的打印日志，成了开发时的重中之重。

Node.js 中打日志的方式，一般有几种：

• 1、主动展示
• 2、被动记录

这两种方式都可以由不同的模块来实现，我们接下去就来看看怎么选择。

常见的主动展示

一般来说，主动一般发生在开发期，不确定状态的时候，我们会打印一些消息，比如常见的。

console.log('hello world');

这就是最简单的主动打印的例子。

但是大多数场景下，我们都不会使用 console 来进行打印，毕竟除了内置之外，在性能和功能方面没有特别的优势。

除了大众都知道的 console 模块，在 Node.js 领域还有一个较为知名的 debug 模块。

可以根据命名空间打印出不同颜色的输出，但是最最有用的，则是他的环境变量控制能力。

默认情况下（不包含任何环境变量），控制台不会有任何输出，而当 DEBUG 环境变量被赋值的时候，对应的命名空间的输出才会被打印到 stdout。

$ DEBUG=* node app.js

由于 debug 模块由 TJ 出品，并且在非常早的时候就投入，使用过于广泛，至今仍有非常多的模块使用了它。

Node.js 官方一直希望能够内置一个 debug 模块。从 v0.11.3 开始，终于加上了一个 util.debuglog 方法。

它的功能和 debug 模块类似，同时是内置的模块，所以逐步也有一些模块开始过渡到它。

const util = require('util');
const debuglog = util.debuglog('foo');

debuglog('hello from foo [%d]', 123);

它的开关也类似，使用的是 NODE_DEBUG 环境变量，应该是特意和 debug 模块做了区分。

$ NODE_DEBUG=foo node app.js

被动记录的方式

除了上面提到的类 console 等方式，我们常见的就是各种日志库默认记录的日志，由于这些日志平时只是默默的记录，并不会过多关注，只会在特殊需要的时候（比如差错，定位，计算时）才会查看，所以我们归类为 “被动的方式”。

大多的三方库都有类似的功能，比如 log4j，winston，pino 等等。

这些库的核心功能一般是：

• 1、将日志输出到不同的渠道（比如控制台、文本文件）
• 2、日志格式的自定义（文本或者 JSON）
• 3、日志的输出等级（warn，debug，error）
• 4、其他的一些能力，比如切割和文件轮转，压缩等等

这些库用起来一般就比较简单，获取实例，调用方法输出即可。

logger.info('hello world');

注意，这里我们会观察到输出有一些不一样的地方。

2021-07-22 14:50:59,388 INFO 7739 [xxx] hello world

整个日志是安装上面类似标准的结构来进行输出的，计算是 Error，也是相同的类似格式，那么这个结构包含了哪几部分东西呢？

日志格式

其实整个日志格式追溯，可以到很久以前，不管是 JAVA 默认的 Simple Logger 结构还是类似 nginx 等反向代理服务器的日志，都会包含一些固定的字段，这些固定的字段长久以来形成了一种输出约定，将这些字段组合起来，形成了当今的日志格式。

当前的日志格式一般会包括几个部分。

• 时间戳
• 日志等级
• 进程id（node）
• 日志的标签（label，from xxx class）
• 消息体（字符串或者 error stack）

除此之外，可能还有一些自定义的内容，比如执行消耗的时间，用户 id，文本长度等等内容。

在文本结构的输出中，这些字段将被空格（space）分隔，以换行符作为结尾（\n），这样可以方便外部的日志采集系统采集，比如阿里云的 SLS 等等。

每个公司会有自己的日志采集和输出规范，所以一般常见的库都会支持自定义的日志格式，但是不管如何变化，基础的字段（上述）都还会存在。

随着系统的迭代，先进使用 JSON 格式来记录日志的方式也逐步出现，以 Logstash 为首的一些数据（日志）采集分析一体的工具，也逐步的成熟，对结构化的数据支持的也很好，所以现在常见的库也会同步支持 JSON 格式输出。

正确的打日志

在了解了基本的日志库和体系之后，我们来具体看一看真正打日志的问题。

比如一个简单调用远端服务：

async invokeRemoteAPI() {
  const result = await remoteService.got();
  return {
    result
  };
}

一般，我们会有意识的加上错误处理。

async invokeRemoteAPI() {
  
  try {
    const result = await remoteService.got();
  } catch(err) {
    logger.error('got a error, err=', err);
    throw err;
  }
  
  return {
    result
  };
}

按照上面的标准格式，这个 logger 还需要其他的一些额外信息，比如：

async invokeRemoteAPI() {
  
  const pid = process.pid;
  const startTime = Date.now();
  
  try {
    const result = await remoteService.got();
  } catch(err) {
    const endTime = Date.now();
    logger.error('pid=%s, rt=%s, got a error, err=', pid, Date.now() - startTime, err);
    throw err;
  }
  
  return {
    result
  };
}

如果每个代码都这么写，就会变得无比冗余，所以，我们会提前将日志的输出格式定义完毕，这样，在实际输出的时候就可以简化，比如：

const logger = new CustomLogger({
  format: '${timestamp} ${level} ' + process.pid + ${rt}'
});

async invokeRemoteAPI() {
  const startTime = Date.now();
  
  try {
    const result = await remoteService.got();
  } catch(err) {
    const endTime = Date.now();
    logger.error('got a error, err=', err, {
      rt: Date.now() - startTime
    });
    throw err;
  }
  
  return {
    result
  };
}

所以在特定场景下，如果有固定的日志字段，在日志库允许自定义的情况下，可以先定义好固定的日志格式。

上下文日志

除了最简单的通用日志输出之外，还有一种相对复杂的日志，我们称之为和上下文（请求）绑定的日志，这类日志会输出上下文相关联的数据，比如之前示例中的响应时间，用户请求的 ip，请求的路由，甚至是链路的唯一 ID 等等。

比如：

2021-07-22 14:50:59,388 INFO 7739 [-/127.0.0.1/-/0ms GET /] hello world

这种情况下，再用普通日志的方式加入参数就不合适了。

当然，有些同学会说，我们直接定义一个新的，比如：

class CustomCtxLogger extends CustomLogger {
  constructor(ctx, format) {
    this.ctx = ctx;
    this.format = format;
  }
  
  error(...args) {
    //xxx
  }
  
  info(...args) {
    //xxx
  }
}

这样的做法，每次都会让基类做初始化，会影响部分性能。我们使用另一种方式来减少性能影响，代理传统日志。

我们来看看最简单的实现方式，以 koa 为例。

// 普通日志
const logger = new CustomLogger();

class CtxLogger {
  constructor(ctx, logger) {
    this.ctx = ctx;
    this.logger = logger;
  }
  
  format() {
    return '${timestamp} ${level} ' + process.pid + '[${ctx.refer} ${ctx.rt}]'
  }
}

app.use(async (ctx, next) => {
  // 代理原始日志
  const ctxLogger = new CtxLogger(ctx, logger);
  ctx.logger = ctxLogger;
  
  await next();
});

类似这种通过代理原始日志的方式，即减少了每次初始化新日志时的性能问题，又解决了 ctx 上字段透传的问题。

这也是常见的上下文日志的实践。

简单总结一下

我们了解了常用的日志库以及和日志打印的关系，也简单的实现了日志库以及上下文日志的实现，是不是现在对日志打印了有了一个基本的了解？

这样一套下来，相信你对 Node.js 打印日志的方式更加的了解，也在排错时游刃有余了。