古代日志治理
日志提供了观测服务器行为的最根底却最全量的伎俩，过来服务器日志的输入通常须要应用程序自行治理，而当初更常见的做法是间接将日志写入到规范输入由运行环境的日志模块对立治理，两种做法没有实质上的区别，然而随着根底能力一直下沉后者逐步成为趋势，比方：通过 Docker -> fluentd -> Elasticsearch 这样的链路能够进一步对日志进行剖析。
日志模块
Express 官网提供的日志模块 morgan 能够对每个申请输入日志，然而不能进一步追踪响应申请中的各种解决，而且输入格局为一般文本不适宜做日志剖析，须要引入一些新的模块增强日志性能，
在上一章已实现的工程 host1-tech/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 即可对服务器在解决申请时的具体行为了然于胸。
本章源码
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 服务器（十）：日志