initial internal doc on logging

doc/logging.txt

@@ -0,0 +1,289 @@
+=========================
+Duktape logging framework
+=========================
+
+Introduction
+============
+
+Duktape 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.
+
+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)
+  1395003609.854 INF myLogger: test 123
+
+Each arguments 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 string is passed to the logging backend, provided by
+``Duktape.Logger.prototype.raw()``.  The default implementation writes the
+log message to ``stderr`` and appends a newline.
+
+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 lazyJsonx1(obj) {
+    return { toLogString: function() { return Duktape.enc('jsonx', obj); } };
+  }
+
+  logger.debug('complex object:', lazyJsonx1(obj));
+
+One can use ``bind()`` for the same effect (in this particular case)::
+
+  function lazyJsonx2(obj) {
+    return { toLogString: Duktape.bind(null, 'jsonx', obj) };
+  }
+
+  logger.debug('complex object:', lazyJsonx2(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('jsonx', this.v);
+  }
+  function lazyJsonx3(val) {
+    // Per lazy value creation, only creates an object with one property.
+    return new LazyValue(val);
+  }
+
+  logger.debug('complex object:', lazyJsonx3(obj));
+
+Lazy formatting can also be done inline, though not very readably::
+
+  logger.debug('data:', { toLogString: function() { return Duktape.enc('jsonx', 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.
+
+* 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 JSONX, 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 JSONX does).
+Since buffers are plain objects, they don't currently go through the formatter,
+but that would be easy to change.
+
+__FILE__ and __LINE__ for C log writes
+--------------------------------------
+
+Include __FILE__ and __LINE__ automatically in C log writes somehow?