TIBET

Logging

Wins

• Configurable logging during application loading and startup sequence.
• Extensible Log4J 2.0-inspired logging after application startup.
• Seamlessly integrated with the TIBET Configuration subsystem.
• APP vs. LIB logger roots: TIBET (TP) and APP (APP) loggers.
• Built via TIBET OO and fully extensible using TIBET types/traits.

Contents

Concepts

The Boot Log

The System Log

• Prebuilt Logging
• Lib vs. App Logging
• Logging Primitives
  • varargs
  • Log Names
  • Markers
  • Formatting (sprintf)
• Branching Primitives
• Built-in Logs

Cookbook

The Boot Log

• Show The Boot Log On Launch
• Log At A Detailed Level During Boot
• Log To The Browser Console

The System Log

• Getting A Logger
• Testing For Logger Existence
• Getting All Loggers
• Logging A Message
• Setting A Level Filter
• Configuring An Appender
• Configuring A Layout
• Creating A Filter
• Clearing Filters
• Creating A Marker

Code

• TP.log Types
• TP.log.Manager
• TP.log.Logger
• TP.log.Appender
• TP.log.Layout
• TP.log.Entry
• TP.log.Filter
• TP.log.Marker

Summary

Concepts

Logging, like configuration, is an essential feature of large-scale applications.

TIBET has two layers of logging. During loading all logging is handled by the Loader's low-level logging facility aka "the boot log". After startup all logging transitions to the TP.log subsystem, a comprehensive logging facility based on Log4J 2.0.

Every component and layer of TIBET seamlessly integrates with both TIBET's configuration and logging subsystems, meaning you have access to detailed logs regarding TIBET operation, information you can control, capture, and leverage.

The Boot Log

The TIBET Loader includes a low-level logging facility that begins logging the moment you invoke TP.boot.launch:

//  Start logging...
TP.boot.$stdout('TIBET Boot System (TBS) ' + TP.boot.$version,
    TP.SYSTEM);

Throughout the boot process the TP.boot.$stdout and TP.boot.$stderr calls are used to log all activity performed by the Loader. These calls provide output in leveled form which allows you to filter how much output you see.

While the boot log can be extremely useful, application code doesn't normally interact with the boot log, it's purely a way for the TIBET Loader to keep you informed about progress, warnings, errors ( like syntax problems in load resources) etc. during startup.

As described in the TIBET Loader docs you can control various aspects of the boot log through configuration parameters managed by the TIBET Configuration subsystem. Once TIBET has loaded and initialized all logging shifts from the boot log to the primary logging subsystem rooted on TP.log.

The System Log

If you've worked with Log4J 1.x, 2.x, or log4javascript you should find TP.log and it's associated types and APIs very familiar. The TP.log subsystem is an implementation of Log4J 2.0 APIs using TIBET's Object-Oriented Infrastructure. This approach allowed us to seamlessly integrate logging with the rest of TIBET and allows you to create your own loggers, appenders, layouts, filters, markers, etc. using TIBET types and traits.

Prebuilt Logging

TIBET makes it easy to do quick level-filtered logging without having to configure loggers, appenders, or other Log4J constructs. This simplification is the result of a set of logging-related TIBET primitives and some default object construction by the library.

Lib vs. App Logging

As you may know, TIBET provides two global roots: APP and TP. The APP root is specific to application code while the TP root is specific to TIBET code.

When you start TIBET it also creates a pair of default loggers, one for the TP root and one for the APP root. These default loggers use TP.log.ConsoleAppenders by default, meaning they write their output to the JavaScript console.

TIBET's default loggers are integrated with the TP and APP root objects by virtue of a set of logging primitives on each root, primitives which make it easy to log by level.

Logging Primitives

For logging purposes there are primitives on each root, one for each logging level supported by the default logging system:

APP.debug
APP.error
APP.fatal
APP.info
APP.severe
APP.system
APP.trace
APP.warn

TP.debug
TP.error
TP.fatal
TP.info
TP.severe
TP.system
TP.trace
TP.warn

Calls to APP-based methods will default to the APP object's default logger, helping to keep your application logs independent of those from the library.

APP.trace(message);

When you use a primitive of this form it ensures the arguments are logged using the level defined by the primitive name.

varargs

All of TIBET's logging primitives of this form accept a variable argument list. You can build logging output from multiple strings just by providing them as separate arguments:

Log Names

One caveat with using variable arguments is that TIBET always processes the first argument to check for a TP.log.Marker or TP.log.Logger name. For example, if we use our prior inputs but change Sample to Test TIBET thinks we want to log to the test log and as a result the output is quite different:

In this case TIBET recognizes there's a test log and assumes we want to use that logger. As a result we see the test INFO as the log name and level rather than APP INFO. In addition, the log name (or what TIBET assumed was the log name) has been removed from the message text itself.

Markers

As mentioned in the Log Names section, one of the things TIBET checks the first logging argument against is a list of TP.log.Marker names. Markers are a Log4J 2.0 construct that allows you to effectively "tag" a logging message.

For example, let's say our application has a "forms" component. We can log from that component and tag all messages as being from the forms component as follows:

//  Do this once to tell TIBET we have a marker named 'forms'.
var mark = TP.log.Marker.construct('forms');

//  Log using our marker.
APP.info(mark, 'Generating another form.');

As the output here shows we see APP INFO output identifying this as an APP logger message at the INFO level. But we also see [forms] in the output, marking this message with our forms marker. TP.log.Filter objects can filter by marker allowing you to leverage appenders specific to a marker or set of markers.

Formatting (sprintf)

TIBET's logging primitives have one additional feature. Once the vararg list has been checked for log name/marker matches and the remaining arguments have been adjusted the first argument is checked for conformance to a sprintf string.

If the first non-marker argument includes sprintf formatting it is used as a format:

See the documentation for sprintf.js for more details and examples.

Branching Primitives

To help cut down on potential overhead you can leverage a second set of primitives specific to testing the current logging level:

APP.ifDebug
APP.ifError
APP.ifFatal
APP.ifInfo
APP.ifSevere
APP.ifSystem
APP.ifTrace
APP.ifWarn

TP.ifDebug
TP.ifError
TP.ifFatal
TP.ifInfo
TP.ifSevere
TP.ifSystem
TP.ifTrace
TP.ifWarn

The logging level check primitives test the current logging level and return a boolean if logging at that level would occur. This allows these primitives to serve as an easy way to create logging ternaries.

A fairly canonical usage of a logging branch test in TIBET might be:

APP.ifTrace() ? APP.trace(message) : 0;

You can also use them in larger more formal if() structures:

if (APP.ifTrace()) {
    APP.trace(message);
}

Note that the if{Level} primitives take a logger name to test and fall back to checking the receiver's current default logger.

The output in both cases, should it pass the filter, would resemble:

20150510T14:49:09.562 - APP TRACE - This is a test from our demo logger.

Built-in Logs

We mentioned a pair of default logs, the TP and APP logs. These logs are what we'd typically refer to as "activity logs", logs which are used without any specific form or format to their content. In other words, they track all kinds of activity.

TIBET also includes a number of specialized built-in logs, logs which are often configured to use different loggers, appenders, layouts, or other configuration and whose use is limited to very specific operations.

Examples of specialized built-in logs are the TIBET test log and TIBET change log which handle test harness output and code change logging respectively.

You don't normally interact with the built-in logs directly in your code, their use is automatic when you run tests or use the TIBET development tools for example.

Cookbook

Boot Log

Show The Boot Log On Launch

Set boot.show_log to true:

http://127.0.0.1:1407#?boot.show_log

By default the boot log will display messages output at the TP.SYSTEM level, a level reserved for system messages from TIBET.

Log At A Detailed Level During Boot

Set boot.level to a specific value from the list:

TP.ALL = 'ALL';
TP.TRACE = 'TRACE';
TP.DEBUG = 'DEBUG';
TP.INFO = 'INFO';
TP.WARN = 'WARN';
TP.ERROR = 'ERROR';
TP.SEVERE = 'SEVERE';
TP.FATAL = 'FATAL';
TP.SYSTEM = 'SYSTEM';
TP.OFF = 'OFF';

Note that you can use uppercase or lowercase level names:

http://127.0.0.1:1407#?boot.level=trace

When logging at TP.TRACE level the boot log will show you each file and inline script it loads, in order.

Log To The Browser Console

Set boot.console_log to true, or use it on the URL:

http://127.0.0.1:1407#?boot.console_log

Console-directed logging can be extremely useful if you've modified the boot screens or made other changes to the default TIBET startup infrastructure.

System Log

Getting A Logger

You can access a specific named logger using the getLogger method:

var logger = TP.log.Manager.getLogger(aName);

If a logger with the name provided doesn't exist a new Logger instance is created with that name. Note that since the name becomes part of the output in most default logger layouts you should use the name you're expecting to see in output.

TIBET will also unique instances if you construct a logger directly:

var logger = TP.log.Manager.getLogger('Demo');
...
var logger2 = TP.log.Logger.construct('Demo');
logger === logger2
true

Testing For Logger Existence

If you don't want to create a logger but want to know if one by a particular name exists use the exists method:

var lives = TP.log.Manager.exists(aName);

Getting All Loggers

You can get a list of the current logger names using the following snippet:

TP.log.Manager.get('loggers').getKeys().sort();
["app", "change", "root", "test", "tp"]

The root log you see in this list is the common parent log for all logs in TIBET, including the TP and APP logs. It's logging name is ROOT.

Logging A Message

Once you have a logger instance you log by invoking any one of the level-specific logging methods such as info, debug, trace, warn, error, etc.

logger = TP.log.Manager.getLogger('Demo');
logger.info('This is a test from our demo logger.');
...
20150510T14:49:09.562 - Demo INFO - This is a test from our demo logger.

Note the 'Demo INFO' portion of the text above. That's our logger name and logging level, which are output by default. When you're using the TP or APP primitives you'll typically see those values in place of Demo above.

Setting A Level Filter

Loggers have essentially two kinds of filtering. The first and most obvious is that a logger won't log messages which don't pass its check for the logging level.

As shown earlier in this document, logging levels run from "ALL" to "OFF". These logging endpoints essentially represent the "don't filter anything" and "filter everything" cases. All other levels fall into an order of sorts where the level will be logged if the logger/appender level filters are set to that level, or a more permissive one.

logger = TP.log.Manager.getLogger('Demo');
logger.setLevel(TP.log.WARN);
logger.info('This is a test from our demo logger.');

Notice that there's no output shown after our logger.info call above. The info level has been filtered out by setting our level to messages of TP.WARN or greater.

Configuring An Appender

Defining an Appender for a Logger is a simple matter. In the sample below we see the relevant lines configuring the TIBET test log:

var logger = TP.log.Manager.getLogger(TP.TEST_LOG);
var appender = TP.log.TestLogAppender.construct();
logger.inheritsAppenders(false);
logger.addAppender(appender);

First we get the logger by name. Next we construct an instance of the desired appender. Since we want this particular log to use only our specific appender we turn off appender inheritance and then add our appender instance.

Configuring A Layout

Layouts are associated with Appenders so our goal is to have Appenders which know what layout we want them to use. We can provide an Appender with layout information in several ways:

• use setLayout() on the appender instance
• define a specific layout instance on the appender type
• define a layout type on the appender type

Let's look at the first option.

Assume we've built an APP.ConsoleLayout which does something special with Entry objects, something other than the default TP.log.ConsoleLayout does. We can make that the layout for a ConsoleAppender as follows:

var appender = TP.log.ConsoleAppender.construct();
var layout = APP.ConsoleLayout.construct();
appender.setLayout(layout);

If we want to map a particular layout to all instance of a particular Appender type we can use one of two options.

Here's the "instance" version, which is useful for custom-configured layouts:

var layout = APP.ConsoleLayout.construct();
TP.log.ConsoleAppender.set('defaultLayout', layout);

We can also simply specify the type to be constructed by default:

TP.log.ConsoleAppender.set('defaultLayoutType', APP.ConsoleLayout);

Creating A Filter

As a simple example let's built a somewhat useless filter that only logs if the logging call includes more than one argument.

// Create a new filter type.
TP.log.Filter.defineSubtype('APP.log.DemoFilter');

// Define a filter that only logs when there are multiple arguments:
APP.log.DemoFilter.Inst.defineMethod('filter',
function(anEntry) {
    return anEntry.getArglist().getSize() > 1;
});

With our logging filter built we can use it to filter logging:

TP.log.Manager.getLogger('APP').addFilter(APP.log.DemoFilter.construct());

APP.info('blah');   // no output
APP.info('blah', 'blah');
20150510T18:40:39.823 - APP INFO - blah blah.

Not a recommended filter for obvious reasons, but the point is you can create filters that filter based on any criteria, from data in the Entry to current system state to any combination of the two, or anything else you need.

Also note that while we focused our demo above on a Logger you can apply filters to Appenders as well, filtering at whichever point makes the most sense for your application.

Clearing Filters

Clearing the filters for a Logger (or Appender) is a simple matter:

TP.log.Manager.getLogger('APP').clearFilters();

Creating Markers

Markers let you produce annotated log entries which can then be filtered. In the sample below we create a 'demo.marker' which, when used as the first item in a logging call, causes [demo.marker] to appear in the log output.

var marker = TP.log.Marker.construct('demo.marker');
logger.info('demo.marker', 'This is a marker-tagged output message.');
20150511T17:36:21.063 - Demo INFO [demo.marker] - This is a marker-tagged output message.

Code

TP.log Types

Logging functionality in the TIBET system is rooted on the TP.log namespace which contains the types which provide the core of the logging subsystem including the Manager, Logger, Appender, Layout, Entry, and Marker types.

The naming, functionality, and APIs for the logging types in TIBET is taken directly from the Log4J 2.0 specification, with minor adaptations as necessary to make things fit within TIBET's naming schemes and OO infrastructure efficiently.

TP.log.Manager

The TP.log.Manager provides a central point for accessing a particular logger or for operating on multiple loggers.

Methods on TP.log.Manager are type methods, methods which don't require an instance to be created. Here's the current list:

TP.log.Manager.Type.getInterface().sort().join('\n');
exists
getLogger
getLoggerFactory
getLoggers
getRootLogger
initialize
registerLogger
removeLogger

Typical usage revolves around getting access to a particular logger or checking for the existing of a logger without actually creating one. As you can see, there are also methods to remove a logger, but that's not a typical use case.

TP.log.Logger

Loggers are the primary entity you interact with when using the logging subsystem.

Every Logger instance has a name, an optional level, zero or more filters, and zero or more appenders which do the actual work of logging.

When a logger doesn't have a level, filter, or appender it will look through a list of parent loggers based on naming hierarchy. For example, a hypothetical logger named APP.test would check locally, then check the APP logger, and then check the ROOT logger.

The basic logger API can be found as follows:

TP.log.Logger.Inst.getInterface().sort().join('\n');
addAppender
addFilter
clearFilters
debug
error
fatal
filter
getAppenders
getFilters
getLevel
getParent
info
inheritsAppenders
inheritsFilters
init
isEnabled
setLevel
severe
system
trace
warn

As you can see, a lot of the methods are typical logging methods based on level, just as we saw with our APP and TP primitives. The remaining methods focus on configuring the logger's level, appenders, and filters.

A Note On Levels

If you look at the level options you'll likely notice that there are 3 which seem to overlap to some degree: error, severe, and fatal. TIBET doesn't enforce any particular semantic on these but we can offer you a suggestion based on our usage:

• error: something bad happened…but we can probably keep running the app.
• severe: something happened that implies we may have a data corruption issue.
• fatal: stop running. seriously, before something unrecoverable happens.

Again, your use of these levels can vary, these are just our suggestions.

Inheritance

Loggers can "inherit" both appenders and filters. Log4J "inheritance" is done in an additive fashion such that a Logger will use whatever appenders it has locally defined, but it can also use the appenders and/or filters from any of its ancestors.

You can use the inheritsAppenders and inheritsFilters methods to define how you want a specific logger instance to handle these options. They're on by default so loggers normally inherit from ancestor loggers.

TP.log.Appender

Loggers handle the public interface to the logging subsystem but it's Appenders and their associated Layouts that define what you see and where you see it.

The default appender for most TIBET loggers is the TP.log.ConsoleAppender, a type focused on directing logging output to the JavaScript system console. As a result if all you need is console-based logging you rarely need to alter a Logger's default appender.

Appenders have a very simple interface:

TP.log.Appender.Inst.getInterface().sort().join('\n');
addFilter
append
clearFilters
filter
getFilters
getLayout
getLevel
isEnabled
log
setLayout
setLevel

You may recognize some of these methods, they're mirrored on the Logger type. Both Logger and Appender make use of two TIBET traits which serve to mix in leveling and filtering behavior. These trait-based methods let Logger and Appender share the logic surrounding levels and filters.

append

The central method for an appender is the append method but you rarely invoke it directly, it's invoked by the Logger methods which we saw in an earlier section. Instead, it's your implementation of append in subtypes that matters.

Appenders become interesting when you find yourself needing to do special processing of TP.log.Entry objects, perhaps funneling them to a remote logging service for example.

Here's a canonical example of a simple append method:

TP.log.DemoAppender.Inst.defineMethod('append',
function(anEntry) {

    /**
     * @method append
     * @summary Formats the entry data using the receiver's layout
     *     and writes it to the console. Logging is always done using
     *     the default 'log' call rather than a call which might alter
     *     the output in any form.
     * @param {TP.log.Entry} anEntry The log entry to format and append.
     * @returns {TP.log.Appender} The receiver.
     */

    var layout,
        content;

    layout = this.getLayout();
    content = layout.layout(anEntry);

    top.console.log(content);

    return this;
});

The other interesting aspect of Appender usage is configuring their Layout, something you may find yourself wanting to do long before you need to create custom Appenders.

TP.log.Layout

As the code example in the previous section shows, a Layout is used by an Appender to format a TP.log.Entry for output. That formatting process is done by the layout method of the Layout instance associated with an Appender.

By creating custom subtypes of TP.log.Layout and implementing your own layout methods you can change how TP.log.Entry content is formatted for output.

The simplest version of this might be:

TP.log.Layout.Inst.defineMethod('layout',
function(anEntry) {

    /**
     * @method layout
     * @summary Formats an entry. The various data fields in the entry
     *     may be processed in virtually any fashion as a result. The
     *     default format is whatever is produced by TP.str() which
     *     relies on the Entry type.
     * @param {TP.log.Entry} anEntry The entry to format.
     * @returns {Object} The formatted output. Can be String, Node, etc.
     */

    return TP.str(anEntry);
});

As the previous snippet shows, the layout method is provided a TP.log.Entry and should return a string.

TP.log.Entry

Every logging method creates an intance of TP.log.Entry which captures data about the logging message, time, etc. The entry is then made available to the various methods involved in filtering, formatting, and presenting log data.

At the time of this writing these values are captured:

• date: The current Date() at the time of the logging call.
• logger: The logger whose logging method triggered Entry creation.
• level: The level at which the entry was logged.
• arglist: The complete list of arguments to the triggering logging call.
• marker: An optional marker from arguments[0]. Must match a TP.log.Marker.

Using this information you can produce whatever output your particular layout desires. The TP.log.ConsoleLayout used by the TP.log.ConsoleAppender formats Entry objects into a form resembling:

{ms} - {level} {logger} {[marker_name]} - {string}

Most interaction with Entry objects is done by the append method of Appender, the layout method of Layouts, and the filter method of Filters.

TP.log.Filter

Whenever you log, both the TP.log.Logger and TP.log.Appender instances involved in your logging call get an opportunity to filter what they'll output. This filtering process is applied to every TP.log.Entry which is submitted for potential logging.

The most obvious filtering which happens is done based on logging levels, which happens regardless of other filters, but you can expand filtering by creating and associating TP.log.Filter instances with either a Logger or Appender instance.

The default implementation of a TP.log.Filter instance for filter looks like this:

TP.log.Filter.Inst.defineMethod('filter',
function(anEntry) {

    /**
     * @method filter
     * @summary Runs one or more checks on anEntry to decide whether
     *     it can be passed forward to an appender. The default
     *     implementation is intended to be overridden by subtype
     *     versions.
     * @param {TP.log.Entry} anEntry The entry to filter.
     * @returns {Boolean} True if the entry is valid.
     */

    return true;
});

Obviously there's not much filtering going on here. We're returning true for all Entry objects provided, essentially saying "Yes, you can log this.". Returning false from your filter method will cause that Entry to be skipped.

TP.log.Marker

Markers are essentially named entities. What makes them intersting is that, like Loggers, they inherit from TP.log.Nestable, which means a Marker can be thought of as belonging to a hierarchy. This makes them particularly useful for filtering.

Markers should be created using the construct call. To make them interesting and more valuable you should put some thought into how you name them. Using common system subsystem and component names is a good default approach.

var marker = TP.log.Marker.construct('APP.logger');

At runtime when you're logging if you use a Marker name as the first parameter to your logging call the associated TP.log.Entry object will have that marker associated with it automatically:

var logger = TP.log.Manager.getLogger('Demo');
var marker = TP.log.Marker.construct('demo.marker');
logger.info('demo.marker', 'This is a marker-tagged output message.');
20150511T17:36:21.063 - Demo INFO [demo.marker] - This is a marker-tagged output message.

The interesting thing to note is the [demo.marker] portion of the message. This is output by the default console layout and can be used in the system console as a handle for filtering independent of any TIBET filtering.

Markers have to be configured/constructed prior to logging for them to be useful, but if you have specific "slices" of logging you wish to identify a set of predefined Markers in a hierarchy is a great option.

Summary

There are a lot of powerful options to logging thanks to TP.log and the Log4J 2.0 APIs it implements.

For examples of logger, appender, and layout construction you may want to look at the TIBET source file TIBETLogging.js found in the TIBET kernel. That file creates the ConsoleLogger/ConsoleAppender pair as well as pairs for both the TIBET change log and test log. The source code there should help you get started with customing logging to meet your specific needs.