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.

Improve this question
5
  • Are you using Linux (I suspect you are based on the fact you are mentioning PIDs)? If so, check out rsyslog. I'm using it to do exactly what you are looking at. You just open a socket to it once it's setup correctly and it will prepend time and the sender name plus any string you send it. If you are using Linux, comment back and I'll do a detailed post on how to set it up and use it from node. Commented Nov 7, 2013 at 18:36
  • Since you are talking about logging state information (the IP address of the request) I think your best bet will be to pass the value around. You can pass a single object with several pieces of information, though. Commented Nov 7, 2013 at 18:49
  • I am using both Linux and OS/X (which is Unix-based). I'd love to know the rsyslog method. Commented Nov 7, 2013 at 19:18
  • For now, I went ahead and did it with an object passed around, which doesn't feel clean, but it does work. Sample log from a test appended to my original message. Commented Nov 7, 2013 at 19:31
  • Since this is a HTTP server is the request object available though your call stack? You could attach the state information to that. Commented Nov 8, 2013 at 6:36

3 Answers 3

Reset to default
2

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.

Improve this answer
Sign up to request clarification or add additional context in comments.

1 Comment

The problem with continuation-local-storage is that every single module that you use in your app must support using continuation-local-storage or use the same promise library that continuation-local-storage is used by. If even one module doesn't (or you forget to initialize continuation-local-storage for that module's promise library), the entire requestId tracking falls apart for any subsequent requests.
1

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.

Improve this answer

Comments

1

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.

Improve this answer

Comments

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.