Skip to main content

Logging in Phobos

Posted by robc on August 25, 2006 at 4:22 PM PDT

Last week we added logging functionality to Phobos. It's an all-JavaScript library clearly inspired by Apache Commons Logging. Although logging is not very glamorous, experienced developers know that it can make a world of difference when chasing down a bug in an application, so it's a much welcome addition to Phobos. I should also point out that this functionality is in CVS but not in the latest Phobos binary build, which is over six weeks old, so you'll have to build Phobos yourself to try it out.

Application logs can be created using the library.log.get function. Here's an example:

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

Typically, you'll put this at the top of a module. Here's an example of a controller that uses logging to log an action method:

  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 action code goes here ...
          }
      }
  });

Just like in Commons Logging, there are six levels: trace, debug, info, warn, error and fatal. For each level, a log object defines a method and a property, with names like trace and
traceEnabled. The method is used to write a log entry, while the property is set to true if and only if the corresponding log level is enabled.

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 the application/startup.js script:

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

As you may expect, log names are hierarchical. Moreover, since there is no notion of packages in JavaScript, log names are completely up to the application. For example, you could have a sub-log called app.persistence exclusively dedicated to persistence events, regardless of the script the code resides in.

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). This is an excellent way to learn how the libraries work. The debug level is the most appropriate to follow what goes on behind the scenes while processing a request.

As an example, let's see how a request involving a plain script is processed. I took the examples application and added 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};

Then I pointed my browser to http://localhost:8080/examples/hello.js and got the following output:

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

As you can see, in this (simple) case, the framework started off by looking for some static content called hello.js, then tried to locate a script with the correct name in the script path. It succeeded, finding the application/script/hello.js script, then proceeded to invoke it.

On the Phobos web site you'll find a more detailed document describing how logging works and how you can use it in your applications.

Related Topics >>