node.js - 在 Node.js 中记录每个请求

Question

我是一位经验丰富的 Java 开发人员，开始学习 Node.js 并转向异步模型。除了日志记录之外，大多数事情都进展顺利。在使用 express 使用 Node.js 进行开发时，我在 Java 中找不到类似于 log4j 和 NDC 的任何东西。

我的目标是让每个日志语句自动添加以下信息:

[2013-11-07 11:17:04.615 serverScript INFO 7036 192.168.7.209]

这包括时间戳、编写此语句的 js 文件的名称(对于模块化 Node 应用程序)、调试级别、进程 ID(正在运行的集群)和客户端的 IP 地址。

当最初进入我的请求处理程序时，我可以让它编写这些，但没有将一堆参数传播到每个调用的函数，子例程内的记录器语句没有信息。我知道我可以在每个 js 文件中创建一个记录器实例来初始化其名称，但我还没有找到客户端 IP 地址的解决方案。对于运行时间较长的请求，我在记录器中设置的地址会在下一个请求进入时被覆盖，因此记录的 IP 会被交叉。

我查看了 winston，但即使使用它也无法解决此问题。有没有人做到这一点？当您可以按 IP 过滤以仅查看一个用户的事件时，跟踪字段问题非常有用。

[编辑:从参数传递解决方案进行测试，直到我学习 syslog 方式]

[2013-11-07 14:29:28.641 server INFO  7527 192.168.7.209] Got request from 192.168.7.209 for /ionmed/executeQuery?
[2013-11-07 14:29:28.641 router INFO  7527 192.168.7.209] About to route a request for /ionmed/executeQuery, method=POST
[2013-11-07 14:29:28.642 router INFO  7527 192.168.7.209] getting POSTed data
[2013-11-07 14:29:28.642 router INFO  7527 192.168.7.209] POST params: {"sqlQuery":"select sleep(10)","sessionStart":"1383852558799","rand":"0.5510970998368581","jsessionid":"117DBAA89F599D923AF80D4AB171BDDF"}
[2013-11-07 14:29:28.642 requestHandlers INFO  7527 192.168.7.209] 'query' was called.
[2013-11-07 14:29:28.642 requestHandlers INFO  7527 192.168.7.209] select sleep(10)
[2013-11-07 14:29:30.673 server INFO  7527 192.168.7.217] Got request from 192.168.7.217 for /
[2013-11-07 14:29:30.673 router INFO  7527 192.168.7.217] About to route a request for /, method=GET
[2013-11-07 14:29:30.673 router INFO  7527 192.168.7.217] No request handler found for /; serving as file
[2013-11-07 14:29:30.673 router INFO  7527 192.168.7.217] Request handler 'serveFile' was called to get: /index.html
[192.168.7.217 Thu, 07 Nov 2013 19:29:30 GMT] HTTP/1.1 GET "/node/" 200 "Mozilla/5.0 (iPod; CPU iPhone OS 5_1_1 like Mac OS X) AppleWebKit/534.46 (KHTML, like Gecko) Version/5.1 Mobile/9B206 Safari/7534.48.3"
[2013-11-07 14:29:33.578 server INFO  7527 192.168.7.217] Got request from 192.168.7.217 for /
[2013-11-07 14:29:33.578 router INFO  7527 192.168.7.217] About to route a request for /, method=GET
[2013-11-07 14:29:33.578 router INFO  7527 192.168.7.217] No request handler found for /; serving as file
[2013-11-07 14:29:33.579 router INFO  7527 192.168.7.217] Request handler 'serveFile' was called to get: /index.html
[192.168.7.217 Thu, 07 Nov 2013 19:29:33 GMT] HTTP/1.1 GET "/node/" 200 "Mozilla/5.0 (iPod; CPU iPhone OS 5_1_1 like Mac OS X) AppleWebKit/534.46 (KHTML, like Gecko) Version/5.1 Mobile/9B206 Safari/7534.48.3"
[2013-11-07 14:29:38.644 requestHandlers INFO  7527 192.168.7.209] sending response
[192.168.7.209 Thu, 07 Nov 2013 19:29:38 GMT] HTTP/1.1 POST "/node/ionmed/executeQuery?" 200 "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:25.0) Gecko/20100101 Firefox/25.0"
[2013-11-07 14:29:41.540 server INFO  7527 192.168.7.217] Got request from 192.168.7.217 for /
[2013-11-07 14:29:41.541 router INFO  7527 192.168.7.217] About to route a request for /, method=GET
[2013-11-07 14:29:41.541 router INFO  7527 192.168.7.217] No request handler found for /; serving as file
[2013-11-07 14:29:41.541 router INFO  7527 192.168.7.217] Request handler 'serveFile' was called to get: /index.html
[192.168.7.217 Thu, 07 Nov 2013 19:29:41 GMT] HTTP/1.1 GET "/node/" 200 "Mozilla/5.0 (iPod; CPU iPhone OS 5_1_1 like Mac OS X) AppleWebKit/534.46 (KHTML, like Gecko) Version/5.1 Mobile/9B206 Safari/7534.48.3"
[2013-11-07 14:29:45.146 server INFO  7527 192.168.7.209] RLz6tmJ7KTH2R16VCVTX: bye {"user":"1"}
[2013-11-07 14:29:45.176 server INFO  7527 192.168.7.209] RLz6tmJ7KTH2R16VCVTX: disconnected

现在我只需要弄清楚如何让快速请求记录器与我的内部记录器采用相同的行条目格式，直到它全部移动到 rsyslog。

Answer 1

前段时间我遇到了同样的问题，最后我可以花点时间研究一下。 @ibash 方法和他的帖子让我率先解决了我遇到的问题(感谢您的帮助)。为了在日志中自动打印每个请求的唯一 ID，我只走了一些步骤。在您的情况下，您可以使用相同的方法添加源和目标 IP 以及每个请求所需的所有信息，并在所有日志中自动打印。

我的方法:- 正如@ibash 解释的那样，我使用 continuation-local-storage 在每个请求的所有模块之间共享信息。所以我为每个请求生成一个唯一的 id 并将其存储在使用这个库创建的命名空间中- 我包装了 Winston 库(以一种非常简单的方式)，以便从共享的命名空间中恢复信息并覆盖我使用的所有 Winston 方法，将唯一 ID 添加到字符串中。显然，在您的情况下，您应该添加您需要的所有信息，并且您之前已经存储在库的命名空间中。

由于向不熟悉所有这些事情的人解释这个问题有点复杂，我在一篇文章中写了一个清晰的例子，如果你愿意，你可以重复使用。 Winston wrap 可能非常有用: Express.js: Logging info with global unique request ID – Node.js

我希望您可以重用我的代码，也许将来 Express 会为此实现解决方案。