As mentioned in my previous post it might be a bit overwhelming when you want to start logging with coldbox. So why not just appending some information to a file instead? There’s a few reasons for this:

  • standards: Logbox has a standard way of sending information to a logging source, so you don’t have to rewrite your code if your loggin requirements change. There are several logging levels (severity), more on that later. And configuration can be done in one central place if you want.
  • performance: Logbox has some standard async loggers. This is a performance benefit, your code will not wait until your logging is finished
  • reusability. This has a a lot in common with the first bullet on standards. All coldbox framework code and many libraries are using logbox. So if you know how to configure Logbox, you can tap into all info which will be logged by framework and other library code.
  • flexibility: Logbox allows you to enable debug logging or suppress other logging level for any part of your own code, the coldbox framework or installed modules. And it allows you to send debugging info to any repository you want. You can even create your own logging methods.

In this post I will show you how to add simple logging capabilities to a coldbox application. I will explain all concepts of Logbox in detail, but I will start with the short version:

  • create a Logbox struct in your coldbox configuration file with keys for appenders (required), root logger (also required), categories (optional but very useful) and the related keys debug, info, warning, error, fatal and off, which are all used to set maximum logging levels for certain categories
  • add at least one appender to your appenders array. There are many appenders such as file appenders, database appenders, console appenders and more. Each appender has at least a class name and some properties which may vary based on the type of appender
  • add a root logger. This root logger is some kind of default category. If you create a a named logger, which is a logger for a category it will try to find a logger configuration for this category and if it doesn’t find the category or a parent category it will use this root logger config. A root logger has an appenders property where you can specify to which appenders the message will be sent, and a levelMin (default=FATAL) and levelMax (default=DEBUG) property to specify which level of messages will be allowed for this category.
  • add some (named) categories. This is optional, but makes live easier if you want to modify logging behaviour for parts of your application, like sending it to other appenders or restricting your logging to certain levels.
  • add some impliciet categories. this is done by using the keys debug, info, warning, error, fatal and off to specify a maximum level for certain categories.

Your config will look a bit like this ( only with some real values…. ) :

//LogBox DSL
logBox = {
    // The configuration file without fileextension to use for operation, instead of using this structure
    configFile = "config/LogBox", 
    // Appenders
    appenders = {
        appenderName = {
            class="class.to.appender", 
            layout="class.to.layout",
            levelMin=0,
            levelMax=4,
            properties={
                name  = value,
                prop2 = value 2
            }
    },
    // Root Logger
    root = {levelMin="FATAL", levelMax="DEBUG", appenders="*"},
    // Granular Categories
    categories = {
        "coldbox.system" = { levelMin="FATAL", levelMax="INFO", appenders="*"},
        "model.security" = { levelMax="DEBUG", appenders="console"}
    }
    // Implicit categories
    debug  = ["coldbox.system.interceptors"],
    info   = ["model.class", "model2.class2"],
    warn   = ["model.class", "model2.class2"],
    error  = ["model.class", "model2.class2"],
    fatal  = ["model.class", "model2.class2"],
    off    = ["model.class", "model2.class2"]
};

Now you can start logging. In a model the most flexible way to do this is by wirebox injection, e.g

property name="log" inject="logbox:logger:{this}";
//or
property name="myLog" inject="logbox:logger:models.sub.myService";
//or
property name="perfLog" inject="logbox:logger:performance";

In a handler or interceptor it is even easier. You can do the same injections to create named loggers, but there is also a preconfigured logger called log so you can just start logging by calling

log.info("Hi there");
log.fatal("Terrible crash!");

So now you know how to start logging I will explain some concepts and some stuff which is confusing or unclear in the Logbox manual.

Logbox

Logbox is the name of the logging library. Logbox is not only available for coldbox, but also standalone. A lot of the functionality has been described in the manual, but it has some issues. Some of the info is slightly outdated, and a lot of the examples lean on programmatic configuration, while creating a config file is probably easier. It also makes you think Logbox is very simular to Apache Log4J, but there are some differences, which you shouldn’t ignore. You can use Logbox standalone, but in a coldbox app it is a lot easier to configure. All information can be found in the manual, but it is a lot, and not always applicable to the most simple (and most often used) scenario: A coldbox app with a configuration file. I will focus on that scenario.
The easies start is to create a config struct, which is just a struct called Logbox with some keys called categories, appenders, root and some more. Just create a correct Logbox struct and stick it in your coldbox config file . You already saw a config example in the intro of this post.

Loggers

So what’s a proper definition of a logger? To my surprise there’s no definition of a logger at all in the Logbox docs. It only tells you HOW to get a logger which you can use in a handler or component. So what does Wikipedia say?

A Logger is an object that allows the application to log without regard to where the output is sent/stored. The application logs a message by passing an object or an object and an exception with an optional severity level to the logger object under a given name/identifier.

wikipedia

You can ask logbox for a logger and give it a category name (more on categories later). The easiest thing to do is by having wirebox create it for you, in both your handlers or models, for example:

property name="myLog" inject="logbox:logger:{this}";
property name="perfLog" inject="logbox:logger:performance";

Each logger has a category. This way you can distinguish between loggers in different models or handlers, which can be useful if you want to tweak your logging output later (in categories).

The {this} part in the wirebox definition makes sure you will get a logger named after your current component.

Sometimes it makes sense to specify some simple name instead of the component name. I use a performance logger for example to log some performance results in any handler. If I want to write that to a specific location it makes sense to have a named logger and define some locations where to report the results (we do that in the categories section later). Coldbox makes things easy for you. In all handlers and interceptors a preconfigured logger is already available, named log and a preconfigured category name of the current handler or interceptor. So no injections required in a handler unless you have specific requirements (like my performance logger).

Severity levels

When you want to log messages, you can do that in different severity levels. That’s one of the most confusing parts of Logbox vs Log4J. We are talking about severity levels. I’ll list your Logbox severity levels here.

  • NONE = -1: no logging at all
  • FATAL = 0 : the application’s situation is catastrophic, it should stop
  • ERROR = 1: a severe issue is stopping functions, but application still runs.
  • WARN = 2: Unexpected problem: not sure if it will happen again, but no serious harm to your application yet. Eventually you need to look at it.
  • INFO = 3: Normal behaviour, these messages just tell you what happened during normal operation.
  • DEBUG =4: Information necessary to diagnose, troubleshoot or test the application.

In Logbox your highest Level is DEBUG and FATAL your lowest level. (NONE is a special case). By default coldbox will log anything from levelMin=FATAL to levelMax=DEBUG. As you can see the term Severity Level is a bit deceiving here. Something FATAL really has a higher severity than a INFO event. But Logbox works exactly the opposite way, so not like Log4J. If you just want to log the most severe problems you have to LOWER your LevelMax. If you want to see every little detail you have to INCREASE your LevelMax. By default coldbox will log anything from levelMin=FATAL to levelMax=DEBUG. I often think in terms of verbosity. Maximum verbosity when debugging were DEBUG is my levelMax. But it still makes not much sense :-). If you have a logger you can create messages like this

myLog.fatal("Oops, your app will explode!");
log.debug("Show me the details", {id=20, action="new");
perfLog.warn("Execution time #mSec# msec, so slow");

As you can see, you can log messages, an even additional details, as shown in the second example. In most cases it doesn’t makes sense to modify your levelMin, unless you only want to show debug messages for example, and hide fatal, error and warning messages.

Appenders

Each logbox setup needs at least one appender. An appender is an object which is used by Logbox to send log messages to some destination repository. Coldbox ships with several appenders. My favorites: DBAppender, FileAppender and RollingFileAppender. There’s also an EmailAppender. Let me tell you how I hate DIRECT emails on any loggable event. I will not tell you how often we had to clear a 50k mailqueue for customers, because their app started mailing at the wrong occasions. Let me show you two appenders in my config

logBox = {
  appenders = {
	debugLog = 	{
	  class="RollingFileAppender",
      properties = {
	    filePath = "../logs",
	    fileName 			= "debug",
	    autoExpand 			= true,
	    fileMaxSize 		= 2000,
	    fileMaxArchives 	= 3,
	  },
 	  //levelMin="FATAL",
      //levelMAX="DEBUG"
	},
	errorLog = 	{
	  class="DBAppender",
	  properties =
	  {
		dsn	                = "myLogDsn",
		table               = "errorlog",
		autocreate 			= true,
		async 				= true,
		rotationFrequency	= 60,
		rotationDays		= 30
	  },
	}
//...
},

As you can see from my sample appenders, I created an errorLog appender and a debugLogAppender. Every appender has a

  • class: you don’t have to specify the full class path anymore, unless it is a custom created appender
  • levelMin and levelMax: don’t touch this on appender level, unless you are really sure you want to restrict your logging levels. In most scenario’s there are better places to do this. You probably are going to use your appenders for more categories, so that’s often a better place. More on loggin levels later.
  • properties: each appender type has it’s own properties. See the manual for all properties for a certain logger type. For example: a file logger needs a file path, a db logger needs a datasource and a table.

Categories

Categories will give you the most advanced configuration option. If you create loggers named after your components ( by adding the dot separated component path as a category for your logger), you can use these categories to set logging levels and logging destinations. We use a concept called Category Inheritance for this. Some examples can be found in the manual. Let’s say we have the following categories:

//....
root = {
  levelMin="FATAL", levelMax="INFO", 
  appenders="myFileAppender,myDBAppender"
},
categories = {
  "coldbox.system" : {
    appenders="myFileAppender"
    levelMax="WARN"
  },
  "myModule" : {
    appenders="myDebugFileAppender"
    levelMax="DEBUG"
  }
}

So, if you have a logger named “coldbox.system.core.util.Util” there is no category defined, but if you traverse your path and look at the parent category you will find:

  • coldbox.system.core.util
  • coldbox.system.core
  • coldbox.system and this has a category defined. So this component will only log fatal, error and warn levels and sent it to myFileAppender (which I defined in the appender part).

If I have a logger for “myModule.someComponent” it will match the myModule category and log everything from fatal to debug in myDebugFileAppender.

The special case is when your component is NOT in some of the specified categories. In that case it will finally match your root logger, so all other categories will be sent to both your myFileAppender and myDBAppender for all Levels from fatal to info. So no debugging here, although there are simple ways to adjust this setting for your development environment.

Implicit categories

The coldbox configuration has a few more keys, such as debug, info, warning, error, fatal and off. They are mentions in the configuration examples as implicit categories. Actually they are just a different point of view on configuration. You start with a levelMax, and specify which categories you want to use for that level. Some examples:

// silence model.class, model2.class2
off   = ["model.class", "model2.class2"],
// make myNewModule and qb very chatty
debug = ["myNewModule","qb"]

These implicit categories look very handy compared to the categories definitions above, but they have their limitations. You can’t change appenders here, and you also cannot change the levelMin. For just restricting the verbosity of your logging they are very handy

More configuration options

In this post I showed you many of the basic Logbox options. There is a lot more. One of the things we found quite useful: customising the output of our appenders, so we could log more info in each event. This can be done by creating your own Layout or by creating your own appenders. In some future posts I will show you how and also give some ideas on integration your logging in your handlers and libraries for auditing and performance monitoring. We send a lot of info to a logging database, so we will also create some ultra basic viewer which integrates in our applications.

Happy logging!