I’ve been providing technical support 24/7 for most of the Node.js services I’ve worked on for quite some years now. During this time I’ve found myself many times wearing a detective hat, digging into thousands of log lines, when no other resource was available to help to troubleshoot an issue. Of course, in an ideal world, you have illuminating metrics, thorough crash reporting tools, and other similar allies to help you find the root cause of the troubles. In reality, log files are sometimes our last resort to find the culprit. I’d like to share some of the principles I’m sticking to in order to produce logs that will help me catch the error smoothly and as soon as possible.

Know the signature of the functions

It’s good to double-check the log method API of Bunyan. I’ve seen many occurrences of logs where the message is passed in the wrong argument of the function, which leads to a less readable output.

If we run the code above, you can see how the first log line outputs more sensible and readable data than the second:

The first log line has a msg property with value Something went wrong, as opposed to the second log line, whose msg contains an amalgam that mixes the message with the error stack trace. Should you have a log visualization tool like Kibana or Splunk, the first log line will be easier to search for if you perform a pseudo-query similar to msg="Something went wrong".

Moreover, this approach will allow you to benefit from bunyan’s CLI filtering capabilities. More about that later on.

First the fields, then the log message

An object literal can be passed to the bunyan log methods, but make sure this object is the first argument, and the second one is the log message. The output will not be so nice if you do it the other way around.

As you can see in the screenshot below, the first log line looks much better than the second.

Just like in the previous example, the first log line has a proper error message, and the object literal will be merged with the resulting JSON generated by bunyan, which will allow you to, again, perform fancy queries with your log visualization tool:

msg = "The player profile has been successfully stored in the database" AND player.name = "Dunkelheit" AND player.level > 10

Again, this is just a pseudo-query, and mileage might vary depending on which log visualization tool you are using.

The second log line will once more contain an amalgam which will make these feats impossible to achieve.

Use the standard bunyan serializers

Bunyan comes with a very convenient set of default serializers that will render readable JSON output for elements like errors, request and response objects, assuming that you use the log method API the right way, sticking to the convention stated in the bunyan documentation. During these past years I’ve seen these serializers not used in their full potential because of the misuse of the log methods.

Enabling these serializers is very easy, and you might have already seen how in the code snippets above. Let’s begin with the following example:

The convention is simple; the first argument of the logging method has to be an object literal containing one or more of the following properties:

• err for errors; it will print the full stack trace of the error, its default properties (like name and message) and any other property in case you are extending the native Error object with any custom fields.
• req for HTTP requests; this will print the following request information: method, URL, headers, remote address and remote port.
• res for HTTP responses: status code and headers.

Be wary of potentially sensitive information being logged as part of the headers in req and res— think of tokens, passwords, personally identifiable information and such.

The output couldn’t be more beautiful!

“player” and “spell” are pretty-printed for your troubleshooting leisure

#programming #nodejs #logging #javascript #bunyan