Volume Number: 17 (2001)
Issue Number: 10
Column Tag: Advanced WebObjects 5

Part 2 - Using the Log

by Emmanuel Proulx

WebObject's powerful logging API

Sometimes you can't use a debugger. For example, when an obscure problem happens only on the server, and that machine doesn't have the development environment installed. In that case, you want to use logging.Ê

You don't have to be desperately seeking a bug to use logging; you could just need to keep a trace of the events of the application, for bookkeeper purposes. Or you might want to log a function that is behaving properly, just in case it has a change of heart. Whatever the reason, it is important to know how it is done.

Before we start, you might want to go back and add toString() functions to all your custom classes, so you will be able to print them out to the log.

The logging system in WebObjects is very powerful and comprehensive. All the message logging is done through the class NSLog. This class lets you log events two ways:

• Sending values to the output, error or debug logging objects. This uses the same mechanism as System.out and System.err.
• Sending output to a custom logger.

A third way of using NSLog is to enable logging on subsystems of WebObjects, as covered in a subsequent section.

The easiest way to use logging is simply to call these methods from anywhere in the code:

Function: NSLog.out.appendln(v)

• Parameters: 1: The value to send to the output stream. If it is not a String already, this function will transform the value into a String.
  This function sends a value of any type (Object or base type) to the stdout output stream.
• Function: NSLog.err.appendln(v) or NSLog.debug.appendln(v)
• Parameters: 1: The value to send to the output stream. If it is not a String already, this function will transform the value into a String.
  This function sends value of any type (Object or base type) to the stderr error stream.

As a general rule, always write descriptive, helpful string containing the object and method that wrote the message, some debugging information, and if there was an exception thrown, the stack trace. To help you to extract the stack trace from an exception, simply call the following (very helpful) function:

Function: NSLog.throwableAsString(e)
Returns: String, the stack trace extracted from the exception.
Parameters: Throwable e: The exception containing the stack trace to extract.
This function extracts the stack trace from any kind of exception and returns it as a String.   

As an example, the following piece of code catches an exception, writes out useful information and the stack trace to the error log:

Listing 1. stackTraceExample()

This code sample is an example of using NSLog to send an error message to the log. It also shows how to 
print the stack trace to a String.

    public String stackTraceExample() {
        String result = "Welcome to this experiment... ";
        try  {
            result += "Doing something that may " + 
                "throw an exception. ";
            // ...
            throw new Exception("An error has occurred.");
        } catch (Exception e) {
            result += " An exception has occurred! ";
            NSLog.err.appendln("Class Main method " +
                "stackTraceExample() has thrown: " +
                e.toString() + ". STACK TRACE: " +
                NSLog.throwableAsString(e) ); 
            result += " Error logged and stack printed.";

        }
        return result;
    }

By default, NSLog sends messages to the log without any details about the context in which the message was send. But sometimes it doesn't give enough information to be able to track problems properly. This is why I recommend turning on the verbose mode. It is off by default. When it is on, the verbose mode prints more information before writing out the log message:

• the time at which the message was sent to the log
• the name of the current thread

To turn on the verbose mode globally in an application, simply call this method from the Application.main():

Function: NSLog.out.setIsVerbose(b) or 
NSLog.debug.setIsVerbose (b) or
NSLog.debug.setIsVerbose (b)

Parameters: boolean b: if true, then verbose mode is turned on. If false, it is turned off (the default).
This function lets you turn on and off the verbose mode for (respectively) the output log, 
the error log and the debug log.   

An example of this will be shown momentarily.

The log file will then be more crowded, but you never know when this extra information may be of assistance.

Sending out anything to the stderr or stdout may be pretty much useless unless there is a way to capture all that information and see it later. By default, the log messages are not sent anywhere except to the console.

This piece of code shows how to redirect each logging object to a file.

Listing 1. logToAFileExample()

This code sample is an example of using NSLog to send an error message to a file.

    public String logToAFileExample() 
        throws FileNotFoundException {
        String result = "Another experiment... ";

        result += "Setting up the file. ";
        PrintStream ps = new PrintStream(
            new FileOutputStream("/tmp/a2log.txt",true)); 
        NSLog.PrintStreamLogger logFile = 
            new NSLog.PrintStreamLogger(ps); 
        NSLog.setOut(logFile); 

        result += "Writing a message. ";
        NSLog.out.appendln("Logging this message! " +
            new java.util.Date() );
        result += "Look at the file /tmp/a2log.txt. ";
        return result;
    }

Note that the file here is appended to, not overwritten. This means the log files can fill up the hard drive at one point. It is good practice to use different log files (e.g. one per day) and to have a procedure to archive log files and free up hard disk space regularly.

Another good practice is not to hardcode the folder names, but rather to get this as a property. This is also more portable, as you'd configure it differently for each platform, and even for each computer on which the application is deployed.

The example shown at the end of this section sets the three logs in the same file, under the folder specified as the system property "logfolder". I suggest you set this to the folder /var/log on the Mac OS X. Make sure that the user has write access to that folder. On other platforms, you may set this to an appropriate folder.

Logging is on by default, but you may turn it off by calling this function:

Function: NSLog.out.setIsEnabled(b) or NSLog.debug.setIsEnabled (b) or NSLog.debug.setIsEnabled (b)
Parameters: boolean b: if true (the default), then the logging is on. If false, it is turned off.

This function lets you turn on and off the logging for (respectively) the output log, the error log and the debug log.   

I do not see why you would do something such as this, but hey, it's available.

Also, NSLog lets you control the type of information you wish to see from existing subsystems of WebObjects. You have the ability to decide which groups of related events will go to the log. You also have the ability to get only those events that are of a certain level of importance.

Group selection

A group is a category of messages. Each group corresponds to one subsystem within WebObjects. There are 25 different default groups. NSLog lets you decide which groups should log events, and which should be ignored. Manipulating groups is done with these methods:

Function: NSLog. setAllowedDebugGroups(g)
Parameters: long g: The bit mask that represents the groups that should log events.
This function replaces the bit mask for selecting the groups that should log events. Each bit is a 
different group. The accepted groups are listed below. The previous groups will be discarded.   

Function: NSLog. allowDebugLoggingForGroups(g)
Parameters: long g: The bit mask that represents the new groups that should log events.
This function adds the specified bits to the bit mask for selecting the groups that should log 
events. Each bit is a different group. The accepted groups are listed below. The previous groups will 
be preserved.   

Function: NSLog. refuseDebugLoggingForGroups(g)
Parameters: long g: The bit mask that represents the groups that should not log events.
This function removes the specified bits from the bit mask for selecting the groups that should log 
events. Each bit is a different group. The accepted groups are listed below. The bits that are not set 
will be preserved. To turn off all groups, simply call 

NSLog.refuseDebugLoggingForGroups(~0).   

Because of space restrictions, we won't show a complete list of the default groups. But one is available here:

http://developer.apple.com/techpubs/webobjects/FoundationRef/Java/Classes/NSLog.html#CAJEHBJJ

The most obvious example of a category of events is the SQL and database access. You often want to see the generated SQL statements and know when and why the database is being accessed. To turn on the database-related groups, simply call these:

NSLog.allowDebugLoggingForGroups
                                       (NSLog.DebugGroupSQLGeneration);
NSLog.allowDebugLoggingForGroups
                                    (NSLog.DebugGroupDatabaseAccess);

You may even create your own group simply by declaring a constant and assigning it existing groups. Combine the groups with the bitwise OR operator:

public final long DATABASEGROUP = NSLog.DebugGroupSQLGeneration | NSLog.DebugGroupDatabaseAccess;

Then use your new group the same way you use the NSLog groups:

NSLog.allowDebugLoggingForGroups(AClass.DATABASEGROUP);

Level selection

Throughout all WebObjects subsystems, you can filter out messages based on their level of importance. Some messages are more important (error messages) and some are less (informational messages). The method that sets the level is NSLog.setAllowedDebugLevel(int), which takes one of these 4 levels as a parameter:

• NSLog.DebugLevelOff (0): This basically disables all messages.
• NSLog.DebugLevelCritical (1): This displays only the error messages.
• NSLog.DebugLevelInformational (2): This displays error messages, and some relevant messages.
• NSLog.DebugLevelDetailed (3): This displays all messages, including many irrelevant ones.

  WARNING: Using NSLog.DebugLevelDetailed will greatly slow down the execution of your application. Avoid using it.

  ---

  Source Code Management

  What is SCM?

  Source Code Management (SCM) software help multiple developers that work on the same application, by taking care of concurrency and tracking file version history. The Project Builder has integrated support for one SCM product called CVS (Concurrent Version System). This product is popular on Unix platforms, and is installed with Mac OS X.

  Setting Up SCM

  Before starting to use SCM, you must set up a CVS repository (and usually also a server). Once those are set up, the next step is to create a blank folder that will serve as the root of all your projects (in this book, the root folder is ~/projects). Assume the CVSROOT environment variable is already set.

  • If the project you are working on is not yet in the repository, you must first put it there. This can be achieved by entering this command in a Terminal window (suppose you are working on vendor 1.0, release 1.0 of your application):

  cd ~projects
  cvs import Find-A-Luv V1_0 R1_0
  

  If you're going work with an existing project, you must first obtain it from the repository. You have to do that using the shell. Open a Terminal window and enter these commands:

  cd ~
  cvs co projects/Find-A-Luv
  

  Once either of these steps is executed, CVS is set up properly to work with WebObjects. Look in your project's folder and you will see some folders named "CVS".

  WARNING: Don't erase any CVS folders! If you do, then CVS will cease to work. If this happens to you, back up any modified code (without the CVS folders), then do a checkout (cvs co ...). Copy the backed up code on top of the old one you just got.

  You may now open your project with the Project Builder. Look at the menu SCM; all of its items are now available. The Project Builder has become aware of the CVS folders and can make use of the repository.

  Status of Files

  When SCM is enabled, you can see the status of the files in your project by looking in the file browser tab. A new column has appeared, displaying the state of all files. In this example, a little "M" means the file has been modified:

  

  You may synchronize the status column with the current status of the repository by selecting menu SCM | Refresh Status. If someone has modified a file, or if there's a conflict, you will see right away.

  Getting the Latest Version

  Suppose someone else has modified a file and you still have the older version. You must get the latest version. To do that, simply go to menu SCM | Update to Latest Revision. The Project Builder will transfer the file and display it instead of the old one.

  Committing Changes

  When you change a file, you must commit it before others can see your modifications. To do this, open menu SCM | Commit Changes. A dialog will pop up. Enter the description of the changes you applied. Click Commit.

  Adding Files

  After adding any files (using menu File | New File for example) don't forget to add the files in the repository. You may do so simply by following these steps:

  • Select the new file, folder or group
  • Go to menu SCM | Add to Repository.
  • The files are marked as being new, but are not added yet. To add, select the file, folder or group again and go to menu SCM | Commit Changes. You will be asked to enter a description.
  • The project itself is modified when you add files. Select the project in the file browser (first item) and go to menu SCM | Commit Changes.

  NOTE: Once the changes to the project are committed, there is no way to know if a file was added to the repository already or not. Don't forget to add new files to the repository. If you do, all other developers will get compilation errors because the files are missing on their computers.

  Comparing and Merging

  In the situation where a file is marked as being modified, you may want to see what was modified before committing it. In order to do that, you need some way to see the difference between your version of the file and the one in the repository. The menu SCM | Compare with Base does exactly that. It brings up a utility called FileMerge, which shows you the repository version on the left side, and the latest version on the right side. This is quite handy.

  Another situation may arise, in which the version in the repository is newer than the one you modified. Meaning someone modified and committed the file at the same time you were modifying your version of the file. The two versions need to be consolidated. FileMerge can help in this task, by showing you both versions of the file, and letting you merge the two versions into a newer, better third version. To do just that, you have to open menu SCM | Compare/Merge with Latest Revision.

  The FileMerge utility is out of the scope of this book, but you may learn all about it by checking out its online help.

  Version History

  You can see the list of versions of a file by clicking on it (or on the project) in the file browser, and pressing (-I (Inspector). Then click on the tab marked "SCM".

  From this same window, you can select multiple versions and view their differences, by clicking on the Compare button.

  PREFERENCES: SCM can be turned off and configured by going to menu Project Builder | Preferences, under the CVS Access category.

  ---

  I recommend using NSLog.DebugLevelDetailed only .in a production environment, and NSLog.DebugLevelInformational in a development environment.

  Setting Logging From the Command-Line

  Having the logging settings hardcoded in the source code may not be ideal. If you want to change the settings, you have to rebuild the application. The logging level and groups can also be set from a parameter of WebObjects applications. The logging level can be set using the parameter "DNSDebugLevel", and the logging groups using "DNSDebugGroups". The value of these parameters is the same as the value of the NSLog constants:

  Logging level: 0 (disables), 1, 2, 3 (all messages),
  Logging groups: an integer value obtained by adding the values of the wanted groups. For example, if 
  you want to use NSLog.DebugGroupSQLGeneration (bit number 17) and NSLog.DebugGroupDatabaseAccess (bit 
  number 16), you will specify 216 + 217 = 196608.
  

  But where do you specify this? You have two choices: in the Project Builder (when running interactively), and in your own script (when running in the background).

  In the Project Builder, simply go to the main target's settings, under the category Executable and then Arguments. Add these two arguments:

  DNSDebugLeve=2
  NDSDebugGroups=196608
  

  If you're using a shell script, then you must add these two arguments in it. Say your application's name is "Logging-Example-a2", then locate the place where your application is executed, and add them. Here's an example:

  cd ~/ Logging-Example-a2/build/Logging-Example-a2.woa
  ./Logging-Example-a2 -DNSDebugLevel=2 -DNSDebugGroups=196608
  

  Don't forget though that changing the level or groups programmatically of will override these settings.

  ---

  Emmanuel Proulx is a Course Writer, Author and Web Developer, working in the domain of Java Application Servers. He can be reached at emmanuelp@theglobe.com.