locomotive.org

Chapter VI. Debugging Your Code

Okay, so now you know all about Handlers, GenericHandlers, Steam, and the Locomotive. Based on our examples, you can now probably write your own module for the Locomotive. But we haven't yet covered one last step. After you've written your code, there's a good chance that it may not work the first time. You'll need to figure out which parts of your code you need to fix to make it work. This chapter will give you some tips on how to debug your code within the Locomotive environment.

Using the log() Method for Debugging

When you're programming for the Locomotive, we recommend that you use the logging facility of the Locomotive to print out debugging information. We recommend against using Java's System.out.println() to print information to the output stream, because, often, you will be running the Locomotive as a background process, which does not have access to the standard output stream. We also caution against writing debugging information directly into the output stream which is written back to the web server, because, usually, the only thing that should be written back to the web server is a complete HTML document, which should not be tampered with.

Instead, use the log() method of GenericHandler to write debugging information to the Locomotive server log. This method takes two parameters: 

public void log (int log_level, String log_message)
log_message is whatever information you want to write to the log. log_level is a number which is meant to represent the "seriousness" of the information that you're logging. A log_level of 0 is the highest severity; as the log_level increases, it becomes less and less severe. If you use a log_level higher than the Locomotive configuration variable LOG_LEVEL (from the file loco.conf), then your message will be suppressed from being written to the log. So, a good way to turn on or off debugging statements is to change LOG_LEVEL in loco.conf. For your convenience, we've provided some default log_level values in the GenericHandler class: 
public static final int ERROR = 0;
public static final int WARNING = 1;
public static final int NORMAL = 6;
public static final int DEBUG = 9;
When you are writing debugging information to the log, you might say: 
log (DEBUG, "reached line 312");
So, to turn on debugging, make sure that LOG_LEVEL has a value greater than 9 in the file loco.conf:
LOG_LEVEL 10
And, to turn off debugging, make LOG_LEVEL 9 or less:
LOG_LEVEL 9
Because you can turn debugging on or off so easily, a good strategy when you first write your code is to put debugging statements in key parts of your code, so that you can "follow" your code by looking at the server log. You can even have more than one debugging log_level, if you'd like, so that you always log the important junctures in your code. A good way to follow the log is by using the "tail -f" option of the Unix "tail" command to continuously display the newest additions to the log file. (You can also tail -f the Event Log, too.)

A word of caution: after you have sufficiently tested and debugged your code, it may be wise to completely remove the debugging statements, because, even if they are not written to the log, they still take up resources to execute.

An alternative to removing the debugging statements is to have a static variable in your Handler which specifies whether to write debugging variables or not. You can then say:

if (IS_DEBUGGING) log(...)
You can turn this static variable on or off as a global configuration variable, to be loaded when the Locomotive first starts up. Or, instead of having a static variable, you can have two different versions of the Handler, invoked by two different line entries in the Handler Routing Table; one entry would be the normal Handler, while the other would be the "debugging" version, thus: 
// normal version of the login handler:
login		org.locomotive.loco.base.LoginHandler

// debugging version of the login handler:
login_dbg	org.locomotive.loco.base.LoginHandler
Then, in your LoginHandler code, you can turn on a debugging variable (not a static variable) if the first url token is login_dbg: 
boolean IS_DEBUGGING;

...

if (url_tokens[1].equals("login_dbg"))
{
    IS_DEBUGGING = true;
}

Debugging Using Steam Variables

Another, more interactive way to debug your code in the Locomotive is to put debugging information into Steam variables, so that they will appear conveniently in the Web page itself rather than in the server log. Then, to "turn off" this kind of debugging, you only need to remove the Steam variable(s) you used for debugging from the HTML template. The disadvantage of this technique is that you need to either create a single Steam variable for each debugging statement -- so that you might end up with many Steam variables to manage -- or, you need to create a StringBuffer to capture the output of all the debugging statements, and, finally, put the contents of that StringBuffer into one Steam variable.

Tracking Down Java Exceptions

If you use the handleException() method of GenericHandler, then, sometimes, you or your users may see an error Web page listing an error code, which might look like this: 
There has been a Locomotive Error

Errormsg: There was a Locomotive error, code: login_lue. 
RequestID: 114604
System Tag: LEVERAGE_DEV
InstanceID: sv_one
Date: Jul 09, 1998 11:47 AM
Please mail a copy of this page to our site administrator, ben@leverage.com.
One way of finding out what caused this error is to look for the word "login_lue" in your Java code. As it turns out, this word occurs only in the file LoginHandler.java, line 91: 
handleException (lue, "There was a Locomotive error, code: " +
                 "login_lue.");
And the line that threw the Exception must be line 82: 
user = new User (conn, form_username, false);
This tells us that there may be something wrong with this particular user's data in the database, or with the loco_users table, or with the database itself. Then, we can take action to find out exactly what was wrong. Having a short, unique identifier code such as login_lue thus helps you pinpoint where the errors are occurring in your code.

By the way, the handleException() method of GenericHandler also writes to the Locomotive Server Log file. It uses a log_level of 0, or ERROR. For any given Exception, handleException() will write a "stack trace", which is a list of all the methods that have called each other to reach the specific line in the program where the Exception was thrown. In the previous example of the error Web page, the handleException() method would also write the following stack trace to the server log: 

1998-07-09 11:47:04 PDT REQ(114604) ERROR: There was a Locomotive error, code: login_lue.  java.loco.LoadUserException
    at org.locomotive.module.base.LoginHandler.handleRequest(LoginHandler.java:83)
    at org.locomotive.module.base.BaseHandler.handleRequest(BaseHandler.java:44)
    at org.locomotive.loco.RequestManager.handoff(RequestManager.java:127)
    at org.locomotive.loco.RequestManager.run(RequestManager.java:75)
    at org.locomotive.server.PooledThread.run(PooledThread.java:38)
    at java.lang.Thread.run(Thread.java:490)
From this stack trace, we would know to go to line 83 in the file LoginHandler.java to see what caused this Exception: 
user = new User (conn, form_username, false);
So, the stack trace in the log file is another way to find out exactly which line caused a particular error. Because users might report incomplete information about the error -- for example, they might only say what they were doing, and maybe give an approximate time when the error occurred, instead of sending the entire error Web page -- having a full stack trace in the log file can be very useful to track down a problem that a user has reported.

Note that the word "ERROR" always precedes a stack trace for an Exception in the log file. This word is added by handleException(). At Leverage, we have a convention that whenever serious Exceptions are thrown, we always put the word ERROR at the beginning of the line in the log file. This way, it makes it easy to find all serious errors in the log file. For example, you can use the "grep" command in Unix to search for "ERROR" in the log files. In fact, it's a good habit to periodically scan for lines containing "ERROR" in your log files, to find out what kinds of problems might be happening in your code or in the Locomotive.

Debugging HTML Templates Containing Steam Variables

Here are a few tips about how you can test and debug your HTML templates while you're testing your features.
  1. Turn off caching in your browser. You need to do this in order to make sure that the pages you're receiving from the web server/Locomotive are the latest ones.
  2. Make the Locomotive always reload HTML templates. Normally, the Locomotive does not load the HTML template files every time, but caches them. But when you're testing, you'll want the Locomotive to reload templates every time, by setting the variable LOCO_CHECK_NEW_TEMPLATE_FREQ to the value '1' in the loco.conf file:
    3.     LOCO_CHECK_NEW_TEMPLATE_FREQ             1
    When you run a Locomotive on the live site, you can make this value higher, in order to save time, because you know that the templates won't change very often on the live site. (There is also a way to force the Locomotive to reload all templates once, whether they've changed or not; see The Locomotive Administrators Guide.)
  3. Try displaying an HTML template as a regular HTML document. If a particular HTML template is not displaying correctly, try putting a copy of it in the web server's document root directory and displaying it. This can help you check that your HTML Tags, especially in Tables, are "balanced" and are not the source of the problem.
  4. Balance your brackets [] for Steam commands. If the HTML is correct, and you're having problems with the Steam commands, first check to make sure that all of your brackets, [], are balanced.
  5. Break down complex Steam commands into their parts. If your Steam commands are complex, try copying some smaller components within them outside in order to display their values. In other words, isolate the problem by process of elimination. Remember that every Steam command has a text value if you display it, even the logic commands such as [and/or/not...] (whose values are either "true" or "", the empty string). Here's an example. We'll take out one subclause within the following Steam command:
    6.     [if [and [USERNAME] [= USERS_AGE 21]] 
        [quote Hi, [USERNAME], you're legal!! :^)]]
    You can check whether USERS_AGE = 21 directly by saying [= USERS_AGE 21], which will evaluate to "true" if it is true. Better yet, we can simply find out the value of the USERS_AGE variable by saying [USERS_AGE].
  6. Make sure that the HTML templates are really being displayed. If you're getting a basic "Server Error" directly from the web server, not from any of the Handlers in the Locomotive, chances are that your code failed to display any HTML content, either because of a bug in your code so that it skips displaying any pages, or because the path of your HTML template is incorrect. Check both possibilities, as well as the permissions bits of your HTML template file and the directories which contain it.