從零搭建 Node.js 企業級 Web 服務器（十）：日誌

時間  2020-08-01
標籤 搭建 node.js node 企業 web 服務器 日誌 欄目 Node.js 简体版
原文   原文鏈接

現代日誌管理

日誌提供了觀測服務器行爲的最基礎卻最全量的手段，過去服務器日誌的輸出一般須要應用程序自行管理，而如今更常見的作法是直接將日誌寫入到標準輸出由運行環境的日誌模塊統一管理，兩種作法沒有本質上的區別，可是隨着基礎能力不斷下沉後者逐漸成爲趨勢，好比：經過 Docker -> fluentd -> Elasticsearch 這樣的鏈路能夠進一步對日誌進行分析。html

c612ca8418e2c2d41a6d8c63f44578132bbcd231.jpg

日誌模塊

Express 官方提供的日誌模塊 morgan 能夠對每一個請求輸出日誌，可是不能進一步追蹤響應請求中的各類處理，並且輸出格式爲普通文本不適合作日誌分析，須要引入一些新的模塊增強日誌功能，
在上一章已完成的工程 host1-tech/nodejs-server-examples - 09-config 根目錄安裝如下模塊：node

$ 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
# ...

強化日誌輸出

如今提高日誌功能，指望追蹤每個請求中進行的行爲，而且記錄每一次異常發生時的詳情：git

# .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 命令行增長可讀性與過濾條件。如下爲進行店鋪編輯時日誌輸出對比：github

$ # 默認格式輸出日誌
$ 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 便可對服務器在處理請求時的具體行爲了然於胸。sql

本章源碼

host1-tech/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 服務器（十）：日誌express

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程