Cut down on logging errors with Jylog

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.

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

JDI is a high-level Java API that provides useful information for debuggers and similar systems needing access to a local or remote VM’s running state. JDI provides access to a running VM’s state, classes, arrays, interfaces, primitive types, and instances of those types. It supports suspending and resuming threads, as well as setting breakpoints, watchpoints, exception notifications, class loading, thread creation, and more. Using this API, the debugger can also access the state of suspended threads, local variables, instance variables, and so on.

JDI consists of four packages:

• com.sun.jdi: This core JDI package defines interfaces for mirrors (see below) of values, types, and the target VM. It also contains classes for bootstrapping.
• com.sun.jdi.connect: Defines interfaces for connecting the debugger and the target VM.
• com.sun.jdi.event: Defines interfaces for JDI events that the debugged JVM generates.
• com.sun.jdi.request: Interfaces in this package configure and set event requests in the debugged JVM.

JDI also uses mirrors, which give an object-oriented representation of a logical entity on the debugged JVM. For example, the VirtualMachine class mirrors the actual VM running on a local or remote machine. Similarly, JDI contains mirrors for threads, methods, fields, local variables, and data types like char, float, and so on. Debuggers use mirror classes to inspect the debugged JVM.

The debugged JVM generates JDI events for requests set by the debugger, and places them on the event queue. An event is always a member of an event set, which is retrieved from the event queue. Event examples include breakpoint events, thread creation events, termination events, and virtual machine death events. With the exception of termination events, the debugger must request the events by setting event requests. (The debugged JVM generates the termination events automatically, so no request is needed.)

In the following sections, I will discuss in detail how you can use JDI to build a complete debugger.

Initiate the debug process

JDI is largely composed of interfaces, except for the Bootstrap class and the exception classes. The only class the debugger creates is com.sun.jdi.Bootstrap, which provides the VirtualMachineManager interface. After getting VirtualMachineManager, the debugger works with JDI interfaces only.

JDI contains interfaces for the three previously mentioned modes in the com.sun.jdi.connect package: AttachingConnector, LaunchingConnector, and ListeningConnector. The debugger connects to the debugged JVM using one of these connector classes. Once a successful connection is established, the debugger gets a reference to the VirtualMachine object.

Set event requests in the target JVM

A JVM only has one event request manager to set all event requests. Using VirtualMachine.getEventRequestManager(), the debugger gets the event request manager. For example, the debugger can set the method entry request as follows:

MethodEntryRequest methodEntryRequest =
EventRequestManager.createMethodEntryequest();
     methodEntryRequest.addClassFilter("com.test.MyTestClass");
// if some method of MyTestClass is to be logged
// or methodEntryRequest.addClassFilter("com.test.*");
// and
methodEntryRequest.addClassExclusionFilter("com.test.MyTestClass");
if all other classes except MyTestClass are to be logged.
     methodEntryRequest.enable();
// must call enable to activate this request in the debugged JVM

Capture JVM-generated events

The debugged JVM generates events and organizes them into event sets. The debugged JVM then places event sets on an event queue. The debugger gets the reference to the event queue using the VirtualMachine.eventQueue() object. A thread should call remove() on the event queue to get the EventSet objects generated at a particular point in the code. Finally, the debugger retrieves the events from the event set object using EventSet.eventIterator().

Whenever it receives an event, the debugger can suspend the execution of the debugged JVM or the JVM’s current running thread. This happens at a breakpoint in the debugger. In a suspended state, the debugger can inspect the JVM method stacks for variable values using a watchpoint.

Jylog limitations

Since Jylog is entirely based on JPDA, the debugged program’s execution is slower than normal; this makes Jylog only usable in debugging environments. If the program generates logs necessary for production releases — for example, many enterprise applications need such logs to track certain activity — I recommend using the Java Logging API. Note that, in those cases, logging requirements are not as dynamic as this approach and are not just for debugging. Moreover, in those cases, what is to be logged is usually predefined.

Jylog’s many hats

Jylog can greatly assist in other development areas, such as unit testing and reverse engineering.

Unit testing

Unit testing basically covers various execution paths and checks variable values or expressions at certain points in code. Jylog generates the selective execution trace on a per-thread basis, which makes Jylog successful in unit testing.

At test points in code, you can set logpoints for variables or expressions. This eliminates the need to write separate test scripts. The log configuration in this case acts as a test script. As the log configuration and the logs generated are both in XML, you can convert them into a presentable form. You can easily design XSL (Extensible Stylesheet Language) stylesheets to present test results in a common format.

Reverse engineering

To understand and enhance an existing piece of code, you must understand the flow of control for some functionality. In general, reverse engineering tools that work with source code cannot find how the control flows among the desired classes for a particular functionality. This functionality could be a simple method call or a call sequence with different inputs — for example, a program response to a command sequence.

Jylog can be effective in this case. You can mark classes or methods of interest and the program will execute the desired functionality. The behavior of the marked classes is logged in XML, using stylesheets for display. In the previous example — a program responding to a command sequence — Jylog can tell which classes and methods are involved in servicing a particular command.

Jylog in IDEs

Ideally, Jylog would be integrated with some Java IDE, where you can set breakpoints, watchpoints, and logpoints simultaneously, and then operate upon them with equal ease. Logging, unit testing, and reverse engineering could come in handy if Jylog merges with an IDE.

Jylog saves you time

Jylog provides a new approach toward the logging problem. In this article, I showed how you could use Jylog as an effective logging system. You learned about its architecture and the architecture of its underlying technology, JPDA.

Jylog separates logging from coding completely, allowing you to concentrate on core logic rather than abundant log statements. This saves valuable development time while increasing productivity; it also provides more flexibility and ease of use. Jylog is not only a logging tool; you can potentially use it for unit testing and reverse engineering as well.