Monday, December 19, 2016

Node js Addon Logger Module

One of the issues I'm attempting to solve while programming node js addons is logging. I've looked for solutions for some time but there's no way to communicate to v8 the addon's internal logs. so I'm left with a few options which are not completely satisfactory. 

Dump the logs to console

I can dump the logs to the console but how do I redirect them to a file? if I redirect the entire stderr or stdout, I'll have irrelevant log entries in my log and trying to split them by module name could be useless work I'll need to do later.

Dump the logs to file

Dumping the logs to a log file is probably the easiest solution, I could use something like log4cpp or Pantheios, but importing them into a node addon could add a whole other set of problems, like how to set the appender at runtime and how do I manage modules, but Pantheios is claimed to be one of the fastest frameworks by their own benchmarks.

Eventually I've decided to try to POC my own with node js domain in mind, its not the best, but its good enough (tm), at least for now.

The basic requirements are:

- must support multithreaded logging
- must be easy on the v8 engine, e.g don't freeze the VM.
- must be able to filter out unneeded log levels, so debug/trace in debug sessons and info and above for production.
- optional - communicate with v8 the log messages

So I went ahead and planned it, its not too complicated, we have only two components at the moment, a queue for holding the debug messages between flushes and a notifier to v8 that there are pending log messages to be processed.

At the moment the queue is a quick write of locking std::queue implemented with std::lock_guard<std::mutex> with an atomic counter to keep track of the number of messages in the queue.

the notifier is implemented as libuv uv_async_send api, which basically schedules an async to be executed on the main node js thread.

on top of it I've added the following APIs exposed to node:

RegisterLogger - to register log callbacks, this way node js can use log4js and do everything in one place, not very efficient, but again, good enough for now.

Flush - which forces the callback to execute and flush any pending log messages

log_level property - to control what to log, so if we set this on Error but a Debug message comes in, the logger will ignore it.

batch_length property - how many log messages to process in one main thread event loop iteration, reducing it will make the log slower but the vm will be more responsive, increasing it may cause the vm to freeze when many log messages are being returned back to v8.

and of curse Log - which can be used for testing purposes or anything else, just don't use it for actual logging as the round trip from v8 -> c++ -> v8 is a waste of perfectly good cpu and memory resources.


- Performance, which could be improved by using a better lock-free queue or perhaps even using a queue per thread as node js is essentially threadpooled. perhaps the callback can accept an array of log messages saving the round trip time between v8 and c++.

- Separation of logs, currently all log messages go in the same queue, so when your callback is getting called, its getting all the messages. 

- One callback only, no support for multiple callbacks

- Queue is only increasing in size, its not a memory leak, but if you don't flush your callback every once in a while, it might look like one. std::queue does not implement shrink_to_fit, so the only way to flush it is to create a new one and swap them.

- Log messages might get lost when the vm crashes, since all logging is done in memory, if the vm crashes without the logs being purged, the messages will be lost to the gods of memory dumps.

This module is a start, I'll probably improve it as the needs grow/change.

You can find the project here:

What's next? Perhaps an instrumentation module... :-)

1 comment: