从零搭建 Node.js 企业级 Web 服务器（十）：日志
现代日志管理
日志提供了观测服务器行为的最基础却最全量的手段，过去服务器日志的输出一般须要应用程序自行管理，而如今更常见的作法是直接将日志写入到标准输出由运行环境的日志模块统一管理，两种作法没有本质上的区别，可是随着基础能力不断下沉后者逐渐成为趋势，好比：经过 Docker -> fluentd -> Elasticsearch 这样的链路能够进一步对日志进行分析。html
日志模块
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