从零搭建 Node.js 企业级 Web 服务器（十）：日志

头像
乌柏木
     中国
    阅读 13 分钟
    26

    现代日志管理

    日志提供了观测服务器行为的最基础却最全量的手段，过去服务器日志的输出通常需要应用程序自行管理，而现在更常见的做法是直接将日志写入到标准输出由运行环境的日志模块统一管理，两种做法没有本质上的区别，但是随着基础能力不断下沉后者逐渐成为趋势，比如：通过 Docker -> fluentd -> Elasticsearch 这样的链路可以进一步对日志进行分析。

    c612ca8418e2c2d41a6d8c63f44578132bbcd231.jpg

    日志模块

    Express 官方提供的日志模块 morgan 可以对每个请求输出日志，但是不能进一步追踪响应请求中的各种处理，而且输出格式为普通文本不适合做日志分析，需要引入一些新的模块加强日志功能，
    在上一章已完成的工程 licg9999/nodejs-server-examples - 09-config 根目录安装以下模块：

    $ yarn add morgan on-finished bunyan uuid # 本地安装 morgan on-finished bunyan uuid
# ...
info Direct dependencies
├─ bunyan@1.8.14
├─ morgan@1.10.0
├─ on-finished@2.3.0
└─ uuid@8.3.0
# ...

    强化日志输出

    现在提升日志功能，期望追踪每一个请求中进行的行为，并且记录每一次异常发生时的详情：

    # .env
LOG_LEVEL='debug'
    // src/utils/logger.js
const bunyan = require('bunyan');
const { name } = require('../../package.json');

const logger = bunyan.createLogger({
  name,
  level: (process.env.LOG_LEVEL || 'debug').toLowerCase(),
});

const LOGGING_REGEXP = /^Executed\s+\((.+)\):\s+(.+)/;

function logging(logger, level = 'trace') {
  return (m, t) => {
    const o = { type: 'sql' };

    const match = m.match(LOGGING_REGEXP);
    if (match) {
      o.transaction = match[1];
      o.statement = match[2];
    } else {
      o.statement = m;
    }

    if (typeof t == 'number') o.elapsedTime = t;

    logger[level](o);
  };
}

module.exports = logger;

Object.assign(module.exports, { logging });
    // src/middlewares/trace.js
const { v4: uuid } = require('uuid');
const morgan = require('morgan');
const onFinished = require('on-finished');
const logger = require('../utils/logger');
const { logging } = logger;

module.exports = function traceMiddleware() {
  return [
    morgan('common', { skip: () => true }),
    (req, res, next) => {
      req.uuid = uuid();
      req.logger = logger.child({ uuid: req.uuid });
      req.loggerSql = req.logger.child({ type: 'sql' });
      req.logging = logging(req.loggerSql, 'info');

      onFinished(res, () => {
        const remoteAddr = morgan['remote-addr'](req, res);
        const method = morgan['method'](req, res);
        const url = morgan['url'](req, res);
        const httpVersion = morgan['http-version'](req, res);
        const status = morgan['status'](req, res);
        const responseTime = morgan['response-time'](req, res);

        req.logger.info({
          type: 'res',
          remoteAddr,
          method,
          url,
          httpVersion,
          status,
          responseTime,
        });
      });

      next();
    },
  ];
};
    // src/middlewares/index.js
// ...
+const traceMiddleware = require('./trace');
const { sessionCookieSecret } = require('../config');

module.exports = async function initMiddlewares() {
  const router = Router();
+  router.use(traceMiddleware());
  // ...
  return router;
};
    // src/config/index.js
const merge = require('lodash.merge');
+const logger = require('../utils/logger');
+const { logging } = logger;

const config = {
  // 默认配置
  default: {
    // ...
    db: {
      dialect: 'sqlite',
      storage: ':memory:',
+      benchmark: true,
+      logging: logging(logger, 'debug'),
      define: {
        underscored: true,
      },
      migrationStorageTableName: 'sequelize_meta',
    },
  },
  // ...
};
// ...
    // src/controllers/shop.js
// ...
class ShopController {
  // ...
  getAll = cc(async (req, res) => {
+    const { logging } = req;
    const { pageIndex, pageSize } = req.query;
-    const shopList = await this.shopService.find({ pageIndex, pageSize });
+    const shopList = await this.shopService.find({
+      pageIndex,
+      pageSize,
+      logging,
+    });

    res.send(escapeHtmlInObject({ success: true, data: shopList }));
  });

  getOne = cc(async (req, res) => {
+    const { logging } = req;
    const { shopId } = req.params;
-    const shopList = await this.shopService.find({ id: shopId });
+    const shopList = await this.shopService.find({ id: shopId, logging });

    if (shopList.length) {
      res.send(escapeHtmlInObject({ success: true, data: shopList[0] }));
    } else {
      res.status(404).send({ success: false, data: null });
    }
  });

  put = cc(async (req, res) => {
+    const { logging } = req;
    const { shopId } = req.params;
    const { name } = req.query;

    try {
      await createShopFormSchema().validate({ name });
    } catch (e) {
      res.status(400).send({ success: false, message: e.message });
      return;
    }

    const shopInfo = await this.shopService.modify({
      id: shopId,
      values: { name },
+      logging,
    });

    if (shopInfo) {
      res.send(escapeHtmlInObject({ success: true, data: shopInfo }));
    } else {
      res.status(404).send({ success: false, data: null });
    }
  });

  delete = cc(async (req, res) => {
+    const { logging } = req;
    const { shopId } = req.params;
-    const success = await this.shopService.remove({ id: shopId });
+    const success = await this.shopService.remove({ id: shopId, logging });

    if (!success) {
      res.status(404);
    }
    res.send({ success });
  });

  post = cc(async (req, res) => {
+    const { logging } = req;
    const { name } = req.body;

    try {
      await createShopFormSchema().validate({ name });
    } catch (e) {
      res.status(400).send({ success: false, message: e.message });
      return;
    }

-    const shopInfo = await this.shopService.create({ values: { name } });
+    const shopInfo = await this.shopService.create({
+      values: { name },
+      logging,
+    });

    res.send(escapeHtmlInObject({ success: true, data: shopInfo }));
  });
}
// ...
    // src/services/shop.js
const { Shop } = require('../models');

class ShopService {
  async init() {}

-  async find({ id, pageIndex = 0, pageSize = 10 }) {
+  async find({ id, pageIndex = 0, pageSize = 10, logging }) {
    if (id) {
-      return [await Shop.findByPk(id)];
+      return [await Shop.findByPk(id, { logging })];
    }

    return await Shop.findAll({
      offset: pageIndex * pageSize,
      limit: pageSize,
+      logging,
    });
  }

-  async modify({ id, values }) {
+  async modify({ id, values, logging }) {
    const target = await Shop.findByPk(id);

    if (!target) {
      return null;
    }

    Object.assign(target, values);
-    return await target.save();
+    return await target.save({ logging });
  }

-  async remove({ id }) {
+  async remove({ id, logging }) {
    const target = await Shop.findByPk(id);

    if (!target) {
      return false;
    }

-    return target.destroy();
+    return target.destroy({ logging });
  }

-  async create({ values }) {
+  async create({ values, logging }) {
-    return await Shop.create(values);
+    return await Shop.create(values, { logging });
  }
}
// ...
    // src/server.js
const express = require('express');
const { resolve } = require('path');
const { promisify } = require('util');
const initMiddlewares = require('./middlewares');
const initControllers = require('./controllers');
+const logger = require('./utils/logger');

const server = express();
const port = parseInt(process.env.PORT || '9000');
const publicDir = resolve('public');
const mouldsDir = resolve('src/moulds');

async function bootstrap() {
  server.use(await initMiddlewares());
  server.use(express.static(publicDir));
  server.use('/moulds', express.static(mouldsDir));
  server.use(await initControllers());
  server.use(errorHandler);
  await promisify(server.listen.bind(server, port))();
-  console.log(`> Started on port ${port}`);
+  logger.info(`> Started on port ${port}`);
}

// 监听未捕获的 Promise 异常，
// 直接退出进程
process.on('unhandledRejection', (err) => {
-  console.error(err);
+  logger.fatal(err);
  process.exit(1);
});
+
+// 监听未捕获的同步异常与 Thunk 异常，
+// 输出错误日志
+process.on('uncaughtException', (err) => {
+  logger.fatal(err);
+  process.exit(1);
+});

function errorHandler(err, req, res, next) {
  if (res.headersSent) {
    // 如果是在返回响应结果时发生了异常，
    // 那么交给 express 内置的 finalhandler 关闭链接
    return next(err);
  }

  // 打印异常
-  console.error(err);
+  req.logger.error(err);
  // 重定向到异常指引页面
  res.redirect('/500.html');
}

bootstrap();

    查看日志

    默认输出的日志是方便机器分析的 JSON 格式，人眼阅读会比较吃力，在查看时可以借助 bunyan 命令行增加可读性与过滤条件。以下为进行店铺编辑时日志输出对比：

    $ # 默认格式输出日志
$ yarn start
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":30,"msg":"> Started on port 9000","time":"2020-07-31T09:19:38.765Z","v":0}
# ...
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"uuid":"6f1ed001-c75a-4bd2-8bae-3293050760bc","level":30,"type":"res","remoteAddr":"::1","method":"GET","url":"/api/shop","httpVersion":"1.1","status":"200","responseTime":"8.831","msg":"","time":"2020-07-31T09:19:40.631Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":20,"type":"sql","transaction":"default","statement":"SELECT `sid`, `expires`, `data`, `created_at` AS `createdAt`, `updated_at` AS `updatedAt` FROM `session` AS `Session` WHERE `Session`.`sid` = 'ZvlC9sSDZHHzkd3XDfOS6GSm2bKALEnv';","elapsedTime":1,"msg":"","time":"2020-07-31T09:19:58.147Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":20,"type":"sql","transaction":"default","statement":"SELECT `id`, `name`, `created_at` AS `createdAt`, `updated_at` AS `updatedAt` FROM `shop` AS `Shop` WHERE `Shop`.`id` = '1';","elapsedTime":1,"msg":"","time":"2020-07-31T09:19:58.160Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"uuid":"848956d2-3dec-4312-b810-21917a8662b5","type":"sql","level":30,"transaction":"default","statement":"UPDATE `shop` SET `name`=$1,`updated_at`=$2 WHERE `id` = $3","elapsedTime":3,"msg":"","time":"2020-07-31T09:19:58.167Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":20,"type":"sql","transaction":"default","statement":"UPDATE `session` SET `expires`=$1,`updated_at`=$2 WHERE `sid` = $3","elapsedTime":2,"msg":"","time":"2020-07-31T09:19:58.174Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"uuid":"848956d2-3dec-4312-b810-21917a8662b5","level":30,"type":"res","remoteAddr":"::1","method":"PUT","url":"/api/shop/1?name=%E8%89%AF%E5%93%81%E9%93%BA%E5%AD%90","httpVersion":"1.1","status":"200","responseTime":"25.301","msg":"","time":"2020-07-31T09:19:58.174Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":20,"type":"sql","transaction":"default","statement":"SELECT `sid`, `expires`, `data`, `created_at` AS `createdAt`, `updated_at` AS `updatedAt` FROM `session` AS `Session` WHERE `Session`.`sid` = 'ZvlC9sSDZHHzkd3XDfOS6GSm2bKALEnv';","elapsedTime":0,"msg":"","time":"2020-07-31T09:19:58.177Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"uuid":"e0a44aa0-4fc9-4d30-bdd4-ae711ff738a0","type":"sql","level":30,"transaction":"default","statement":"SELECT `id`, `name`, `created_at` AS `createdAt`, `updated_at` AS `updatedAt` FROM `shop` AS `Shop` LIMIT 0, 10;","elapsedTime":0,"msg":"","time":"2020-07-31T09:19:58.180Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"level":20,"type":"sql","transaction":"default","statement":"UPDATE `session` SET `expires`=$1,`updated_at`=$2 WHERE `sid` = $3","elapsedTime":2,"msg":"","time":"2020-07-31T09:19:58.185Z","v":0}
{"name":"10-log","hostname":"unoMBP.local","pid":77259,"uuid":"e0a44aa0-4fc9-4d30-bdd4-ae711ff738a0","level":30,"type":"res","remoteAddr":"::1","method":"GET","url":"/api/shop","httpVersion":"1.1","status":"200","responseTime":"6.966","msg":"","time":"2020-07-31T09:19:58.186Z","v":0}
    $ # 增加可读性与过滤条件
$ yarn start | yarn bunyan -o short -l info
# ...
09:24:25.241Z  INFO 10-log:  (uuid=f0a57336-947f-4703-bea7-2d45b873b979, type=res, remoteAddr=::1, method=GET, url=/api/shop, httpVersion=1.1, status=200, responseTime=7.586)
09:24:32.017Z  INFO 10-log:  (uuid=e51df4b4-99be-4f4a-be6a-cbc87e30de60, type=sql, transaction=default, elapsedTime=14)
    statement: UPDATE `shop` SET `name`=$1,`updated_at`=$2 WHERE `id` = $3
09:24:32.027Z  INFO 10-log:  (uuid=e51df4b4-99be-4f4a-be6a-cbc87e30de60, type=res, remoteAddr=::1, method=PUT, httpVersion=1.1, status=200, responseTime=29.926)
    url: /api/shop/1?name=%E8%89%AF%E5%93%81%E5%B0%8F%E9%93%BA
09:24:32.034Z  INFO 10-log:  (uuid=1017d45c-7829-4330-ae30-1985d4a25f2b, type=sql, transaction=default, elapsedTime=0)
    statement: SELECT `id`, `name`, `created_at` AS `createdAt`, `updated_at` AS `updatedAt` FROM `shop` AS `Shop` LIMIT 0, 10;
09:24:32.039Z  INFO 10-log:  (uuid=1017d45c-7829-4330-ae30-1985d4a25f2b, type=res, remoteAddr=::1, method=GET, url=/api/shop, httpVersion=1.1, status=200, responseTime=6.930)

    通过匹配 uuid 即可对服务器在处理请求时的具体行为了然于胸。

    本章源码

    licg9999/nodejs-server-examples - 10-log

    更多阅读

    从零搭建 Node.js 企业级 Web 服务器（零）：静态服务
    从零搭建 Node.js 企业级 Web 服务器（一）：接口与分层
    从零搭建 Node.js 企业级 Web 服务器（二）：校验
    从零搭建 Node.js 企业级 Web 服务器（三）：中间件
    从零搭建 Node.js 企业级 Web 服务器（四）：异常处理
    从零搭建 Node.js 企业级 Web 服务器（五）：数据库访问
    从零搭建 Node.js 企业级 Web 服务器（六）：会话
    从零搭建 Node.js 企业级 Web 服务器（七）：认证登录
    从零搭建 Node.js 企业级 Web 服务器（八）：网络安全
    从零搭建 Node.js 企业级 Web 服务器（九）：配置项
    从零搭建 Node.js 企业级 Web 服务器（十）：日志
    从零搭建 Node.js 企业级 Web 服务器（十一）：定时任务
    从零搭建 Node.js 企业级 Web 服务器（十二）：远程调用
    从零搭建 Node.js 企业级 Web 服务器（十三）：断点调试与性能分析
    从零搭建 Node.js 企业级 Web 服务器（十四）：自动化测试
    从零搭建 Node.js 企业级 Web 服务器（十五）：总结与展望

    javascriptnode.js前端后端服务器
    乌柏木
    2.2k 声望1.1k 粉丝

    认真写点好代码。

    « 上一篇
    从零搭建 Node.js 企业级 Web 服务器（九）：配置项
    下一篇 »
    从零搭建 Node.js 企业级 Web 服务器（十一）：定时任务

    引用和评论

    被 10 篇内容引用
    推荐阅读
    头像
    再见了 Redux、Recoil、MobX、Zustand、Jotai 还有 Valtio，状态管理还可以这样做？

    乌柏木赞 4阅读 2.5k

    头像
    腾讯新闻中心首页改版啦

    小蚊酱赞 11阅读 9.3k评论 7

    头像
    网页设计的垂直居中

    寒青赞 39阅读 4.6k评论 3

    头像
    CSS团队协作规范

    寒青赞 36阅读 3.9k

    头像
    前端如何入门 Go 语言

    robin赞 26阅读 7.7k评论 8

    头像
    100个React最佳实践小技巧

    夕水赞 17阅读 2.6k评论 4

    头像
    不使用 JS 纯 CSS 获取屏幕宽高

    南城FE赞 15阅读 2.1k评论 3

    0 条评论
    得票最新