📜 ⬆️ ⬇️

About logging in Node.js

First, I’ll repeat what every developer should know about this - need to be protected .


Why do you need to log


You have launched a server application that does not have a GUI to display its state, but you really want to know. The simplest and most obvious solution is to display some messages somewhere - stdout / stderr, files, syslog, something more perverted. This is logging (thanks to cap).

I will list the main tasks that can be solved using logging:
')
  1. Behavior and performance analysis. Here it should be noted that for performance analysis, it is better to use probing (eg twitter zipkin gets data through samples in the code). Behavior is everything that is happening now.
  2. Analysis and diagnosis of problems. It is obvious here - the critical situation in the application is 1/0 (and it doesn’t matter when it happened, the application is about to expire), what should I do? That's right - log it. About this more below.
  3. Any left usage scenarios.


How to log


It is necessary to write logs and a lot and a little. So little to understand the state of the application now, and so much so that if the application collapses to understand why.

That is, we write what you yourself consider necessary so that you can understand what is happening. But it must be emphasized that logging is eating application resources - so do not get carried away, I saw the application once, where logging consumed about 50% of performance (of course, PPC doesn’t have to do that).

If an error / exception occurs, etc., you need to understand why. At this very moment, we write to the logs everything (yes, absolutely everything) that is necessary for understanding why this happened (here you just need to write a lot - do not be shy).

Log levels


Obviously, not every message has the same importance. Usually, most applications need 5 levels of logs - I use the name of the levels I used to with slf4j:

  1. ERROR - application in a critical situation, requires the attention of a person to continue. Appears quite rarely, but aptly. I use it for very low-level things or for unhandled exceptions.
  2. WARN - something unusual happened, out of the ordinary scenario, but the application is smart and has restored its work itself. I use this level in error handling.
  3. INFO - what is happening now
  4. DEBUG - what is happening now, in more detail
  5. TRACE - we write as Twitter, all that is not getting.


Further, there will be a small comparison of the loggers that I tested in node.js and what is wrong with them, taking into account the above.

log4js


This is the first thing I looked at, in the hope that this would be at least as much as log4j.

A small example:
var log4js = require('log4js'); var logger = log4js.getLogger(); logger.debug("Some debug messages"); 

A color message will appear in the console:
 [2014-01-13 20:41:22.604] [DEBUG] [default] - Some debug messages 

This logger has the necessary minimum. There is a message filtering by level and category (logger name), the time of the message and the ability to change it. For the output of messages, util.format is used - therefore the same formatting options are used as in console.log.

winston


It is often recommended on SO. I personally would not recommend it to anyone.
Example:
 var winston = require('winston'); winston.info('Hello distributed log files!'); 

What will be in the console:
 info: Hello distributed log files! 

At this point, there was a small opus that winston does not allow the issuance of time records, thanks to Keenn , it turned out that everything is possible, but these options (timestamp: true for transports) are disabled by default, which is very strange.

bunyan


Unlike the two previous libraries, this logger produces JSON instead of text. The creator decided that the logs are still disassembled by the machine (log collectors), then let it be a machine-readable format. This is well suited for the first logging scenario (obviously, collecting samples by hand is at least silly), but collectors are not always used. What personally seemed to me strange, or better said unfortunate decision:
  1. JSON for the second script, which in my opinion is the most reasonable application of logging, is how to look for an error in C ++ code in assembly code. Logs are read by people. If the application is small, the log collector is redundant, and if it does, you just need to add a handler for it.
  2. If we talk about the organization of the code, then that the handler logger spits out and where, it is completely the responsibility of the handler - that is, in theory, the JSON output can be screwed to any library that allows you to write your handlers / formatters.
  3. Bunyan has one feature - serializers for custom types. Along with the message the logger is fed a pack of objects and it serializes them. If you look at it from a different angle:
    serialization is just a JSON representation of the object; each object can define the toJSON method in its prototype and it will be called with JSON.stringify - this is the serializer; now how to display it - absolutely all loggers allow you to display json representation of objects with a special flag (for util.format it is% j). That is, the feature seems to be quite obvious.

I honestly admit, I have almost no experience with this logger (I tried to fasten it the very first - all the same joyent uses it), if I am shown / pointed / nipped, that it is cool, I will gladly listen and take note. Although I noticed that there is a simple organization of the hierarchies of the loggers, but I did not find it convenient to use.

intel


This is the best logging library I've come across. In terms of configuration, I did not have any complaints about it. Why I liked her:
  1. As already said, it has a very convenient configuration, you can configure everything in one place. Loggers have handlers, handlers have message formatters, message and level filters. Almost a fairy tale.
  2. Hierarchies of loggers who came to Mr. Slf4j take this for granted, but only in this lib this was normally implemented. What is the hierarchy of logs:
    each logger has a parent (the full name of the logger is set by combing through the point of all parents), setting the parent configuration, you can set the option so that all children automatically receive it (log propagation). That is, for example, I can create several parent loggers, set handlers for them (for example, send the email to the ERROR and WARN levels) and all children will use them, but more than that if I need to silence some kind of logging tree, I simply specialize the configuration for his full way. And all this in one place and once.
  3. Very reasonable substitution of the standard console. The paths are allowed relative to the current working directory, which allows you to easily configure the console.log output and get logger buns.

After a short use (I noticed that this project doesn’t pay as much attention to the formatting as the others), I made several pull requests to add the ability to output milli-seconds, support for formatted error output, but after a brief conversation with the author and 4-5 pull requests, it became obvious that the author wants to go his own way and I forked the project by adding what I dreamed of.
Having checked the code I noticed that the author optimized the code for the benchmark . I would rather leave my opinion on such things with me.
What I have changed in the lib itself, leaving untouched handlers:
  1. I threw out all such optimizations for the benchmark - writing such is not respecting yourself.
  2. The format of messages in intel: you need the fields of the record object to indicate their type (n 'p' [% (date) s]% (name) s ::% (message) s'), but the types of these fields are known - so why you need to specify them. Instead, I took the message format from logback.
  3. For formatting the arguments, the logging uses its own analogue util.format, with its own keys and it is also used when changing the console, that is, if the third-party lib writes that we will get something not exactly what we expect to the console. Naturally this was replaced by util.format
  4. After some profiling, it became obvious that all the time was spent on formatting messages. Since the format is usually specified once it is reasonable to optimize it, which was done, the new function is used to format the format once, rather than with each call.

There are still some trifles, but it will be some kind of PR, not a comparison.
To show some differences - a small measurement of speed ( benchmark code , all versions are recent). Just print logger.info (with the message):
 $ node benchmark/logging.js console.info x 1,471,685 ops/sec ±0.79% (95 runs sampled) rufus.info x 200,641 ops/sec ±1.04% (84 runs sampled) winston.info x 65,567 ops/sec ±0.80% (96 runs sampled) intel.info x 56,117 ops/sec ±1.51% (92 runs sampled) bunyan.info x 86,970 ops/sec ±1.71% (81 runs sampled) log4js.info x 45,351 ops/sec ±3.25% (79 runs sampled) Fastest is console.info 

With this message format, '[% date]% logger ::% message', which is always reasonably expected. Let's try to replace it with a standard message in intel to experience the full power of optimizations:
 $ node benchmark/logging.js console.info x 1,569,375 ops/sec ±0.66% (95 runs sampled) rufus.info x 199,138 ops/sec ±0.81% (97 runs sampled) winston.info x 66,864 ops/sec ±0.84% (91 runs sampled) intel.info x 173,483 ops/sec ±5.64% (59 runs sampled) bunyan.info x 86,357 ops/sec ±1.02% (94 runs sampled) log4js.info x 49,978 ops/sec ±2.29% (81 runs sampled) Fastest is console.info 

An interesting change.
In general, that's all. If anyone is interested - fork (I probably will not accept feature requests, since I wrote for myself in my free time, you are welcome with bugs and pull requests).
As always, I hope in the comments to find something new for myself. Mistakes please in lichku.

Source: https://habr.com/ru/post/209436/


All Articles