The NODE_DEBUG environment variable can be set to any combination of the following flags:

• http
• net
• tls
• stream
• module
• timer
• cluster
• child_process
• fs

In our recipe, we were able to enable core timer and HTTP debug logs, by setting the NODE_DEBUG environment variable to timers in the first instance and then timers,http in the second.

We used a comma to delimit the debug flags; however, the delimiter can be any character.

Each line of output consists of the namespace, the process ID (PID), and the log message.

When we set NODE_DEBUG to timer, the first log message indicates that it's creating a list for 100. Our code passes 100 as the second argument passed to setTimeout, internally the first argument (the timeout callback) is added to a queue of callbacks that should run after 100 ms. Next, we see a message, timeout callback 100, which means every 100 ms timeout callback will now be called. The following message (the now message) indicates the current time as the internal timers module sees it. This is milliseconds since the timers module was initialized. The now message can be useful to see the time drift between timeouts and intervals, because a timeout of 10 ms will rarely (if ever) be exactly 10 ms. It will be more like 14 ms, because of 4 ms of execution time for other code in a given tick (time around the event loop). While 4 ms drift is acceptable, a 20 ms drift would indicate potential performance problems-a simple NODE_DEBUG=timer prefix could be used for a quick check. The final debug message shows that the 100 list is now empty, meaning all callback functions set for that particular interval have now been called.

Most of the HTTP output is self-explanatory, we can see when a new connection has been made to the server, when a message has ended and when a socket has closed. The remaining two cryptic messages are write ret = true and SERVER socketOnParserExecute 78. The write ret = true relates to when the server attempted to write to a socket. If the value was false, it would mean the socket had closed and (again internally) the server would begin to handle that scenario. As for the socketOnParserExecute message, this has to do with Node's internal HTTP parser (written in C++). The number (78) is the string length of the headers sent from the client to the server.

Combining multiple flags can be useful. We set NODE_DEBUG to timer,http and we were able to see how the http module interacts with the internal timer module. We can see after the SERVER new http connection message; that two timers are set (based on the timeout lists being created), one for 12,0000 ms (two minutes, the default socket timeout) and one (in the example case) for 819 ms.

This second interval (819) is to do with an internal caching mechanism for the HTTP Date header. Since the smallest unit in the Date header is seconds, a timeout is set for the amount of milliseconds remaining before the next second, and the Date header is provided the same string for the remainder of that second.