之前在写业务需求的时候，需要记录慢查询和慢请求的耗时，并上报给ES。还会有其他类型的日志需要记录和上报，一开始没有统一的字段，各类日志的字段比较松散，现在需要统一日志字段。这个需求说起来简单，提取一些公共字段，比如type、timeTaken、data等字段，还有一些公共字段，比如username、method、url等，这些公共字段不需要传infromoutside，只需要从请求上下文中获取即可。如果以上方法可以完美解决需求，本专栏文章可以马上发表，但现实总是比想象的要复杂。由于很多地方都使用了上报日志的方法（以下简称sendLog），而一开始并没有传递req对象，也就是说，如果使用上面的方案，必须在sendLog中添加参数，以及req对象必须在request中处理handler层层传递给sendLog。对于一个上线十个月的项目来说，改造比较麻烦，不够好（zhuang）和优雅（bi）。那么有没有一种方法不需要传递req对象就可以方(you)方便(ya)的方法获取请求上下文呢？转战Google和StackOverflow找了半天，发现了一个NPM包express-http-context。该软件包每周有30k+次下载。阅读了介绍中的描述，发现它优雅且易于使用。我立刻觉得现在应该稳定了。经过一个例行的操作，就开始运行了，不需要传递req对象就可以获取到共享参数。各种本地测试用例一个一个来，结果一个字——完美！这才叫专业，这才叫完美！本着负责（neng）负责（run）、尽（jiu）责（xing）的态度，抓紧测试上线。先去一个测试环境，观察一段时间，没有问题，再发到生产环境。观察了一段时间，发现日志正常，CPU和RAM也都正常。关机并离开工作。背景以上很多都是背景。新题发布上线很久之后，有一天我从日志中发现MySQL慢查询日志中的公共字段都是空的。问题是用的姿势不对？还是上下文丢失了？经过搜索，我发现这不是一个新问题。又查找了一下，发现大部分项目的数据库连接都是在HTTP服务之前启动的，所以回调中的ScopeId是无法关联到HTTP请求的。也就是说，在MySQL的查询回调中，是获取不到请求上下文的。继续搜索时，我发现在Contextlostaftermysqlquery,mysql2requestsaren'tbeingattachedtorootscope#946andAsyncHooksdonotrecognizeexecutioncontextscreatedwhenprocessingthenables#22360你可以使用util.promisify来规避这个问题。解包express-http-context里面的代码不多。逻辑就像在cls-hooked上放置一个shell并将其封装到Express中间件中一样简单。让我们简单地看一下cls-hooked。核心逻辑在cls-hooked/blob/master/context.js中，大致使用了NodeJSv8内置的async_hooks模块的异步hook特性。在此基础上，封装了一个命名空间来管理请求上下文。没有发现明显的漏洞，令人费解。搜索了一下，在专栏里找到了一篇相关的文章——《使用 Async-hooks 集成 Envoy 和我们的 RPC 库（二）》。本专栏提到的第一个和第三个问题，应该是对上述问题的解释：在async_hooks的生命周期中，before和after可能不是，祖先的销毁可能早于后代。关于async_hooks的介绍可以参考文末链接的文章。了解了以上原因后，单纯使用async_hooks生命周期钩子并不能保证上下文不丢失，所以一个简单的思路就是只使用init钩子函数来记录调用栈，然后在一定时间后清除调用栈的时间。造轮子的大致思路上面已经讲过了，这里简单总结一下：使用async_hooks的init方法来记录调用栈。查找将请求的调用堆栈串在一起的功能。定期清除调用堆栈。第一步，需要在init方法中记录调用者和被调用者的映射关系。这些映射关系形成了调用栈的依赖树，从上到下逐层调用。具体就是建立异步调用的asyncId和executionAsyncId的映射关系。type参数是标识异步资源的类型，主要是区分TCPWRAP实例。__tm是为了记录调用栈的创建时间，以便后续清理。asyncHooks.createHook({init(asyncId,type){constexecutionAsyncId=asyncHooks.executionAsyncId()callstackMap[asyncId]={id:executionAsyncId,isTCP:type===TCPWRAP_NAME,__tm:Date.now()}}})。enable()的第三步是使用定时器清除过期的调用栈。第二步就是如何在茫茫调用栈的海洋中把一个请求的所有相关调用栈串起来。最终请求将通过这个中间件。Express或Koa的框架模型下如何组织请求上下文？写一个Express和async_hooks结合的例子，看init方法的参数：constfs=require('fs')constasyncHooks=require('async_hooks')constexpress=require('express')asyncHooks.createHook({init(asyncId,type,triggerAsyncId){consteid=asyncHooks.executionAsyncId()fs.writeSync(1,`${type}(${asyncId}):触发器：${triggerAsyncId}执行：${eid}\n`)}}).enable()constapp=express()app.all('*',(req,res)=>{res.send('HelloWorld!')})app.listen(3001)三个请求后检查打印如下：TCPWRAP(6):trigger:1execution:1TickObject(7):trigger:6execution:1TCPWRAP(8):trigger:6execution:0TIMERWRAP(9):trigger:6execution:6Timeout(10)：触发器：6执行：6HTTPPARSER(11)：触发器：6执行：6HTTPPARSER(12)：触发器：6执行：6TickObject(13)：触发器：6执行：6TIMERWRAP(14)：触发器：12执行：12Timeout(15)：触发器：12执行：12TickObject(16)：触发器：8执行：12WRITEWRAP（17）：触发器：8执行：12TickObject（18）：触发器：12执行：12TickObject（19）：触发器：12执行：12TickObject（20）：触发器：16执行：16TIMERWRAP（21）：触发器：16执行：16TickObject(22)：触发器：19执行：19TickObject(23)：触发器：20执行：20TickObject(24)：触发器：20执行：20TickObject(25)：触发器：20执行：20TickObject(26)：触发器：8执行：8TickObject(27)：触发器：8执行：8TCPWRAP(28)：触发器：6执行：0Timeout(29)：触发器：6执行：6HTTPPARSER(30)：触发器：6执行：6TickObject(31)：触发器：6执行：6TIMERWRAP（32）：触发器：30执行：30TickObject（33）：触发器：28执行：30WRITEWRAP（34）：触发器：28执行：30TickObject（35）：触发器：30执行：30TickObject（36）：触发器：30执行：30TickObject（37）：触发器：33执行：33TickObject（38）：触发器：36执行：36TickObject（39）：触发器：37执行：37TickObject（40）：触发器：37执行：37TickObject（41）：触发器：37执行：37TickObject（42）：触发器：28执行：28TickObject（43）：触发器：28执行：28TCPWRAP（44）：触发器：6执行：0Timeout（45）：触发器：6执行：6HTTPPARSER（46）：触发器：6执行：6TickObject（47）：触发器：6执行：6TickObject（48）：触发器：44执行：46WRITEWRAP（49）：触发器：44执行：46TickObject（50）：触发器：46执行：46TickObject（51）：触发器：46执行：46TickObject（52）：触发器：48执行：48TickObject（53）：触发器：51执行：51TickObject（54）：触发器：52执行：52TickObject（55）：触发器：52执行:52TickObject(56):trigger:52execution:52TickObject(57):trigger:44execution:44TickObject(58):trigger:44execution:44其中1-2行的log在我没有请求的时候已经存在了，所以请求生成的日志从第三行开始。仔细观察会发现，每一次请求都会有一条TCPWRAP类型的调用栈记录。NodeJS官方文档是这样解释的：TCPWRAPI是来自客户端的新连接。建立新连接时，会立即构建TCPWrapinstance。发生这种情况ns在任何JavaScript堆栈之外。（一个executionAsyncId()of0意味着它是从C++执行的，上面没有JavaScript堆栈。）只有这些信息，不可能根据导致资源创建的原因将资源链接在一起，因此触发AsyncId的任务是传播什么resource负责新资源的存在。简而言之，每次收到来自客户端的请求，当请求连接建立时，TCPWrap实例立即被创建。通过上面的发现，我们可以使用TCPWRAP来标记一个请求的开始，这个标记也可以作为请求调用栈的根。接下来，我们需要将TCPWRAP与中间件相关联。我们通过中间件执行时的executionAsyncId和init中记录的调用栈，查找距离最近的TCPWRAP实例对应的executionAsyncId。这个TCPWRAP实例对应的executionAsyncId是这个请求的根。现在有了一个可以标记root的executionAsyncId，我们暂且称它为rootId，那么当请求进入下一个中间件时，就可以根据自己的executionAsyncId向上查找，直到找到rootId。每次set或者get的时候，都会根据对应的rootId找到对应的context，这样就把一个请求的context串起来了。由于rootId是在执行中间件时确定的，因此在TCPWRAP实例创建和中间件之间不应有任何异步操作，其前面不应有任何包含异步操作的中间件。因为从创建TCPWRAP实例到进入中间件是同步的，所以在进入中间件时，只需要递归向前搜索，根据中间件对应的executionAsyncId，递归找到距离最近的TCPWRAP实例对应的asyncId，以及你会发现这个请求对应的rootId。然后为rootId对应的调用栈初始化一个空上下文，//middlewarelogicconstmiddleware=()=>{constexecutionAsyncId=asyncHooks.executionAsyncId()constrootId=findTCPWrapAsyncId(executionAsyncId)callstackMap[rootId].data={}callstackMap[executionAsyncId]={id:rootId,__tm:Date.now()}}//找到rootIdconstfindTCPWrapAsyncId=asyncId=>{if(callstackMap[asyncId]){if(callstackMap[asyncId].type===TCPWRAP_NAME){returnasyncId}returnfindTCPWrapAsyncId(asyncId-1)}}优化总觉得第三步用定时器清空调用栈的操作不够优雅。为了尽快删除无用的调用栈，能不能在某些时刻主动删除，而不是定时器里的都删除。首先想到的是使用上面提到的destroyhook方法，但是考虑到上面提到的问题，需要在销毁TCPWRAP实例的时候清空相应的调用栈。另一种方法是在触发http.ServerResponse的finish和close事件时清除调用堆栈。最后，使用定时器删除一些游走在http请求之外的调用栈。上面的逻辑启动后，仍然出现contextloss，真是秃了。从日志中发现，上下文丢失大部分发生在服务端异步请求超时后，也可以在本地模拟重现该问题。搞了半天想明白了，当客户端请求超时或者用户终止连接时，上面的优化操作会清空此时请求的调用栈，但是有一个很微妙的细节。客户端超时后，服务端调用其他服务可能还没有结束。在这些调用结束之前，其所属请求的调用栈已经被清空。如果在这些调用结束后操作上下文，则上下文已经消失，无处可寻。因此，上面提到的优化是不可靠的。目前只能依靠定时器来清空调用栈，有效时间要根据业务需要合理设置。有没有其他必须优化的优化方法？当然有！既然destroyhook方法不靠谱，那就从其他靠谱的地方入手。NodeJS请求中有两个事件，finish和close，必然会触发其中一个。当然，直接触发这两个事件后清空调用栈也是可以的，但还是有一种情况需要慎重考虑。测试过程中发现close事件一般发生在客户端终止请求的时候。这种情况一般发生在服务器超时（或者服务器处理时间过长），用户失去耐心，关闭页面或者刷新页面。在这种情况下，close事件触发后调用栈被清空，内部异步请求可能要等到后面才返回，来不及获取上下文。这个优化点虽然比destroy钩子方法靠谱一点，但也不是绝对靠谱，但是在大部分业务场景下，finish事件后清空调用栈还是靠谱的！由于它们都不是绝对可靠的，因此这些优化操作是可选的，默认情况下是关闭的。在内部使用中，只有在开启finish事件后才清空调用栈，效果还是不错的。具体逻辑和之前类似。所有带有rootId的调用堆栈都将记录在rootId下。一旦触发finish/close事件，如果需要清空调用栈，只需清空rootId对应的调用栈即可。End上线一段时间后，没有发生上下文丢失，内存占用正常，服务性能也正常。目前唯一关心的是中间件能否经受住大流量&复杂逻辑场景的考验。最终输出是一个中间件http-request-context。总代码加上Express+Koa中间件的封装，不到一百行。欢迎使用和指正。参考原文首发于知乎专栏《使用 Async-hooks 串联 HTTP 请求上下文》NodeJSasync_hooks《Node.js v8.x 新特性 Async Hook 简介》《使用 Async-hooks 集成 Envoy 和我们的 RPC 库（二）》
