Node.js日志优化之使用RequestId关联日志
背景
现状
现有系统采用pino用于普通日志输出，采用pino-http用于输出服务器请求日志。
./src/createServer.js文件
基于Express创建Server。为了直观简洁，以下仅展示与log相关代码。
'use strict';
const express = require('express');
const logger = require('./utils/logger');
const requestLogger = require('./middlewares/requestLogger');
const errorHandler = require('./middlewares/errorHandler');
const createServer = async () => {
logger.info('Starting to createServer...');
const app = express();
// skip other middlewares...
app.use(requestLogger)
// skip... routers
app.use(errorHandler);
return app;
};
module.exports = createServer;
./src/utils/logger.js
封装pino日志组件，所有日志输出均调用该组件。
'use strict';
const pino = require('pino');
const logger = pino()
module.exports = logger;
./src/middlewares/requestLogger.js*
封装服务器请求日志中间件pino-http，用于打印请求日志。
'use strict';
const pinoHttp = require('pino-http');
const uuidv4 = require('uuid/v4');
const logger = require('../utils/logger.js');
const requestLogger = pinoHttp({
logger,
// Have default ID which is increasing number per process, better use UUID
// to avoid collection in server cluster
genReqId: () => uuidv4(),
});
module.exports = requestLogger;
./src/middlewares/errorHandlers.js*
封装错误处理中间件，用于在最后统一处理请求错误。
'use strict';
module.exports = (err, req, res, next) => {
req.log.error({
context: 'errorHandler middleware',
query: req.query,
body: req.body,
stack: err.stack.split('\n'),
});
const {
errorCode,
statusCode,
name,
message,
} = err;
res
.status(statusCode)
.json({
errors: [
{
errorCode,
name,
message,
},
],
});
};
存在的问题
以上代码能满足基本的日志需求，直到有一天。
程序猿小程抱怨道：“哇，好蛋疼~，上周末ON CALL有问题让我DEBUG，看着成堆的日志查找了半天才发现是评论团队那边的XXXAPI出了问题。”
程序猿小序：“em，所有请求都要经过我们的API Gateway，同一时间的日志确实很多，我也感觉每次DEBUG挺耗时间的，而且每次有问题都会先找我们查找原因🤣。”
程序猿大猿：“我们的错误处理中间件会打印出该请求的错误信息，但有些中间过程产生的错误（如请求其他team的API）并不需要抛出到错误处理中间件处理，这些日志信息的确不太好找，以及在Services或者Drivers里面的日志。我们最好能将每个请求相关的所有日志都串起来，这样不就好排查问题了吗。”
运维小运：“Kibana对日志的搜索功能还是很强大的，而且Amazon CloudFront会给每个请求头添加唯一的ID，你们倒是可以通过对字段x-amz-cf-id进行搜索🤔。”
程序猿大猿：“嗯，那小程你负责去跟进下这个日志的优化问题。”
小程欣然地答应了。
使用RequestId关联日志
思考
“RequestId在request这个对象里面，要怎么使用RequestId关联现有的日志呢？”，小程思考了片刻，最先想到的方法是直接通过函数传值，于是他兴奋地开了个branch尝试去做。
改了几个文件后。。。
“不对啊，这样的方式也太蠢了吧!要在Controllers、Services、Drivers、Utils......，几乎每个函数都加上requestId这个参数，而且这样写出来的代码即难看又冗余。但是不这么做，要如何做到呢？”，小程自言自语到。
小序不小心听到了小程的疑虑，也思考了片刻，“em~看来有点棘手啊，貌似只能从上下文（Context）这个角度入手”。
“嗯，对logger进行进一步的封装，使其拥有不断回溯上下文的能力，这样就可以溯源到request这个对象，进而获取RequestId打印出来。但具体要如何做呢？”，小程回答道。
“这种问题算是比较常见，坊间应该也有对应的方案，何不Google一下？”，小程继续补充到。
通过查阅相关资料，可以通过使用cls-rtracer，或者pino社区推荐的cls-proxify来实现。本文将使用cls-proxify实现。
实现
有了具体的实现思路后，小程兴奋的捣鼓起来。。。
- 首先新增个requestId中间件，如果是通过Amazon CloudFront的请求，使用X-Amz-Cf-Id作为requestId，否则通过uuid生成。
./src/constants/log.js
新增常量便于后期维护
'use strict';
module.exports = {
CLS_KEY: 'clsKeyLogger',
REQUEST_ID: 'X-Request-Id',
};
./src/middlewares/reqeustId.js
requestId中间件，确保RequestId全局统一性。
'use strict';
const uuidv4 = require('uuid/v4');
const CF_HEADER_NAME = 'X-Amz-Cf-Id';
const { REQUEST_ID } = require('../constants/log');
module.exports = (req, res, next) => {
req.id = req.headers[CF_HEADER_NAME.toLowerCase()] || uuidv4();
res.setHeader(REQUEST_ID, req.id);
next();
};
./src/createServer.js
使用requestId中间件
'use strict';
const express = require('express');
const logger = require('./utils/logger');
const requestLogger = require('./middlewares/requestLogger');
const errorHandler = require('./middlewares/errorHandler');
const requestId = require('./middlewares/requestId');
const createServer = async () => {
logger.info('Starting to createServer...');
const app = express();
// skip other middlewares...
app.use(requestId); // use requestId middleware
app.use(requestLogger)
// skip... routers
app.use(errorHandler);
return app;
};
module.exports = createServer;
./src/middlewares/requestLogger
requestLogger的生成的ID使用RequestId中间件生成的，确保统一。
'use strict';
const pinoHttp = require('pino-http');
const logger = require('../utils/logger.js');
const requestLogger = pinoHttp({
logger,
// Have default ID which is increasing number per process, better use UUID
// to avoid collection in server cluster
genReqId: (req) => req.id, // use req.id which generate from requestId middleware
});
module.exports = requestLogger;
- 应用cls-proxify，使得每个request都有相应的child logger。记得安装依赖：npm i cls-proxify cls-hooked
./src/createServer.js
'use strict';
const express = require('express');
const { clsProxifyExpressMiddleware } = require('cls-proxify/integration/express');
const { defaultLogger } = require('./utils/logger');
const requestLogger = require('./middlewares/requestLogger');
const errorHandler = require('./middlewares/errorHandler');
const requestId = require('./middlewares/requestId');
const { CLS_KEY, REQUEST_ID } = require('./constants/log');
const createServer = async () => {
defaultLogger.info('Starting to createServer...');
const app = express();
// skip other middlewares...
app.use(requestId); // use requestId middleware
app.use(requestLogger);
// Integrate pino with CLS.For creating dynamically configured child loggers for each request.
// NOTE: Put any third party middleware that does not need access to requestId before it.
// Details see: https://github.com/keenondrums/cls-proxify
app.use(
clsProxifyExpressMiddleware(CLS_KEY, req => defaultLogger.child({ [REQUEST_ID]: req.id })),
);
// skip... routers
app.use(errorHandler);
return app;
};
module.exports = createServer;
./src/utils/logger.js
'use strict';
const pino = require('pino');
const { clsProxify } = require('cls-proxify');
const { CLS_KEY } = require('../constants/log');
const defaultLogger = pino(config.get('logger'));
const logger = clsProxify(CLS_KEY, defaultLogger);
module.exports = {
defaultLogger, // default logger, won't print RequestId
logger, // logger with CLS feature, will print RequestId if has.
};
大功告成。。。
本地测试通过后，小程兴奋的提了个PR，并注明：
- 确保所有日志都包含对应请求的RequestId，以便我们更顺畅的DEBUG。
- 底层使用了Node.js async_hooks api，需要在性能及日志的易读性间做权衡，不太确定在我们的场景下会对性能有多大影响，有数据测得会下降10% ~ 15%的RPS(request per second)。
此PR的一些参考资料：
https://itnext.io/request-id-tracing-in-node-js-applications-c517c7dab62d
https://nodejs.org/api/async_hooks.html
pinojs/pino#601
https://github.com/keenondrums/cls-proxify#live-demos
大猿review了这个PR，Approve并评论：
Nice Job!
基于我们这个Api gateway的特点，好的日志是很有必要的。
至于性能方面，我们有做Cache，并且Devops在Amozon ClouldFront也做了CDN CACHE，所以影响暂时不会很大。
小程merge这个branch，等CI部署成功后，到Kibana上看了看日志，嘴角微微上扬，喝起了82年的卡布奇洛。
实现到此已告一段落，对原理感兴趣的读者可以继续往下阅读。以下仅供参考，如有错误的地方，欢迎指正。
追根溯源
纸上得来终觉浅，小程不满足于仅仅停留在用完即弃的层面，想要进一步探究其来龙去脉。
在许多其他语言及平台（如Java Servlet container），HTTP服务器是基于多线程的架构及阻塞I/O，这使得它们天然就可以将特定请求所在的线程标识用于跟踪该请求的日志信息。另外，也可以通过使用Thread-local-storage(TLS)以键值对的方式存储/获取当前线程关联的上下文。在我们这个例子中，可以用TLS存储每个请求的ReqeustId或者其他诊断信息。很多的日志框架会默认内置TLS这个特性。
那为什么在Node.js的世界不可以这样做呢？小程思考到。
由于Node.js基于事件循环的异步特性，TLS自然派不上用场，毕竟JS代码是在一个主线程处理的。
“虽然Node.js没有类似TLS的API，但我们也会有类似的需求，该怎么办呢？似乎只能从Context Object（上下文对象）这块入手。”，小程继续思索到。
其实Node.js社区很早前就注意到了这个问题，最终提出了continuation-local-storage(CLS)的概念。CLS就像线程编程中的TLS，但其基于Node.js的回调链而不是线程。起初CLS基于使用process.addAsyncListener API，直到Node.js v0.12该API不可用，之后是通过使用该API的polyfill async-listener来实现。由于这个polyfill做了很多封装内置Node API的猴子补丁，所以不太推荐使用。
幸运的是，CLS库衍生出了后续版本cls-hooked，使用了Node.js v8.2.1后内置的API async_hooks。尽管async_hooks仍然处于试验阶段，但其仍然比使用猴子补丁的CLS要好些。
“cls-hooked是挺好的，能解决回溯context的问题，但是我还是需要做大量的工作封装并将其集成进express以及pino中，不知有没有以及做好这些工作的库？”。小程百思不得其解，直到找到pino社区开发的cls-proxify。
cls-proxify基于cls-hooked并使用了代理模式，可以为每个请求创建一个包含动态上下文的child logger，原理如下图：
“探索知识的过程真的是非常有趣呢！”，小程心想，愉快地将剩下的卡布奇诺一饮而尽。
