5基础篇：自定义日志

前言

在所有的后端服务中，日志是必不可少的一个关键环节，毕竟日常中我们不可能随时盯着控制台，问题的出现也会有随机性、不可预见性。一旦出现问题，要追踪错误以及解决，需要知道错误发生的原因、时间等细节信息。

之前的需求分析部分，在网关基础代理的服务中，网关作为所有业务流量的入口也有统一日志落库的需求。所以本章将介绍如何开发一个自定义的日志插件。

开启默认 Logger

NestJS 框架自带了 log 插件，如果只是普通使用，直接开启日志功能即可：

const app = await NestFactory.create(ApplicationModule, { logger: true });

但我们为了框架的性能使用 Fastify 来替换底层框架之后，需要使用下述代码来开启 Fastify 的日志系统：

const app = await NestFactory.create<NestFastifyApplication>(AppModule, new FastifyAdapter({ logger: true }));

接下来，当我们访问 http://localhost:3000/ ，就可以看到控制台已经在正常打印接口请求的日志了：

虽然自带的日志功能开启之后，控制台能够正常打印日志，但是 Fastify 默认的日志输出格式无法满足业务需求。首先，无法快速区分日志类型，打印日志能参考的价值不大，其次，logger 并没有本地落库，后续查找也很麻烦，对于一个实战工程来说，快速定位日志问题以及有本地存储、日志轮转等功能还是必要的。

自定义 Logger

既然自带的日志功能不能满足我们的业务需求，那就需要对默认的日志功能进行拓展。

1. 安装几个必要的依赖：

$ yarn add fast-json-parse // 格式化返回对象

$ yarn add pino-multi-stream // 替换输出流

$ yarn add split2 // 处理文本流

$ yarn add dayjs // 可选，如果自己写时间格式化函数可以不用

1. Fastify 作为一款专注于性能的 HTTP 框架，使用 pino 作为内置日志工具，下面是自定义日志的参数配置：

const split = require('split2')

const stream = split(JSON.parse)

logger: { level: 'info', file: '/path/to/file' // 将调用 pino.destination()

// stream: stream }

开启 file 配置的话，日志会自动存储在本地，如果开启 stream 的配置，就需要自己自定义修改配置，这两者是互斥的，只能配置一个。

每个团队对日志的需求也并不相同，如果想对日志做更多定制化的功能，可以选择开启 stream 配置，自己开发所需要的日志功能。

logStream

1. 新建 common/logger/logStream.ts 文件：

const chalk = require('chalk')
const dayjs = require('dayjs')
const split = require('split2')
const JSONparse = require('fast-json-parse')

const levels = {
  [60]: 'Fatal',
  [50]: 'Error',
  [40]: 'Warn',
  [30]: 'Info',
  [20]: 'Debug',
  [10]: 'Trace'
};

const colors = {
  [60]: 'magenta',
  [50]: 'red',
  [40]: 'yellow',
  [30]: 'blue',
  [20]: 'white',
  [10]: 'white'
}

interface ILogStream {
  format?: () => void
}

export class LogStream {
  public trans;
  private customFormat;

  constructor(opt?: ILogStream) {
    this.trans = split((data) => {
      this.log(data);
    });

    if (opt?.format && typeof opt.format === 'function') {
      this.customFormat = opt.format
    }
  }

  log(data) {
    data = this.jsonParse(data)
    const level = data.level
    data = this.format(data)
    console.log(chalk[colors[level]](data))
  }

  jsonParse(data) {
    return JSONparse(data).value;
  }

  format(data) {

    if (this.customFormat) {
      return this.customFormat(data)
    }

    const Level = levels[data.level];
    const DateTime = dayjs(data.time).format('YYYY-MM-DD HH:mm:ss.SSS A');
    const logId = data.reqId || '_logId_';

    let reqInfo = '[-]';

    if (data.req) {
      reqInfo = `[${data.req.remoteAddress || ""} - ${data.req.method} - ${data.req.url}]`
    }

    if (data.res) {
      reqInfo = JSON.stringify(data.res)
    }

    // 过滤 swagger 日志
    if (data?.req?.url && data?.req?.url.indexOf('/api/doc') !== -1) {
      return null
    }
    return `${Level} | ${DateTime} | ${logId} | ${reqInfo} | ${data.stack || data.msg}`
  }

}

levels 以及 colors 分别是定义日志类型与控制台输出颜色，可以根据自己的习惯或者团队规则进行配置。format 是格式化 Fastify 的日志输出，也可以根据自己的习惯格式化日志格式。log 则是将日志输出到控制台。

logStream.ts 整体比较简单易懂，主要的功能就是格式化日志以及打印日志。

在接入自定义日志后，可以看到控住台输出内容变成如下所示：

对比最开始的默认日志打印格式，现在可以很清晰的从控制台看出日志的类型与内容，方便我们快速定位问题。

fileStream

在接管了控制台输出日志后，我们接着开发日志的落库与轮转功能：

新建 common/logger/fileStream.ts 文件：

import { dirname } from 'path'
import { createWriteStream, stat, rename } from 'fs'

const assert = require("assert")
const mkdirp = require("mkdirp")

import { LogStream } from "./logStream"

const defaultOptions = {
  maxBufferLength: 4096, // 日志写入缓存队列最大长度
  flushInterval: 1000, // flush间隔
  logRotator: {
    byHour: true,
    byDay: false,
    hourDelimiter: '_'
  }
}

const onError = (err) => {
  console.error(
    '%s ERROR %s [chair-logger:buffer_write_stream] %s: %s\n%s',
    new Date().toString(),
    process.pid,
    err.name,
    err.message,
    err.stack
  )
}

const fileExists = async (srcPath) => {
  return new Promise((resolve, reject) => {
    // 自运行返回Promise
    stat(srcPath, (err, stats) => {
      if (!err && stats.isFile()) {
        resolve(true);
      } else {
        resolve(false);
      }
    })
  })
}

const fileRename = async (oldPath, newPath) => {
  return new Promise((resolve, reject) => {
    rename(oldPath, newPath, (e) => {
      resolve(e ? false : true);
    })
  })
}

export class FileStream extends LogStream {
  private options: any = {};
  private _stream = null;
  private _timer = null;
  private _bufSize = 0;
  private _buf = [];
  private lastPlusName = '';
  private _RotateTimer = null;

  constructor(options) {
    super(options)
    assert(options.fileName, 'should pass options.fileName')
    this.options = Object.assign({}, defaultOptions, options)
    this._stream = null
    this._timer = null
    this._bufSize = 0
    this._buf = []
    this.lastPlusName = this._getPlusName();
    this.reload()
    this._RotateTimer = this._createRotateInterval();
  }

  log(data) {
    data = this.format(this.jsonParse(data))
    if (data) this._write(data + '\n')
  }

  /**
   * 重新载入日志文件
   */
  reload() {
    // 关闭原来的 stream
    this.close()
    // 新创建一个 stream
    this._stream = this._createStream()
    this._timer = this._createInterval()
  }

  reloadStream() {
    this._closeStream()
    this._stream = this._createStream()
  }
  /**
   * 关闭 stream
   */
  close() {
    this._closeInterval() // 关闭定时器
    if (this._buf && this._buf.length > 0) {
      // 写入剩余内容
      this.flush()
    }
    this._closeStream() //关闭流
  }

  /**
   * @deprecated
   */
  end() {
    console.log('transport.end() is deprecated, use transport.close()')
    this.close()
  }

  /**
   * 覆盖父类，写入内存
   * @param {Buffer} buf - 日志内容
   * @private
   */
  _write(buf) {
    this._bufSize += buf.length
    this._buf.push(buf)
    if (this._buf.length > this.options.maxBufferLength) {
      this.flush()
    }
  }

  /**
   * 创建一个 stream
   * @return {Stream} 返回一个 writeStream
   * @private
   */
  _createStream() {
    mkdirp.sync(dirname(this.options.fileName))
    const stream = createWriteStream(this.options.fileName, { flags: 'a' })
    stream.on('error', onError)
    return stream
  }

  /**
   * 关闭 stream
   * @private
   */
  _closeStream() {
    if (this._stream) {
      this._stream.end()
      this._stream.removeListener('error', onError)
      this._stream = null
    }
  }

  /**
   * 将内存中的字符写入文件中
   */
  flush() {
    if (this._buf.length > 0) {
      this._stream.write(this._buf.join(''))
      this._buf = []
      this._bufSize = 0
    }
  }

  /**
   * 创建定时器，一定时间内写入文件
   * @return {Interval} 定时器
   * @private
   */
  _createInterval() {
    return setInterval(() => {
      this.flush()
    }, this.options.flushInterval)
  }

  /**
   * 关闭定时器
   * @private
   */
  _closeInterval() {
    if (this._timer) {
      clearInterval(this._timer)
      this._timer = null
    }
  }

  /**
   * 分割定时器
   * @private
   */
  _createRotateInterval() {
    return setInterval(() => {
      this._checkRotate()
    }, 1000)
  }

  /**
   * 检测日志分割
   */
  _checkRotate() {
    let flag = false

    const plusName = this._getPlusName()
    if (plusName === this.lastPlusName) {
      return
    }
    this.lastPlusName = plusName;
    this.renameOrDelete(this.options.fileName, this.options.fileName + plusName)
      .then(() => {
        this.reloadStream()
      })
      .catch(e => {
        console.log(e)
        this.reloadStream()
      })
  }

  _getPlusName() {
    let plusName
    const date = new Date()
    if (this.options.logRotator.byHour) {
      plusName = `${date.getFullYear()}-${date.getMonth() +
        1}-${date.getDate()}${this.options.logRotator.hourDelimiter}${date.getHours()}`
    } else {
      plusName = `${date.getFullYear()}-${date.getMonth() +
        1}-${date.getDate()}`
    }
    return `.${plusName}`;
  }

  /**
   * 重命名文件
   * @param {*} srcPath 
   * @param {*} targetPath 
   */
  async renameOrDelete(srcPath, targetPath) {
    if (srcPath === targetPath) {
      return
    }
    const srcExists = await fileExists(srcPath);
    if (!srcExists) {
      return
    }
    const targetExists = await fileExists(targetPath)

    if (targetExists) {
      console.log(`targetFile ${targetPath} exists!!!`)
      return
    }
    await fileRename(srcPath, targetPath)
  }
}

fileStream.ts 的主要功能是存储日志文件以及日志轮转。文件这块处理的内容比较多，但是从代码角度来看并不复杂，大家可以根据代码注释看完以及对应的功能来理解。

完成上述文件之后，修改 main.ts 接入自定义的日志插件：

import { ValidationPipe, VersioningType, VERSION_NEUTRAL } from '@nestjs/common';
import { NestFactory } from '@nestjs/core';
import {
  FastifyAdapter,
  NestFastifyApplication,
} from '@nestjs/platform-fastify';
import fastify from 'fastify';
import { AppModule } from './app.module';
import { AllExceptionsFilter } from './common/exceptions/base.exception.filter';
import { HttpExceptionFilter } from './common/exceptions/http.exception.filter';
import { TransformInterceptor } from './common/interceptors/transform.interceptor';
import { FastifyLogger } from './common/logger';
import { generateDocument } from './doc';

declare const module: any;

async function bootstrap() {

  const fastifyInstance = fastify({
    logger: FastifyLogger,
  })

  const app = await NestFactory.create<NestFastifyApplication>(
    AppModule,
    new FastifyAdapter(fastifyInstance)
  );

  // 统一响应体格式
  app.useGlobalInterceptors(new TransformInterceptor());

  // 异常过滤器
  app.useGlobalFilters(new AllExceptionsFilter(), new HttpExceptionFilter());

  // 接口版本化管理
  app.enableVersioning({
    defaultVersion: [VERSION_NEUTRAL, '1', '2'],
    type: VersioningType.URI,
  });

  // 启动全局字段校验，保证请求接口字段校验正确。
  app.useGlobalPipes(new ValidationPipe());

  // 创建文档
  generateDocument(app)

  // 添加热更新
  if (module.hot) {
    module.hot.accept();
    module.hot.dispose(() => app.close());
  }

  await app.listen(3000);
}
bootstrap();

重新启动项目之后，可以看到本地根路径的 logs 文件夹下有对应的日志文件生成：

自定义插件参考 fastify-logger 这个项目，原项目是 JS 的版本，在 NestJS 中使用有些麻烦，索性拉下来改成 TS 版本了，另外稍微修改了一些内容适配项目。

写在最后

本章文中贴出的代码只有部分重要的示例，完整的代码示例已上传 demo/v8，需要的同学可以自取。

本章是针对自定义日志的处理，如果项目并不非常复杂，已经足够满足日常开发需求。

但实际上一个企业级的项目在日志处理方面可能会更加复杂，特别是使用 k8s 容器编排部署之后，日志会零散地落库在各个 pod 中，排查问题、恢复数据等操作需要聚合多个 pod 的日志才行，这就需要借助其他的工具例如 elk 等来处理日志。这块内容衍生性比较大，如果有需求，后期可以再拿出来单独讨论一下。