Per request logging in Node.js

Question

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.

Answer 1

I got into this same problem some time ago, and finally I could spend sometime researching it. The @ibash approach and his post put me in the lead to solve the problem I had (thanks for your help). I only walked some steps more in order to print in the logs automatically a unique id per request. In your case you can add origin and destination IP and all information needed to each request, using same approach and print it automatically in all logs.

My approach: - As @ibash explained, I used continuation-local-storage to share information among all the modules per request. So I generate a unique id per request and store it in a namespace created with this library - I wrapped the Winston library (in a very simple way) in order to recover the information from the namespace shared and override all Winston methods I use adding to the string the unique Id. Obviously in your case you should add all the info you need and you have stored previously in the namespace of the library.

As the problem was a little complex to explain to people no familiarize with all these things, I wrote it down in a post with a clear example that you can reuse if you want. Winston wrap could be really useful: Express.js: Logging info with global unique request ID – Node.js

I hope you can reuse my code and perhaps in the future Express implements a solution for this.

Answer 2

These instructions were from an Ubuntu 12.04 distribution I set up, but they should apply pretty closely to RHEL, Fedora, CentOS, etc.

Rsyslog is a system logging utility you can use to log messages from any program on a Linux machine. First you need to find your rsylog configuration information. You can do that with the following command:

sudo find / -name rsyslog.conf

If you can't find the configuration file, you can list the service running to see if rsyslog is even on your machine with the following command:

service --status-all

Now open the file it finds and do the following:

• Comment out the line $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
• Uncomment $ModLoad imtcp
• Uncomment $InputTCPServerRun and specify port number 1514, going to use 1514 b/c Ubuntu 12.04 rsyslog has a problem dropping permissions if I use port 514, other distributions don't have similar issues and you could keep default port #. I get around this by using iptables to reroute port 514 traffic to 1514
• Change $FileCreateMode 0640 to 0644

Now I created a file named /etc/rsyslog.d/10.conf (this is a secondary configuration file for rsyslog where we can filter message, name log files, etc) and added the following to it:

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

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

This file creates a new file for each day and finds any message sent with MsgName in the text and puts it into the daily file and then removes it from the queue to be logged by any other log requests so we don't double log it.

Now you can reboot the machine you are working on and it all should be working. You can check this by looking for files in /var/log as defined in 10.conf above. Hit the logger from the command line by issuing the following commands:

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

You should see both those lines pop up in the log file. If you get that, then let's move on to the node module that will be able to hit the log.

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. . . 

The '\n' on the write tells rsyslog we are done with this line. Also, you will need to prepend a space for the filtering to work: http://www.rsyslog.com/log-normalization-and-the-leading-space/

The devil is always in the details with a setup like this, but I think this will get you most of the way there and google searching will get you the rest of the way.

Answer 3

Answering this as I just wrote a post on how to use continuation-local-storage to save a "transaction id" with every log (without manually propagating it). You can do the same for the client ip, process id, etc.

Follow this post: https://datahero.com/blog/2014/05/22/node-js-preserving-data-across-async-callbacks/

But instead of just saving a transaction id, you'll want these as well: request.connection.remoteAddress and process.pid

Let me know if you have any questions here or there, and I'll answer them.