I suggest you read this blog with Firefox 3.0 or later. There appear to be problems with the line numbering of code samples when using Internet Explorer.

Sunday, January 24, 2010

Logical Exclusion as a Debugging Tool

I want to revisit and expand upon a point that I made in the previous article. When you are debugging code that you don't understand, it is often helpful to eliminate things that are logical impossibilities. Look at the following code:


package nodebugger;

public class Logical {
public static void main(String[] args) {
String x = "ABCDEF";
int index = 5;
index = one(index);
index = two(index);
char a = getAChar(x, index);
System.out.println("a = " + a);
}

private static int one(int i) {
int rv = i * 2;
rv = rv + 3;
rv = rv / 4;
return rv;
}

private static int two(int i) {
if (i < 0) return i;
return i - 6;
}

private static char getAChar(String x, int i) {
if (i >= x.length()) {
i = x.length() - 1;
}
if (i % 3 == 0) {
return x.charAt(i);
}
return x.charAt(-i);
}
}

When this code runs, you get the following exception:


Exception in thread "main" java.lang.StringIndexOutOfBoundsException
at java.lang.String.charAt(String.java:418)
at nodebugger.Logical.getAChar(Logical.java:30)
at nodebugger.Logical.main(Logical.java:9)

This is admittedly silly code, but I use it to make a point about logical impossibilities.

Eliminating the Impossible

First of all, we are failing with a StringIndexOutOfBoundsException. As in the previous article, we find that this means an index was either negative or else it was greater than or equal to the length of the String. When we first glance at the "getAChar" method, we see something suspicious on line 32:

    return x.charAt(-i);

However, the exception shows that we were at line 30 in this method. Since the method contains no loops (or any other construct that could cause execution to move backwards), we know that we must not have gotten to line 32.


Understanding Boundaries for Variable Values

So, let's look at the line in our code that is part of the failure.


      return x.charAt(i);

Thus, "i" must either be negative, or else it is greater than or equal to the length of the String "x". So, let's look at how "i" gets here:


  private static char getAChar(String x, int i) {
if (i >= x.length()) {
i = x.length() - 1;
}
if (i % 3 == 0) {
return x.charAt(i);
}

The variable "i" is a parameter to this method. However, look at what happens on lines 26 and 27. If "i" is greater than or equal to the length of the String "x", then it gets set to the position of the last character in the String. Nothing else happens to "i" before it is used on line 30, so clearly, "i" is not too big - it is bounded by the length of the String. Therefore, it must have been negative.


How Did We Get This Value?

The "i" parameter must be negative, but how could it have been? Well, let's look at all the places that that parameter is set in the calling method:


    int index = 5;
index = one(index);
index = two(index);
char a = getAChar(x, index);

The parameter "i" comes from variable "index" in the main routine. The initialization on line 6 sets "index" to a positive number, so that clearly isn't the immediate problem. Then we see that it is the target of assignments on lines 7 and 8, where it passes the "index" variable as a parameter, then the same variable receives the return values from routines "one" and "two". So, let's look at those routines.

Method "one" looks like this:


  private static int one(int i) {
int rv = i * 2;
rv = rv + 3;
rv = rv / 4;
return rv;
}

This routine looks like it is doing some complicated things to the return value, but look at them in order. Line 14 takes the initial parameter (which is the "index" variable from the main method) and multiplies it by two. Line 15 adds to it, and line 15 divides it. Notice, however, that there is no place where we could possibly introduce a negative value unless we started with one. There is no subtraction, no adding of negative values, no complementing (e.g. making negative). Therefore, this routine can not be the source of a negative number.


Finishing Up Debugging

Method "two" looks like this:

  private static int two(int i) {
if (i < 0) return i;
return i - 6;
}

Notice that line 21 could return a negative value, but only if the value was already negative. We have proven that this could not be the case, so we skip past that line. On line 22, though, we see that there is a subtraction. This could give us a negative value. Since this is the last change to the value before it gets passed to the "getAChar" method, this must be the line that made it negative - there is no other place where it could have happened.


Conclusion - Logical Impossibilities Are Your Friends

The point of this silly example is that, when a variable has an unexpected value, it is important to understand the possible range of values for that variable. Working back from the statement where things went wrong, you can use each statement in the program to put boundaries on the value. In this case, we started with a value that was either negative ot too big for a String, then proved that it must have been negative. We used that to eliminate an entire method from consideration, and eventually got to the specific line where the bad value was introduced. Note that this did not necessarily identify the actual bug - all it did is help us to understand how we could have gotten to the point of failure. However, once we have identified how we got the bad value, we now can look at the code that leads up to that point and figure out whether one part of the code made invalid assumptions about how other parts worked (which is usually the cause of bugs when dealing with larger programs).

Sunday, January 3, 2010

Debugging Without A Debugger: IndexOutOfBoundsException

The technique of putting yourself in the position of the computer is very valuable when you do not have the luxury of using a debugger to debug a problem. However, it is rare to be able to debug your problems in this way without the benefit of logging. Logging, in combination with logical thinking, can help to make this type of debugging much easier.

Here is another example with a different type of exception that shows how valuable logging is when debugging these types of problems.


package nodebugger;

import java.util.ArrayList;
import java.util.List;

public class DebugExample2 {
private static final String JIM = "Jim";
private static final String JAVA = "Java";

public String removeComment(String line) {
if (line.charAt(0) != '*') {
return line;
}
// Return empty line
return "";
}

private static String addHighlight(String line,
String str,
String hilite) {
final int pos = line.indexOf(str);
String newLine = line.substring(0, pos);
newLine += "<" + hilite + ">" + str +
"</" + hilite + ">";
newLine += line.substring(pos + str.length());
return newLine;
}

public static void main(String[] args) {
DebugExample2 de = new DebugExample2();
List<String> newLines = new ArrayList<String>();
// Simplification - imagine that these lines
// are being read from a file.
for (String line : DebugExample.LINES) {
String newLine = line;
//
if (line.contains(JIM)) {
newLine = addHighlight(line, JIM, "B");
}
else if (line.contains(JAVA)) {
newLine = addHighlight(line, JAVA, "I");
}
else if (line.startsWith("*")) {
newLine = "";
}
newLines.add(de.removeComment(newLine));
}
System.out.println("newLines = " + newLines);
}
}


The above example is highly simplified in order to focus on the key concepts that are interesting for debugging purposes. We have a main method that obtains a list of lines from an external source and then makes changes to those lines depending on the content. On line 18, you see a general purpose method that searches for a string in a line, and if it finds that string, it applies the specified HTML highlighting to it. At line 37, you see that if the line contains the string, "Jim", then it will highlight that string in bold. Similarly, on line 40, is the line contains the string, "Java", then it will highlight that string in italics. Finally, if the line starts with an asterisk, then it treats it as a comment and sets up to ignore it.

When you run the above program, you get the following exception:
Exception in thread "main"
java.lang.StringIndexOutOfBoundsException
at java.lang.String.charAt(String.java:418)
at
nodebugger.DebugExample2.removeComment(DebugExample2.java:11)
at nodebugger.DebugExample2.main(DebugExample2.java:46)


When you look at the exception, the first line of the stack trace is from the java.lang.String class. In virtually every situation, we can assume that there aren't any bugs in any code that comes from Java itself. So, we move down to the next line and we see line 11 of our source file.


if (line.charAt(0) != '*') {


We consult the API documentation for the String class and find the following:

IndexOutOfBoundsException - if the index argument is negative or not less than the length of this string.

Since the index is a constant, it clearly cannot be negative, so it must not be less than the length of the string. Since the index is zero, the string must be of length zero, in other words an empty string.

How Did We Get Here?

So, we know that we must have had an empty string in order to have taken this exception. A naïve approach to solving this problem would be to go into the code at line 11 and change it to handle empty strings. However, when you are working with complex software, the naïve approach is usually the wrong approach. It may be the case that this method never should be called with an empty string, in which case the problem would not be at line 11. So, let's look at the next line in the stack trace:


for (String line : DebugExample.LINES) {
String newLine = line;
//
if (line.contains(JIM)) {
newLine = addHighlight(line, JIM, "B");
}
else if (line.contains(JAVA)) {
newLine = addHighlight(line, JAVA, "I");
}
else if (line.startsWith("*")) {
newLine = "";
}
newLines.add(de.removeComment(newLine));
}


The problem occurred at line 46, and sure enough, we see a call to the removeComment method on that line. The variable newLine, then, must be an empty string for us to have received this exception. But how could we have gotten to this point? If you look at the code closely, you'll see that there are two possibilities: either the incoming line was empty, or the incoming line began with an asterisk. But how do we know this?

Pretending to Be the Computer, a.k.a. Using Logic

On line 35, we see the declaration for the variable newLine. Since it is inside the for loop that begins on line 34, the scope of a variable is limited to the for loop. Therefore, we know that we only have to look at the lines within this for loop to determine what may be happening. In other words, we only care about lines 35 to 46 inclusive. So, let's examine all the places where this variable is modified to see where it is possible for us to get an empty string.

First of all, on line 35 itself, the variable is set to the current element in our list of lines. This happens unconditionally, so the value of the current element is a consideration.

Next, on line 38, we see that it is set to the result of the addHighlight method. The parameters to this method are the original line, the string, "Jim", and the string "B." So, let's examine that method on line 18.

This method appears somewhat complicated. There seems to be many possibilities where things may go wrong depending upon the parameters that are passed to this method. However, remember that we are not required to fully understand what this method does in order to debug this particular problem. We only care about situations where we will end up with an empty string in the calling method, which means that we only care about situations where this method can return an empty string.

So, working backwards, we see that the variable newLine is returned on line 26. We see this variable as the target of assignment statements on lines 22, 23, and 25. Notice, however, that after it is initially set on line 22, the following two assignments are "+=" assignments. Therefore, they are concatenations to the existing value. Specifically, on line 23, notice that several constants are being concatenated to the variable. Regardless of whatever else this routine may be doing, it is clear from this line that there is no way that this routine could ever return an empty string. In the worst possible case, the returned string would still contain at least four characters: "<><>". Since we only care about situations where we can get an empty string, this routine clearly cannot have been called in the path that leads to this particular exception. Therefore, this tells us that line 38 could not have been run when we received this exception.

Similarly, since line 41 calls the same method, it also cannot have been run in the path that leads to this exception.

The last-place where the newLine variable appears on the left side of an assignment statement is online 44. Here, we see that it is, in fact, being set to an empty string. Well, that certainly looks suspicious. We see, however, that line 44 is protected by the if statement online 43, which checks whether the original line starts with an asterisk. To be thorough, note that this test is the else clause for the previous tests on line 37 and 40. So, we know that the only way we could have gotten to line 44 is if the original line did not contain the string, "Jim", did not contain the string, "Java", but did start with an asterisk.

The End of Our Analysis

Our analysis has shown that there are two possibilities that could have led to this exception: either the original line was empty, or the original line started with an asterisk. But which is it? There is simply no way to tell without actually getting access to the system, making changes to the code, and then rerunning this test.

Performing Further Debugging

Of course, if this class was a part of an enterprise software product that was installed on a customer production system, it would be extremely difficult to make a change to the class, then send that change the customer and ask them to simply try it out. It would be much better to have built the class with the necessary pieces for doing this additional debugging without having to ask the customer to install patches. In a subsequent article, I will discuss techniques for doing this in a way that does not impact the customer normally. For now, though, simply note that if it were possible to see the contents of the newLine variable at line 36, then we would be able to determine exactly which path we were taking that led to this problem.

Simple Logging

The easiest thing to do would be to add a logging statement to line 36 that would log the contents of the newLine variable. So, let's change line 36 to the following:

System.out.println("newLine = " + newLine);


Running with Simple Logging

When we run the new code, we see the following:

newLine = * Comment 1
Exception in thread "main"
java.lang.StringIndexOutOfBoundsException
at java.lang.String.charAt(String.java:418)
at
nodebugger.DebugExample2.removeComment(DebugExample2.java:11)
at nodebugger.DebugExample2.main(DebugExample2.java:46)


This shows us that, in fact, the problem is we received a line that starts with an asterisk. We need to change the code to deal properly with these types of lines, or else we need to change other aspects of the system to ensure that we would never get such a line in the first place.

Conclusion

When trying to debug a problem without the benefit of a debugger, the task can at first appear quite daunting. However, with a little logic, you can often make great simplifying assumptions that will remove entire complex branches of code from consideration. The judicious use of logging statements can further augment the use of logic to make debugging much simpler.