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).

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.

Debugging Without a Debugger: NullPointerExceptions

We will now begin giving some examples of techniques you can use to debug without actually having access to the system where the problem occurred. This example shows techniques for dealing with a common type of problem: the NullPointerException.

Note that software engineers who have significant experience with diagnosing customer issues may find this posting a bit obvious, but I think it's still a good introduction to the concepts.

Example Code

Here's the example code:

public class DebugExample {
 public String doSomething(String s) {
     return s.replace('l', 'L');
 }

 public static final class C1 {

     private DebugExample _de;

     public DebugExample getDe() {
         return _de;
     }

     public void setDe(final DebugExample de) {
         _de = de;
     }

     public String save(DebugExample de) {
         return de.doSomething("Hello");
     }
 }

 public static final class C2 {
     public String x(C1 c1) {
         return c1.getDe().doSomething(null); /* Line 25 */
     }
 }

 public static void main(String[] args) {
     DebugExample de = new DebugExample();
     de.doSomething("Hello");
     C1 c1 = new C1();
     c1.save(de);
     C2 c2 = new C2();
     System.out.println(c2.x(c1));  /* Line 35 */
 }
}

Scenario

Imagine that you have a customer bug report, saying that when they run the above code, then get the following:

Exception in thread "main" java.lang.NullPointerException
 at DebugExample$C2.x(DebugExample.java:25)
 at DebugExample.main(DebugExample.java:35)

You don't have any other information. So, what do you do?

Become the Computer

The best way to approach NullPointerExceptions (NPEs) is to put yourself in the position of the computer. You want to try to look at the evidence you have, and then use logic to work backwards from the point of the exception to see how you could possibly have gotten to that point with a null variable.

In this case, the exception occurred at line 25. Line 25 looks like this:

return c1.getDe().doSomething(null); /* Line 25 */

So, how could this line produce a NPE? Working from the end of the line, your eye might be drawn to the null being passed to the “doSomething()” method. However, that could not be the problem. If it were, then the NPE would have occurred inside the “doSomething()” method. But it did not – it occurred on the line in the “x()” method. Even if the null could cause a problem (which it definitely would in this case), it was not the cause of this problem.

Causes for NullPointerExceptions

There are only two possible ways that line 25 could cause an NPE: If the “c1” variable was null, or if the “getDe()” method returned a null. Remember that an NPE means that Java tried to use an object reference to call a method on that object, but the object reference was null. So, the last method in any chain of method calls can not be the cause of a NPE that occurs directly on that line.

First Possibility

So, let’s look at those two possible causes. Could the “c1” variable be null? Well, “c1” is a parameter to the method:

public String x(C1 c1) {

There are no intervening lines that make any changes to “c1”, so if it is null, there had to be a null passed in the “x()” method call. So, let’s look at the previous line in the stack traceback. It says that the call to “x()” came from line 35:

C1 c1 = new C1();
c1.save(de);
C2 c2 = new C2();
System.out.println(c2.x(c1));  /* Line 35 */

As you can see, the parameter to the “x()” method is also called “c1”, and it is most definitely not null. The only assignment to it is where it is assigned to “new C1()”. There is no way that a constructor can return a null, so the “c1” variable is not null. Novices might be tempted to look into the “save()” method on the C1 class to see if there is anything that could be null there, but the internal state of the object that “c1” refers to does not matter. Remember, for Java to throw an NPE, the object reference itself must be null – if the reference itself is not null, then an NPE could not be thrown from that line.

Second Possibility

So, this means that the only way we could have gotten a NPE from line 25 is if the “getDe()” method returned a null. We have proven that there is no other way this could have happened. This is a key part of this kind of debugging – you have to not waste time chasing after issues that could not possibly have occurred.

So, let’s look at the “getDe() method:

public DebugExample getDe() {
 return _de;
}

So, “_de” is a member variable (a.k.a. “field”) of the C1 class. Let’s look at its declaration:

private DebugExample _de;

Now we’re getting somewhere. There’s no initializer for this variable, which means that its value starts out as null. So now we should look for assignments to that variable. Scanning the source, we find only one such assignment:

public void setDe(final DebugExample de) {
_de = de;
}

OK, so somebody must call this method before the call to “getDe()” takes place. Scanning the source, though, there are no callers to this method. That, then, is the reason for the NPE – the “getDe()” method is being called without a previous call to “setDe()”.

Aftermath

Finding the problem is the first part – now you need to determine how to fix the problem. After reading the code, you notice that the C1 class has a method called “save()” that takes an instance of a DebugExample object as a parameter. It calls a method on that object, but it does not do anything else with it. From the method name (“save”), you can reasonably guess that the original writer of this code was planning to save the reference to the DebugExample object parameter. After fixing that, you find that the null you originally looked at on line 25 is indeed a problem, and you fix that as well.

Conclusions

The art of debugging is especially challenging when you don’t have access to the system where the failure occurs. It is necessary to become the computer, using logic to look for take the actual symptoms and reverse-engineer what must have been true to cause those symptoms. In doing this kind of work, it is key to not waste time looking at things that you have already proven could not be true.

A Complex Debugging Scenario

Here’s an example of a complex situation that did not involve a customer, but required extensive debugging work.

Background

This was a complex J2EE-based product with several web applications and EARs, plus several JARs that were directly added to the J2EE container (WebSphere Application Server) in order to provide us with some functions that extended the container’s function. This was a new release of the product, under active development. There were many third-party components present in the product, and we did not have access to the source code for most of them. We were using the IBM 1.5 JVM and WebSphere Application Server (WAS) version 6.1.2 (which was also being developed at the same time).

The major difference here relative to the previous scenario was that there were no customers involved. This provided several advantages:

• We had some level of direct access to all the systems involved.
  
• We had the ability to ask for detailed reproduction steps.
  
• We could try out possible solutions within reason
  

The major drawback, though, is that the development team was split between India and the US. This meant that when we wanted further information, we often had to wait a day to get it.

Scenario

The situation first came to light when two system testers in India reported out of memory errors while running tests during development of the previous release of the product. The problem was only reproducible on two systems – it was never seen anywhere else. Also, there was no real pattern that could be discerned so that we could attempt to reproduce the problem anywhere else.

As time went on, since the problem was confined to those two systems and had never been seen anywhere else, it was decided that we could release the product. We did increase the JVM maximum memory recommendations (the –Xmx option) “just in case”, but we never had any customer reports of issues. So, we were ready to chalk it up to “gremlins”.

However, after release, even with the larger memory, the problem continued to be seen by those two testers. As we worked on testing of the new product release, the same problem was still seen by those two testers. Even a month before release, problem was still being seen by them, but it was still never seen on any other systems. Since the problem had gone on so long, we decided to take a serious look in order to prove that it was not a case of “gremlins.”

Reproducing the Problem

The key issue to be addressed, clearly, was reproducing the problem. Every previous attempt had failed, so we knew that if it was a real issue, there must be something on those two systems that was different from all other systems. Several people thought they knew what was necessary to reproduce the problem, but there previous attempts to communicate those steps to others had apparently failed (again, assuming it was a real problem).

So, we asked for *exact* reproduction steps in writing from the testers who saw the problem. Every single step, no matter how minor, was requested. We told them to not leave out anything – even if something seemed obvious to them, they should write it down. Once we had those steps, we were extremely pedantic about making sure that every single step was executed in order to maximize the chances for reproduction. The reproduction steps that were finally delivered took an hour to run through. We needed to uninstall, reinstall, then run many other steps without restarting any servers. This was the first clue that something was different – every one else “knew” that you could start the servers after about half the steps, but these testers were waiting until almost the very end. That was an apparent difference.

Eureka Number 1

Finally, we successfully reproduced the problem on another system. This happened only after executing every single step we were given, even those that should not have had anything to do with the problem. Suddenly, this problem that had been pooh-poohed as “not a real problem,” suddenly was a legitimate issue.

Diagnosing the Problem

Now, we needed to gather data. The stack traces that came with the OutOfMemoryExceptions showed that the problem occurred when the JVM was attempting to load a new class. Every time that problem occurred, the top 15 lines of the stack traceback were the same. Once the problem occurred, WAS itself stopped working for a while. We could not use any WAS features, even including the WAS Integrated Solutions Console. We could do nothing with it. However, after a few minutes, the problem would clear up.

Since this was a memory issue, we used a memory profiling tool to observe overall JVM heap size during problem reproduction. However, we soon ran into a problem: monitoring with the profiler showed that we never got close to running out of heap space. The maximum size allowed was 1GB, but the peak size we ever observed was 600MB. The heap was rapidly oscillating between 300MB and 600MB during active testing, but it never got to be more than 60% of the total JVM size allowed.

Theories?

So the question was, why were we running out of memory when there was plenty available? It could not be a case of memory fragmentation, because there was still 400MB of contiguous space for new allocations. One theory was that JVM memory garbage collection (GC) was getting overloaded by rapid expansion/contraction cycles. However, that didn’t make sense. When the heap is full, the JVM should wait until GC reclaims memory before continuing. It shouldn’t be throwing memory errors.

More Diagnosis

We then decided to turn on a JVM option that enabled verbose garbage collection (WAS provides a checkbox to enable this easily, but it is also available on any JVM with the “–verbosegc” option). This writes data to the JVM console whenever GC ran, giving details on what GC does.

Once we did that, we noticed an odd pattern to the GC output. The GC log showed that many finalizers were being run during each GC run. What’s more, the longer the time between GC runs, the more finalizers were being run. In other words, when there was less activity on the system, CG would run less often, but there would paradoxically be more finalizers run during the fewer GC runs. In one case, 5 minutes between GC runs resulted in over 20000 finalizers being run. This told us that the finalizers were being created on the basis of time, not on the basis of load. But why were there so many finalizers in the first place?

Analysis

The main reason to have a finalizer is to release native resources for objects that are no longer needed, since GC knows nothing about native resources. This includes cleaning up JNI allocations. When GC wants to free up an object that has a finalizer, it instead calls the finalizer, and then leaves the object on the heal for the next GC pass to collect. This sounded good, but we had no JNI code, and we certainly had no finalizers. So, we concocted a new theory – some third party code was running a thread that periodically created finalizers. But which third-party code was it (we had many different packages in our product)?

In any case, it was still unclear why this would cause memory failures. After all, plenty of memory was available. Then, while reading more about how GC worked, we came across a reference to a “non-Java JVM heap.” We read that this heap is used for allocations not directly related to Java objects. For example, JNI allocations, or those for internal JVM maintenance, come from this other heap. The key items for us, though, were these: this heap is not garbage collected, and it is limited in size.

Thus, we now knew how it was possible to run out of memory even though the main JVM heap had plenty of memory remaining. Moreover, since we had so many finalizers running, we knew that someone must be causing these allocations to occur, and the evidence also indicated that they must be occurring in some thread that runs periodically (as opposed to in direct response to input requests to the product).

Eureka Number 2

Now we had a theory, but we still didn’t have a culprit. Each time the system failed, the stack traceback pointed to our own product code, and we knew that we could not be at fault. So, since we at least had a reproduction scenario, we kept repeating tests. Finally, we hit the jackpot. We got a stack traceback that had those same 15 lines being invoked from a thread created by a third party UI framework called Wicket.

Further Analysis

Now we started looking at the Wicket documentation, and noticed that new Wicket “Application” objects could be configured in either “Deployment” or “Development” modes. Since we could get access to the Wicket source, we read it, and found that “Development” mode caused a maintenance thread to look for changes to files that were part of the UI (HTML, Java classes, etc.). By default, this thread would run once per second! That sounded like were looking in the right place. Since we knew that the problem was time-based rather than load-based, we were looking for a thread running on a frequent schedule.

As we looked we found that the Wicket code did not directly create finalizers. However, it did use java.io classes to look at the file system for updated files. It would open and close directories quickly to look at modification dates. As we did further research, we found that when a java.io class opens a file, it drops to native code (JNI), and certain items are allocated in that JNI code. Those items, of course, came from the “non-Java JVM heap.” The java.io class then creates a finalizer to ensure that, when the corresponding Java class is scheduled to be GCed, the native heap items are cleaned up first. Ah ha!

Eureka Number 3

So the final question was, why would development mode be used by our product? So, we looked at our code that created the Wicket application, and found that it looked at a system environment variable to determine whether to run in “Development” or “Deployment” mode. This “feature” had been added when we converted from Tapestry to Wicket by a developer who wanted to do faster development of Wicket pages.

The problem was that this same environment variable used for other purposes, including allowing a re-initialization of our product’s database in case the data got corrupted. These two testers had that environment variable set “just in case” they needed to do this re-initialization. This was one of the steps that everyone had skipped because “it should not have caused the problem.”

We changed the code to always specify “Deployment” mode, regardless of the setting of the environment variable, and the problem went away!

Lessons

The important lessons here were:

• Do not take anything for granted when trying to reproduce a problem. If a problem cannot be easily reproduced, be extremely pedantic about following every step, and take notes on every step that is run.
  
• As a corollary, once again, attention to detail is required. The “gun-slinging” approach to debugging that software engineers learn in school, in this case, led to developers pooh-poohing the bug report. The earlier haphazard attempts to debug the problem led to developers believing that this wasn’t a real problem.
  
• Be aware of the native heap. Watch for finalizers being run by garbage collection – many finalizers is an indication of possible significant usage of the native heap.
  
• Verbose GC is your friend when diagnosing memory problems.
  
• Do not use existing environment variables that control some aspect of your product for other purposes. People will not realize that when the variable is set in a certain way, that other things are happening besides the ones they expect. Use a different variable instead.
  

Conclusions

So far, we have seen that debugging hard problems requires diligence, patience, and persistence. The early emphasis on a “gun slinging” approach to debugging will fail when you are presented with a truly difficult problem. I strongly suggest that every developer gets used to taking extra care when doing their own debugging – that way you won’t revert to early training when pressure is on.

Communication is also a real key when working on a hard problem. This can be especially challenging when a customer is involved. Don’t take anything for granted. Make sure all the people involved in the problem communicate everything they are doing - the smallest detail could end up being significant. As a side benefit, you will find that in many cases, people will appreciate it if you truly listen to them, especially customers.

Finally, always suspect your own code, even when the evidence points to third parties (e.g. the JVM, Wicket, etc.). Look for all the ways that you interact with that component. It may be that someone else made a change that you are unaware of that causes the component to behave unpredictably.