在 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 文件的名称（对于模块化节点应用程序）、调试级别、进程 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 会为此实施解决方案。

Answer 2

这些说明来自我设置的 Ubuntu 12.04 发行版，但它们应该非常适用于 RHEL、Fedora、CentOS 等。

Rsyslog 是一个系统日志记录实用程序，您可以使用它来记录来自 Linux 机器上任何程序的消息。首先你需要找到你的 rsylog 配置信息。您可以使用以下命令执行此操作：

sudo find / -name rsyslog.conf

如果找不到配置文件，可以列出正在运行的服务，看看rsyslog是否在你的机器上，使用以下命令：

service --status-all

现在打开它找到的文件并执行以下操作：

• 注释掉 $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat 行
• 取消注释 $ModLoad imtcp
• 取消注释 $InputTCPServerRun 并指定端口号 1514，将使用 1514 b/c 如果我使用端口 514，Ubuntu 12.04 rsyslog 会出现删除权限的问题，其他发行版没有类似问题，您可以保留默认端口号。我通过使用 iptables 将端口 514 流量重新路由到 1514 来解决这个问题
• 将 $FileCreateMode 0640 更改为 0644

现在我创建了一个名为 /etc/rsyslog.d/10.conf 的文件（这是 rsyslog 的辅助配置文件，我们可以在其中过滤消息、命名日志文件等）并向其中添加以下内容：

$template DailyPerHostLogs,"/var/log/MyLogFile_%$YEAR%_%$MONTH%_%$DAY%.log"

#:msg,contains,"MsgName" -?DailyPerHostLogs
*.* -?DailyPerHostLogs
&~

此文件为每天创建一个新文件，并在文本中查找使用 MsgName 发送的任何消息并将其放入每日文件中，然后将其从队列中删除以由任何其他日志请求记录，这样我们就不会加倍记录下来。

现在您可以重新启动您正在使用的机器，它应该可以正常工作了。您可以通过在上面 10.conf 中定义的 /var/log 中查找文件来检查这一点。通过发出以下命令从命令行点击记录器：

logger this is from the command line
echo "this is from the tcp port" > /dev/tcp/127.0.0.1/1514

您应该会在日志文件中看到这两行弹出。如果你明白了，那么让我们继续讨论能够命中日志的节点模块。

var net = require('net');

var client = net.connect({port: this.1514}, function(){ console.log("Open"); });

client.write(' ' + "sMsgName: What"+ ' ' + "hath" + ' ' + "God wrought?" + '\n');

//Do everything else your program needs. . . 

写上的 '\n' 告诉 rsyslog 我们已经完成了这一行。此外，您需要在前面添加一个空格，以便过滤工作：http://www.rsyslog.com/log-normalization-and-the-leading-space/

魔鬼总是在这样的设置细节中，但我认为这会让你大部分时间到达那里，而谷歌搜索会帮助你完成剩下的事情。

Answer 3

回答这个问题，因为我刚刚写了一篇关于如何使用 continuation-local-storage 为每个日志保存“事务 ID”（无需手动传播）的帖子。您可以对客户端 ip、进程 ID 等执行相同操作。

关注这个帖子：https://datahero.com/blog/2014/05/22/node-js-preserving-data-across-async-callbacks/

但是，您不仅需要保存交易 ID，还需要以下内容： request.connection.remoteAddress 和 process.pid

如果您有任何问题，请在这里或那里告诉我，我会回答。