Duktape logging framework

Introduction

Duktape 1.x contains a built-in very minimal logging framework which has a small footprint (around 1kB), reasonably high performance, and makes it easy to change both the frontend and the backend of logging. It is easy to write log entries from both C and ECMAScript, and then redirect all the log output to a custom backend. Lazy formatting is also possible.

In Duktape 2.x the logging framework was moved into an optional extra (extras/logging) to avoid portability issues on exotic target platforms. The extra has the same feature set as Duktape 1.x built-in logging and provides the same bindings (Duktape.Logger object, duk_log() and duk_log_va() API calls).

The framework focuses on how logger objects are created and what the logger interface looks like. Other features are quite barebones; for example, the default backend simply writes to the stderr and there is no advanced backend configuration like multiple log outputs. The user can easily replace the frontend and the backend functions to extend the basic feature set in a transparent manner.

The logging framework also provides API calls to write log entries from C code. This is very convenient, as these log entries will then nicely interleave with log entries written from ECMAScript code.

The logger object API is close to log4javascript except that there is no special handling for an error object as the last call argument. See:

• http://log4javascript.org/docs/quickstart.html

Writing log entries from ECMAScript

A logger object is first created:

// Without arguments, the logger defaults to the fileName of the call site
var logger = new Duktape.Logger();

// Explicitly name
var logger = new Duktape.Logger('myLogger');

// Explicitly unnamed (any non-string argument, null probably best)
var logger = new Duktape.Logger(undefined);
var logger = new Duktape.Logger(null);

After a logger has been created, log entries are written with the exposed log writing calls inherited from the logger prototype. There are six log levels, each with its own frontend function. Each log level also has a number (0 to 5) which is used e.g. to control log level, and a 3-letter abbreviation (like INF) used in the log prefix. Some example log calls:

logger.trace('loop iteration:', i, 'out of', n);   // level 0 (TRC)
logger.debug('objects:', obj1, obj2, obj3);        // level 1 (DBG)
logger.info('normal log message');                 // level 2 (INF)
logger.warn('exceptional condition');              // level 3 (WRN)
logger.error('something went wrong');              // level 4 (ERR)
logger.fatal('something went really wrong');       // level 5 (FTL)

The logger functions make a logging decision based on log level. If the entry gets logged, call arguments are formatted into strings, concatenated with spaces, and a prefix is added. The prefix contains a timestamp, the log level, and the logger name. Example:

duk> logger.info('test', 123)
2014-03-19T02:42:20.425Z INF myLogger: test 123

Each argument is formatted separately, and if an error is thrown during formatting, the argument is replaced with string coercion of the error. Non-object values are formatted in pure C by the default logger functions to minimize unnecessary calls. Object values are formatted by calling fmt() method of the logger, usually inherited from Duktape.Logger.prototype.fmt().

The default object formatting function calls the toLogString() function of the object if it has one, else it simply coerces with String(val). The toLogString() function is a Duktape custom function which allows the user to control how an object should appear in logs by default.

Although arguments whose formatting fails get replaced by an error, the logger API does not guarantee that no errors can be thrown. For example, if formatting fails and also string coercing the formatting error fails, the latter error will propagate out of the logger. As always, internal errors like out-of-memory or out-of-stack can occur at any time.

The final log message is passed as a buffer to the logging backend, provided by Duktape.Logger.prototype.raw(). The default implementation writes the log message to stderr and appends a newline. The log message is provided as a buffer (instead of a string) to avoid interning the message unnecessarily. For short messages, a single dynamic buffer is reused over and over by modifying the visible size of the buffer (the dynamic buffer is not reallocated), to eliminate memory churn.

Logger related properties like the logger name (p), log level (l), and the fmt() and raw() functions are all looked up through the logger instance so that they can overridden either in the prototype, or on a per-logger basis.

Writing log entries from C

The Duktape API provides a snprintf-like log call which allows C code to log to the same backend as ECMAScript code:

duk_log(ctx, DUK_LOG_INFO, "return value: %d", rc);

Note that if you just want to format a plain string, you must use a %s format to avoid security holes (your string might contain a % which would cause uncontrolled memory accesses):

const char *my_plain_string = "beware of the %s";
duk_log(ctx, DUK_LOG_WARN, "%s", my_plain_string);

Log writes from C code use a representative logger instance stored in Duktape.Logger.clog. You can manipulate or replace this logger to control C log writes more explicitly.

Logger objects

Each logger is an object with a few possible properties:

• n: name of the logger, added to log lines. If not given, defaults to the fileName of the function where to logger is created. If even that is missing, the value will be missing from the object, and a default value is inherited.
• l: minimum log level of the logger. Log writes below this level are dropped. If missing, a default value is inherited.

Typically, if log levels are not altered, a logger object only contains the n property. Loggers are compacted at creation to ensure a minimal footprint (they very rarely change state).

Each logger object has as its internal prototype Duktape.Logger.prototype. The prototype provides:

• n: a default name ('anon')
• l: a default log level (2, info level)
• log writing methods for each level

Lazy formatting

Lazy formatting is useful when formatting the log arguments is costly and the log line is normally filtered by the log level. This is often the case when debug logging complex values like deep serializations of internal state objects.

Lazy formatting is easily achievable by using the toLogString() method. The simplest but not very efficient approach is:

function lazyJx1(obj) {
  return { toLogString: function() { return Duktape.enc('jx', obj); } };
}

logger.debug('complex object:', lazyJx1(obj));

One can use bind() for the same effect (in this particular case):

function lazyJx2(obj) {
  return { toLogString: Duktape.bind(null, 'jx', obj) };
}

logger.debug('complex object:', lazyJx2(obj));

Creating a function instance per lazy-logged value is quite expensive. Because the toLogString() is called as a method, lazy values can inherit from a prototype which is reasonably efficient:

function LazyValue(val) {
  this.v = val;
}
LazyValue.prototype.toLogString = function () {
  return Duktape.enc('jx', this.v);
}
function lazyJx3(val) {
  // Per lazy value creation, only creates an object with one property.
  return new LazyValue(val);
}

logger.debug('complex object:', lazyJx3(obj));

Lazy formatting can also be done inline, though not very readably:

logger.debug('data:', { toLogString: function() { return Duktape.enc('jx', data); } });

Customizing logging

Some options:

• Add a toLogString() method to the prototype of interesting objects to control how they are serialized into strings by the default formatter Duktape.Logger.prototype.fmt(). For instance, you can add the method to Object.prototype to provide better logging for all object values.
• Replace Duktape.Logger.prototype.fmt() for custom formatting of object values.
• Replace Duktape.Logger.prototype.raw() for redirecting formatted log lines to an alternate destination. Be careful to avoid unnecessary memory and string table churn.
• Replace the frontend functions (Duktape.Logger.prototype.info() etc) for custom formatting of log lines. You may also choose not to call Duktape.Logger.prototype.raw() for emitting the formatted log line, but rather interface with your custom backend directly.
• Replace the entire Duktape.Logger constructor and prototype object for full control over logging.
• Of course, you can also use an external logging framework.

Limitations

The built-in logging mechanism has several limitations. Most of them are intentional to keep the logger footprint small:

• Currently a new logger is created regardless of whether or not a previous logger exists with the same name. Sometimes it might desirable to return the same logger instance in this case, so that e.g. the log level can be controlled by finding a logger and operating on it. You can implement this by overriding the constructor.
• There is no way to modify the built-in line format except by overriding the frontend functions (Logger.prototype.info() etc). This is intentional, as having a fixed format makes it easier to log faster and reduce memory churn caused by logging.
• There is no concept of a logging context for C code. Instead, all log writes go through a single logger instance. If multiple global objects exist in the Duktape heap, each global context (or more specifically Duktape.Logger instance) will have its own logger object. Logging from C is usually less of a priority so the logging C API is kept very minimal on purpose.

Existing frameworks and related links

• http://ajaxpatterns.org/Javascript_Logging_Frameworks
• http://getfirebug.com/logging
• http://log4javascript.org/docs/quickstart.html
• http://log4js.berlios.de/
• http://benalman.com/projects/javascript-debug-console-log/

Future work

Format all value types in a useful manner by default

Like JX, the logger should write useful log entries for all available value types by default. Currently this is not the case for e.g. buffer values.

Reduce memory churn

Memory churn can be reduced considerably by string coercing all primitive types (or at least undefined, null, boolean, integer numbers) without going through string interning.

Better multiline support

Perhaps duplicate the prefix but perhaps change the final colon to indicate continuation, e.g.:

<timestamp> INF myLogger: multi
<timestamp> INF myLogger| line

Or perhaps:

<timestamp> INF myLogger: multi
                        | line

ASCII sanitization

It would be nice if logger output would be guaranteed to be printable ASCII only. This needs handling either in the frontend functions (e.g. for strings) or the final writer function.

Buffer formatting

Buffer data should maybe be formatted in hex encoded form (like JX does). Since buffers are plain objects, they don't currently go through the formatter, but that would be easy to change.

---

Include __FILE__ and __LINE__ automatically in C log writes somehow?