2018-10-16发表2018-11-17更新Server / Egg10 分钟读完 (大约1544个字)

Egg日志系统完善

Egg 日志系统完善

Egg已经内置了比较全面的日志了, 比如common-error和egg-web等, 会自动把错误日志聚集到一起等, 但是还缺少后端服务里比较关键的一类: access_log, 以及node用于转发请求较多的情况下, 记录转发的其他请求日志:request_log. 而且现在服务基本都是部署在Docker容器中, Egg日志都是打印在本地磁盘上, 如果需要统一收集也会比较麻烦, 需要一个简单轻量的解决方案

自定义 logger

根据Egg的文档, 添加一个自定义logger非常简单, 只需要在config里添加相关配置, 使用时候获取就行了
同时记得打开前置代理模式, 我们的服务一般都会部署在负载均衡后面, 如果不打开获取的用户IP会是错误的

// config.default.js
module.exports = (appInfo) => {
  config.customLogger = {
    accessLogger: {
      file: path.join(appInfo.root, 'logs', appInfo.name, 'access.log'),
      consoleLevel: 'DEBUG',
    },
    requestLogger: {
      file: path.join(appInfo.root, 'logs', appInfo.name, 'request.log'),
      consoleLevel: 'DEBUG',
    },
  };
  config.proxy = true;
};

access_log

首先来看看接口访问日志如何实现, 在上一篇内容中已经介绍了中间件和开发了错误处理中间件, 那么访问日志就很简单了, 在此中间件中加上相关逻辑就行. 同时这里也会有个问题, 在此中间件之前的报错是无法收集到日志的, 比如csrf中间件, 实际使用中需要注意这个问题.

这里最开始是自动生成request_id, 后来发现我们的LBC有接入tracing, 于是在接入tracing后, 日志里也加入了相关内容, 做到日志全链路打通

module.exports = ({ level = 'DEBUG' }, app) => {
  const logger = app.getLogger('accessLogger');

  return async function wrapper(ctx, next) {
    const now = new Date();
    let access_log = {
      time: now.toISOString(),
      id: ctx.getTraceId(),
      remote_ip: ctx.ip || '',
      host: ctx.request.host,
      method: ctx.request.method,
      uri: ctx.href,
      user_agent: ctx.header['user-agent'] || '',
      http_referer: ctx.header.referer || '',
      status: 200,
      error: '',
      latency: 0,
      latency_human: '0',
      bytes_in: ctx.request.length || 0,
      bytes_out: 0,
      snapshot: LOG_UTILS.getValidateLogMap(ctx.args),
      response_body: {},
    };

    try {
      let result = await next();
      // !! 接口不要直接返回array, 会造成这里判断有误
      if (!ctx.body && !_.isUndefined(result)) {
        if (_.isArray(result)) {
          let [_result, code = 200, msg = ''] = result;
          ctx.body = ctx.wrap({ data: _result, code, msg });
        } else {
          ctx.body = ctx.wrap({ data: result });
        }
      }
      return result;
    } catch (e) {
      if (!_.isError(e)) {
        e = new Error(e);
      }
      e.trace_id = ctx.getTraceId();
      ctx.logger.error(e);
      if (!ctx.res.finished) {
        result = ctx.wrap({ success: false, code: 500, msg: _.toString(e.message) });
        if (level == 'DEBUG') {
          result.stack = e.stack || undefined;
        }
        ctx.body = result;
        ctx.status = 500;
      }
      access_log.error = _.toString(e.message);
    } finally {
      access_log.status = ctx.status;
      const spendTime = Date.now() - now.getTime();
      access_log.latency_human = `${spendTime}ms`;
      access_log.latency = spendTime * 1000000;
      const logStr = JSON.stringify(access_log);
      logger.log('INFO', [logStr], { raw: true });
    }
  };
};

这里面稍微有点坑的地方在于logger.log, 如果不加第三个参数{ raw: true }会发现日志里会自动加上一些时间/进程/级别的头部信息, 导致此条日志不是一个合法的json格式, 解析起来会有问题. 最开始还担心改动起来比较麻烦, 查完源码后发现使用这个参数就能完美的解决这个问题了

request_log

当app启动的时候, 在app.httpclient相关事件中注入日志埋点数据

class AppBootHook {
  constructor(app) {
    const requestLogger = app.getLogger('requestLogger');
    app.httpclient.on('request', (req) => {
      req.__start_time = new Date();
    });
    app.httpclient.on('response', ({ req, res, ctx }) => {
      const http_log = {
        time: req.__start_time.toISOString(),
        id: ctx ? ctx.getTraceId() : '',
        method: req.options.method,
        uri: req.url,
        status: res.status,
        latency: res.rt * 1000000,
        latency_human: `${res.rt}ms`,
        bytes_in: req.size,
        request_time: res.rt,
        snapshot: this.getValidateLogMap(req.args.data),
        result: this.getValidateLogMap(res.data),
      };
      logger.log('INFO', [JSON.stringify(http_log)], { raw: true });
    });
  }
}

rsyslog

上面的两个日志内容开发完成后, 在运行时就能在本地/日志文件夹中看到对应的日志记录了, 现在面临的问题是, 如何把本地Docker容器的日志无缝发送到远端日志收集器中. 了解之后发现使用rsyslog是一个比较好的方案.

Transport

查看Egg文档后, 发现它有提供将日志打印到其他媒介上的很简单的方案: 实现transport, 同时还不会影响到本地日志打印, 先实现一下大概框架

// rsyslog-transport.js
class RsyslogTransport extends Transport {
  constructor(options) {
    super(options);
  }
  log(level, args, meta) {
    const result = super.log(level, args, meta);
    // todo
  }
  close() {
    // todo
  }
}

// app.js
class AppBootHook {
  constructor(app) {
    app.getLogger(loggerKey).set(
      'rsyslog',
      new RsyslogTransport({
        ...app.config.logger,
        level: logger.level,
        app,
        rsyslogConfig: { ...app.config.rsyslog.config },
      }),
    );
  }
}

node-rsyslog

上面的内容开发完后, 发现自定义的日志传输通道就已经生效了, 剩下的就是将日志内容发送到远端的rsyslog-server中

但是试了下npm提供的rsyslog包之后, 发现它不支持TCP发送, 只支持UDP发送, 而且有些细节实现貌似和标准也不一致, 于是只能参考它自己实现一个node-rsyslog.

const _ = require('lodash');
const Transport = require('egg-logger').Transport;
const { RSyslog, SEVERITY } = require('./tools/node-rsyslog');

class RsyslogTransport extends Transport {
  constructor(options) {
    super(options);
    this.rsyslogConfig = options.rsyslogConfig;
    this.initRsysLog();
  }
  initRsysLog() {
    this._rsyslog = new RSyslog(this.rsyslogConfig);
    this._rsyslog.on('error', (err) => {
      this.options.app.logger.error(err);
      this._rsyslog = null;
      if (!this._rsyslog_timer) {
        // 实现简单的自动重连, 但是消息丢了不会重发
        this._rsyslog_timer = setTimeout(() => {
          this.initRsysLog();
          this.options.app.logger.info(`Reconnect rsyslog server`);
          this._rsyslog_timer = null;
        }, 1000);
      }
    });
  }
  log(level, args, meta) {
    const result = super.log(level, args, meta);
    this._rsyslog && this._rsyslog.send(SEVERITY.NOTICE, _.trim(result).replace(/\r?\n/gi, ' '));
  }
  close() {
    this._rsyslog && this._rsyslog.disconnect();
  }
}

module.exports = RsyslogTransport;

整合

最后就剩下将rsyslog的配置抽离到config文件中了, 并且实现不同的日志打印到不同的facility中

// config.js
module.exports = (appInfo) => {
  config.rsyslog = {
    enable: true,
    config: {
      host: '',
      port: 0,
      method: 'TCP',
      appname: `${appInfo.name}-${config.appEnvTag}`,
      hostname: os.hostname(),
      procid: process.pid,
    },
    logger: {
      logger: { appname: `${appInfo.name}-egg`, facility: FACILITY.local0 },
      coreLogger: { appname: `${appInfo.name}-${config.appEnvTag}-core`, facility: FACILITY.local0 },
      errorLogger: { appname: `${appInfo.name}-${config.appEnvTag}-error`, facility: FACILITY.local0 },
      scheduleLogger: { appname: `${appInfo.name}-${config.appEnvTag}-schedule`, facility: FACILITY.local0 },
      accessLogger: { appname: `${appInfo.name}-${config.appEnvTag}-access`, facility: FACILITY.local2 },
      requestLogger: { appname: `${appInfo.name}-${config.appEnvTag}-request`, facility: FACILITY.local4 },
    },
  };
};

// app.js
class AppBootHook {
  constructor(app) {
    if (app.config.rsyslog.enable) {
      _.map(app.config.rsyslog.logger, (loggerConfig, loggerKey) => {
        const logger = app.getLogger(loggerKey);
        logger.set(
          'rsyslog',
          new RsyslogTransport({
            ...app.config.logger,
            level: logger.level,
            app,
            rsyslogConfig: { ...app.config.rsyslog.config, ...loggerConfig },
          }),
        );
      });
    }
  }
}

日志收集

在Docker中直接启动rsyslog, 然后在config文件中配置好地址后, 就可以在有日志的时候, 同步看见rsyslog服务器中的日志打印, 日志收集器也只需要在此机器上采集日志存储到ELK

Egg日志系统完善

https://mosby-zhou.github.io/2018/10-16-egg-logger/

作者

Mosby

发布于

2018-10-16

更新于

2018-11-17

许可协议

#egg

Egg日志系统完善