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

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

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 打印日志的方式更加的了解，也在排错时游刃有余了。