Cut down on logging errors with Jylog

Separate logging from coding for error-free and flexible event logging

With the addition of the Logging API in Sun's JDK 1.4 (Merlin) beta release, the importance of logging is evident. Logging helps you find code failure points and helps you trace variable values at various locations in your code.

The current approach to logging is to write log statements at important points in your code; those statements essentially invoke some logging library to format the log data. However, this approach is prone to common programming errors resulting from overlooked or misused log statements. So, instead of aiding in debugging, the logging code itself needs debugging. In addition, log statements provide a static log generating system in which you cannot add a new log statement without modifying the source.

Assume that, after writing an algorithm, you need to observe some variable's value at certain code points. One solution uses a debugger and sets breakpoints, and then sets watches (when debugging halts the execution, values of selected variables display in a watch window) at those points. This technique slows the process; every time the breakpoint is hit, you must check the current values and press a button to resume execution. If the code executes a few hundred times, debugging becomes a programmer's nightmare, especially with a multithreaded program.

What is Jylog?

Jylog, an open source logging tool I built with the Java Platform Debugger Architecture (JPDA) SDK 1.3, generates logs for Java programs at runtime. It completely separates the task of logging from coding, eliminating logging errors in your code. You can configure whatever you need logged in Jylog's Swing-based GUI. You can also store this information in an XML file for reuse.

Jylog uses the log configuration to suspend the program execution at certain times and extracts the necessary information (such as method entry and exit, local variables, instance variables, or method parameters) from the JVM at runtime. Since it extracts the information from JVM stacks, that information is guaranteed to be complete and correct. With this information, Jylog prepares a thread-aware XML log tree in which the execution's thread trace is logged separately.

Here is a summary of Jylog's main features:

  • Does not modify the application source or binaries.
  • Works with JVM, KVM, and applets.
  • Extracts logs from the JVM at runtime.
  • Logs all necessary information, like timestamp, thread ID, code line, class name, and method name.
  • Logs values of any local variable, instance variable, or any custom message at any code line.
  • Logs all caught and uncaught exceptions automatically.
  • Fully supports multithreading. Logs all threads separately along XML log tree branches.
  • Is location independent; the debugged JVM can be local or remote.

Plus:

  • You can view logs as Jylog consoles generate them, instead of after the program executes.
  • A program can have multiple log configurations, in XML file format, which you can generate using the Jylog GUI. During an execution, you can select any configuration.

In a future release, Jylog's design will let you incorporate conditional logging -- that is, the log will generate at a point only if a specified variable has a certain value or if a specified expression is true. In addition, Jylog will support distributed logging; it will connect to more than one JVM and generate execution logs.

How to use Jylog

Using Jylog is similar to using any popular IDE with debugging support, like JBuilder or Forte. In a debugger, prior to or during program execution, you can set breakpoints and the program will halt at those points. Similarly, in Jylog you can set logpoints at any code line. Using the GUI class or the source code, you can specify what should be logged at a particular logpoint, including local variables, instance variables, or custom message strings. If your source code is unavailable, you can load classes and mark methods for logging method entry with arguments and method exit.

You can load Java classes or source code files in Jylog's GUI, which supports loading more than one class at a time. Using the GUI, you can set logpoints in classes. It also provides menus for loading precreated log configuration files and saving current log configuration files or generated log files.

You can set logpoints in two views. If you only log method entry and exit, then you can load classes in the class view (Jylog uses reflection for this). The class view displays all the loaded classes' fields and methods in a tree; you can select any method and mark it for logging. On the other hand, if you add logpoints on a source line, you can then load the source code in the source view and mark logpoints as you would set breakpoints in an IDE.

After you set the log configuration, you can start the program or the debugged JVM. Jylog configures the JVM to generate events according to the log configuration. As the program executes, Jylog traps the events generated by the debugged JVM and prepares the log tree. You can see the program's input or output on Jylog's built-in virtual console. The generated logs are also reflected on a logging console as the program executes.

Jylog's three consoles include:

  • System console: Displays the current status or any errors occurring in Jylog, such as class not found or system failure errors. This console also displays connection status messages.
  • Logging console: Displays the generated events after proper formatting. Using this console, you can view the logs as they generate rather than view the log file after the program executes.
  • VM virtual console: If you launch the debugged program from inside Jylog, this console controls the program input and output.

Start the log process

You can initiate communication between the debugger and the debugged JVM in three modes:

  • Attaching mode: The target JVM starts and acts as a server for the debugger. Whenever the debugger starts, it attaches to the target JVM and can place event requests in it.
  • Launching mode: The target program is launched from within the debugger; however, a new JVM instance starts and the debugger connects to it.
  • Listening mode: The debugger acts as a server and starts prior to the program. The program starts on a local or remote machine with the server JVM's address in the command line. The target JVM connects to the debugger before executing any program code where the event requests can be set.

Jylog can only connect to the debugged JVM in launching and listening mode. This release does not support attaching mode, as the events captured during the execution might corrupt the generated XML tree; however, you can expect this mode in a future release.

To launch a program from Jylog, first use the Virtual Machine menu to set the main class, using the option "Set the main class." After you set all the logpoints, click Activate VM (which mimics Run in an IDE) on the menu or toolbar.

If you want the debugged VM to execute separately, then click on the Start Listening button after loading a log file or setting the log configuration. Then start the debugged program in debug mode and set Jylog's address and port in the command line. Note that in the listening case, all the classes to be debugged should be in the classpath of the machine on which Jylog is running.

Jylog's sample log

The following sample log was generated for a small sample program. As shown here, the first method, TestClass.a(), is invoked before TestClass.b() is invoked. TestClass.b() calls TestClass.a() a second time, so it is logged in that method's branch only:

<log>
  <uncaught-exceptions />
  <caught-exceptions />
  <thread id="1" name="main">
    <methodEntry className="testing.TestClass" name="a" time="Thu May 10
16:16:56 GMT+05:30 2001" />
    <methodExit className="testing.TestClass" name="a" time="Thu May 10
16:16:56 GMT+05:30 2001" />
    <methodEntry className="testing.TestClass" name="b" time="Thu May 10
16:16:56 GMT+05:30 2001">
        <argument name="c" value="40" />
        <methodEntry className="testing.TestClass" name="a" time="Thu May 10
16:16:57 GMT+05:30 2001" />
        <methodExit className="testing.TestClass" name="a" time="Thu May 10
16:16:57 GMT+05:30 2001" />
     </methodEntry>
    <methodExit className="testing.TestClass" name="b" time="Thu May 10
16:16:57 GMT+05:30 2001" />
  </thread>
</log>

Jylog architecture

The following diagram describes the internal structure of Jylog; I have omitted some details for clarity. As you can see in the diagram, the VM manager is Jylog's controller class; it can connect to the debugged JVM, set events, and read event requests. The info manager contains the log configuration corresponding to the VM manager setting the event requests. Whenever VM manager encounters an event, it selects and invokes an appropriate event handler. Finally, the event handler uses the log manager to log the event. The subsequent list describes these components in detail.

Jylog architecture

Info manager

The info manager manages and caches the log configuration. It initializes upon loading a log configuration file or setting logpoints. It provides the current log configuration to the VM manager and the event filter. Info manager contents serialize to an XML file upon saving.

VM manager

The VM manager connects to the target JVM in various modes, sets event requests, and listens on the event queue with a high priority thread.

Event handlers

All event handlers register with the VM manager for one or more event types. Whenever the VM manager encounters an event on the event queue, it selects and invokes the appropriate event handlers using a priority queue. An event handler decides what action to take on an encountered event. If the event passes through the event filter, the handler can simply log the event, as it might when logging custom messages or suspending the JVM execution to extract values of local/instance variables or method parameters from JVM stacks. After retrieving the desired information, the event handler passes the information to the log manager.

Event filters

One event request can result in the debugged JVM generating many events. For example, if a method entry is to be logged, the VM manager sets the request at the class level. For all that class's method entries, including the constructor, the debugged JVM generates an event. So the events must be filtered and unnecessary events ignored.

Log manager

The log manager contains classes for converting logs into various formats, like XML and plain text. The log manager delegates information that the event handler passes to it to the appropriate logger, which then formats the information and serializes it into a disk file. For a multithreaded program, upon logging a particular event, Jylog automatically determines the thread that generated the event. If a log tree branch does not exist for that thread, Jylog creates a new branch; otherwise, Jylog logs the new event under its thread's branch.

What is JPDA?

JPDA is the debugging support for JDK 1.2.2 and higher. This discussion, however, is limited to JPDA in SDK 1.3. JPDA provides the infrastructure you need to build user debugger applications. The idea behind JPDA is simple: A JPDA-based debugger connects to a JVM executing in debug mode or launches a JVM in debug mode. After a successful connection, the debugger sets event requests in the target JVM.

For example, if Jylog is to log a method entry, the debugger sets the method entry request for the class that contains the method. The debugged JVM generates an event whenever any method of the class is entered. Similarly, the debugger requests events for method exit, breakpoint, watchpoint, classload, and so forth. The debugged JVM generates events and puts them on an event queue. The debugger JVM reads and clears this event queue using a high-priority thread. The debugger can also suspend the debugged JVM's execution and extract the values in various method stacks or even thread-specific information.

JPDA internals

JPDA consists of three interfaces designed for debuggers to use in development environments: the Java Virtual Machine Debugger Interface (JVMDI), the Java Debug Wire Protocol (JDWP), and the Java Debug Interface (JDI). This section explains them in moderate detail.

Java Virtual Machine Debugger Interface

A VM implements JVMDI, a native interface that defines the services that a VM must support for debugging.

JVMDI supports:

  • Requests for runtime information, like JVM stacks
  • Actions taken on the debugged JVM by the debugger JVM, such as setting breakpoints in the JVM, which suspends execution whenever the breakpoint is hit
  • Notification service; i.e., when any breakpoint is hit, it notifies the debugger

JVMDI provides a common interface for debugging support; any VM that implements this interface can automatically work with any JPDA-compatible debugger.

Java Debug Wire Protocol

JDWP is an alternate way to support debugging. If a JVM does not implement a JVMDI interface, it can still support JDWP. JDWP defines the format of information and requests between the debugged JVM and debugger JVM. It is independent of any transport mechanisms like sockets, shared memory, and so on. JDWP lets you write the debugger on a different platform or in a different language.

Java Debug Interface

1 2 Page 1