基于 log4js 做全链路日志

背景

提到监控或应用观测，经常出现三个词：「链路(Tracing)」、「指标(Metric)」和「日志(Logging)」。

所以什么是全链路日志呢？简单说，就是每条日志包含链路 ID（trace id）,比如：

代码语言：javascript复制

{
   "projectName":"some_project",
   "env":"test",
   "uid":"xxxxx",
   "trace_id":"03babddsdscf5-d3f-8eea-26e56459b2",
   "path":"/api/test",
   "cost":"300",
   "startTime":"2022-01-18T15:59:59.048Z",
   "categoryName":"default",
   "data":[
      "响应请求：xxx",
   ],
   "level":{
      "level":10000,
      "levelStr":"DEBUG",
      "colour":"cyan"
   },
   "context":{
      "user_name":"fjywan",
   },
   "pid":1839
}

这条结构化日志中包含一个重要字段：trace_id。根据 trace id 能串起一个请求，从「发起」到「响应」的全部日志：

就好像函数的调用栈，通过这组日志，能观察一个请求的完整情况，哪一步出现了 error，帮助快速定位出现问题的节点。

既然全链路日志对定位问题如此重要，如何在项目中使用呢？

方案设计

trace id 的生成时机

既然记录一个完整请求，那么 trace id 就应该在请求发生的那一刻生成。

请求一般起始于端上，比如初始化页面拉数据、用户行为触发等，所以，端上负责生成 trace id，然后附加到请求上。

通过 HTTP 请求传递 trace id

trace id 属于请求的附加信息，一般放在 header 中。约定 header 中 'X-Request-Id' 放置 trace id。

日志的结构

字符串日志不利于后续分析，所以，输出的日志一定要是结构化的，比如 json。日志中需要记录的必要信息：

trace id：不多说了；
project name：项目或者服务名，尤其微服务架构，很关键，表明哪个服务输出的这条日志；
env：环境，如果日志根据环境存储在不同位置，这个字段就不必要；
uid：用户标识，比如系统的用户 id、用户名等，可以通过 uid 串起一个用户的完整活动日志，就像 trace id 一样；
path：HTTP 请求的路径；
cost：耗时数据；
start time：开始打日志的时间；
level：日志等级，很关键，日志分级是告警的基础，也方便快速定位问题节点。

日志的储存和检索

把日志直接文件储存最简单，但是不利于后续合并检索和分析。这里我们可以借助开源工具，比如经典的 ELK，包含日志搜集、储存和可视化。如果腾讯云，可以使用 LogListener 搜集日志，对接 cls 日志服务，一站式完成容器日志搜集、储存、可视化。

不管哪种日志搜集工具，一般都支持两种来源：file 和 http。

端上采用 http 的方式搜集日志，容器内使用 file 搜集日志。

实现

以 koa HTTP Server 为例，基于 log4js 实现服务端全链路日志搜集。log4js 的详细 API 可以参考：https://log4js-node.github.io/log4js-node/

配置 log4js 输出 json 日志到文件

代码语言：javascript复制

import log4js from 'log4js';
log4js.addLayout('json', config => function (logEvent) {
  return JSON.stringify({
    projectName,
    env: process.env.NODE_ENV || '',
    uid: logEvent.context.uid || '', // uid
    trace_id: logEvent.context.trace || '', // trace_id
    path: logEvent.context.path || '', // request path
    cost: logEvent.context.cost || '', // costtime
    // 里面有 startTime 等标识日志时间的字段
    ...logEvent,
  }, 0)   config.separator;
});
log4js.configure({
  appenders: {
    global: {
      type: 'dateFile',
      filename: 'logs/global',
      pattern: '.yyyy-MM-dd.log',
      alwaysIncludePattern: true,
      layout: { 
        type: 'json', 
        separator: '' 
      },
    },
  },
  categories: {
    default: { 
      appenders: ['global'], 
      level: 'debug' 
    },
  },
});

这里可同时配置多个 appender，比如输出到机器人告警，感兴趣可以参考之前的一篇文章解决告警轰炸的一种实现。

2. 每个请求获取一个新的 logger 实例，并附加 trace id

代码语言：javascript复制

import { v4 as uuidv4 } from 'uuid';
import Koa from 'koa';
import { getLogger } from 'log4js';

const app = new Koa();
app.use(async (ctx, next) => {
  // 每个请求都要一个新的 logger 实例，以便有一个全新的 log context；
  // logger 实例同时挂载 ctx 上，方便取用
  if (!ctx.logger) ctx.logger = getLogger();
  // 添加 trace id
  const traceId = ctx.get('X-Request-Id') || uuidv4();
  // 附加 trace id 到 logger 的 context 上，这样后续每个 log 都会携带 trace id
  ctx.logger.addContext('trace', traceId);
  // 同时附加请求的 path 
  ctx.logger.addContext('path', ctx.request.path);
  await next();
});

3. 每个需要打日志的地方，透传这次请求生成的 logger 实例。

比如 controller 中：

代码语言：javascript复制

import Router from 'koa-router';
export const router = new Router();;
router.get('/api/test', async (ctx) => {
  ctx.logger.debug('hello')
  // 透传 logger 到调用的 service
  const data = someService(ctx.logger)
  ctx.body = {
    retcode: 0,
    message: 'ok',
  };
});

ctx.logger.debug('hello') 的调用不单单是向日志文件输入 hello 的字符串，因为前面定义的 json layout，输出时会附加 logger 的 context，最终类似开头的 json 字符串。

稍微麻烦的地方：任何打日志的函数，都要透传 logger 实例。优化办法可以参考之前的一篇文章如何用domain减少logger的传递

4. 打日志的时机

日志打多了，虽然可能干扰关注点，但无大碍。日志打少了，却可能丢失关键线索，导致无法定位问题。

经验上，有这样几个时机必须要打日志：