16

I am an experienced Java developer picking up Node.js and making the shift to the asynchronous model. Most things are going fine except for logging. I cannot find anything similar to log4j and NDCs in Java while developing in Node.js with express.

My goal is to have each log statement automatically prepend the following information:

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

This includes the timestamp, name of the js file writing this statement (for modularized node apps), the debug level, the process ID (running clusters), and the client's IP address.

I can get it to write these when initially coming into my request handler, but without propagating a bunch of parameters to every called function, the logger statements inside the subroutines don't have the info. I know I can create an instance of my logger inside each js file that initializes its name, but I've yet to figure out a solution for the IP address of the client. For longer running requests, the address I set in my logger gets overwritten when the next request comes in, so the IPs that are logged get crossed.

I've looked at winston but have not been able to solve this issue even with it. Has anyone accomplished this? It is very useful tracking field issues when you can filter by IP to view only one user's activity.

[edit: test from parameter passing solution until I learn the syslog way]

[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

Now I just need to figure out how to get the express request logger to be in the same line entry format as my internal logger until it is all moved to rsyslog.

4

3 回答 3

2

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

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

由于向不熟悉所有这些事情的人解释这个问题有点复杂，我在一篇文章中写了一个清晰的例子，如果你愿意，你可以重复使用。Winston wrap 可能非常有用： Express.js：使用全局唯一请求 ID 记录信息 – Node.js

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

于 2017-11-30T13:17:11.527 回答
1

这些说明来自我设置的 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/

像这样的设置，魔鬼总是在细节中，但我认为这会让你走上大部分路，而谷歌搜索会让你走完剩下的路。

于 2013-11-07T20:12:52.757 回答
1

回答这个问题，因为我刚刚写了一篇关于如何使用 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

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

于 2014-05-22T16:00:44.377 回答