Using Logging

Introduction

Phobos now contains extensive logging functionality. If you are familiar with the Apache Commons Logging library you'll be right at home using its Phobos equivalent.

Currently the Phobos log output goes to the standard output (System.out), so the actual location and name of the resulting file is dependent on the servlet container you are using. In GlassFish, the default location for the log is glassfish/domains/domain1/log/server.log.

Logging events in your application

Just like in Commons Logging, there are six levels. In order of importance, they are:

fatal
error
warn
info
debug
trace

It is good practice to establish uniform guidelines for your application, so that administrators will know where to look for information. As a general rule, use the lowest logging level that will get the job done: for example, you don't want purely informational messages to be misinterpreted as warnings.

The Phobos logging library is called library.log. For each logging level, it exports a constant representing the corresponding logging level, e.g. library.log.WARN for the warn level. To create a log, use the library.log.get function. Here's an example:

  var log = library.log.get("app");

Typically, you'll put this line at the top of a module or script, then use the log instance whenever you want to log some data. To generate log output, you need to make sure your code calls any of the methods defined on the log object. For instance, here's a code snippet from a controller that logs an action method at the trace level:

  library.common.define(controller, "test", function() {
      var log = library.log.get("app");

      this.Test = function() {};

      with (this.Test) {
         prototype.index = function(mapping) {
              log.trace("invoked action: test.index");

              // ... the rest of the controller code goes here ...
          }
      }
  });

For each level, a log object defines a method and a property:

the method is named after the level (e.g. trace); it can be used to write a log entry at the corresponding level;
the property is named after the level suffixed with the string Enabled (e.g. traceEnabled); its value is a boolean which is true if and only if the corresponding log level is enabled.

For example, assume that there is some expensive computation that you only want to take place when logging at the debug level. Your logging code would then look like this:

  if (log.debugEnabled) {
    log.debug(expensiveFunction(42));
  }

Configuring logging

The final bit of information you need to start using logging is how to configure it. Like most other application settings, logging is configured via the application.options object. For example, to set the logging level for the app log to debug, you can add the following line to a startup script:

application.options.log["app"] = {level: library.log.DEBUG};

The library.log module defines symbolic constants for all the levels, in the form of uppercase identifiers, like DEBUG and ERROR. The default level is error. You can change it by modifying the configuration of the predefined any log.

E.g. to set the default to warn:

application.options.log["any"].level = library.log.WARN;

Finally, it's important to know that log names are hierarchical. If you use a log name of foo.bar.baz, the system will look for log configuration information in the following order, stopping at the first match: foo.bar.baz, foo.bar, foo, any. Thus, configuration for the foo log will provide a default for all its sub-logs, like foo.bar and foo.somethingElse.

Logging and the built-in libraries

The Phobos libraries now contain logging code, so you can trace through them with ease. The log name is framework, with sub-logs for each built-in library (e.g. framework.controller, framework.db, etc.). The debug level is the most appropriate to follow what goes on behind the scenes while processing a request.

As a practical example, let's see how some simple requests are processed. First of all, take the examples application and add the following line to its application/startup.js file: (the timestamp: false bit turns off timestamping, so the output is easier to read)

application.options.log["framework"] = {level: library.log.DEBUG, timestamp: false};

Now point a browser to http://localhost:8080/examples/hello.js, then check the server log. It should contain entries entries like the following ones:

INFO: lifecyle.onService: GET /examples/hello.js
DEBUG: mapping.applyRules: invoking function: library.mapping.maybeContent
DEBUG: mapping.applyRules: invoking function: library.mapping.maybeScript
DEBUG: mapping.maybeScript: running: /application/script/hello.js
DEBUG: scripting.run: executing: /application/script/hello.js

Based on the output, it's easy to see that the framework first tried to map the request URL to some static file but failed. It then tried to map it to a script, and sure enough it found and ran application/script/hello.js.

As a final example, let's see how a request involving a controller is processed. The URL is http://localhost:8080/examples/test2/action and the corresponding log output is:

INFO: lifecyle.onService: GET /examples/test2/action
DEBUG: mapping.applyRules: invoking function: library.mapping.maybeContent
DEBUG: mapping.applyRules: invoking function: library.mapping.maybeController
DEBUG: mapping.maybeController: created controller: test2.Test2
DEBUG: mapping.maybeController: invoking method: __onRequest__
DEBUG: controller.__onRequest__: action: action
DEBUG: controller.__onRequest__: invoking: action
DEBUG: view.render: rendering view:/application/view/simple.ejs
DEBUG: scripting.run: executing: /application/view/simple.ejs

As you can see, after a couple of misses the framework found an appropriately named controller and invoked its action method, which in turn caused the simple.js view to be rendered.

Another good candidate for debugging is the persistence library, library.db. When logging is enabled at the debug level, it logs every SQL statements that it produces. As an exercise, take the demoj1 application and add the following line to application/startup.js:

application.options.log["framework.db"] = { level: library.log.DEBUG, timestamp: false };

then play with it for a while and examine the logs to see all the SQL statements that were executed.

Tracing

At the most detailed level (trace), the framework logs each and every call into the Phobos libraries; since this is a formidable amount of output, you'll rarely need it. There are cases though in which tracing through one particular built-in library can make a big difference in debugging an application. Thanks to hierarchical logs, it's easy to turn on tracing in, say, the controller library and nowhere else:

application.options.log["framework.controller"] = { level: library.log.TRACE };

Main Menu