Logging as a Debugging Aid

Debugging a problem remotely (for example, when you simply don't have direct access to the system where your program is running) is often difficult. Even the simplest problems can be impossible to understand when all you get is a message like this:

Exception in thread "main" java.lang.StringIndexOutOfBoundsException
Exception in thread "main" java.lang.NullPointerException
 at nodebugger.DebugExample2.findFirst(DebugExample2.java:20)
 at nodebugger.DebugExample2.addHighlight(DebugExample2.java:27)
 at nodebugger.DebugExample2.main(DebugExample2.java:45)

Or worse:

Execution failed


You have to do a lot of thinking, using techniques that I describe earlier, to sort out what might have gone wrong.

Logging to the rescue

However, you can make your job significantly easier by judicious use of logging (i.e. Writing to the console). Here's the example from the previous post, with more logging statements added:

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) {
    System.out.println("Removing comment, line = " + 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 +
      "";
    newLine += line.substring(pos + str.length());
    return newLine;
  }

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

When you run this, you get the following:

newLine = * Comment 1
Line is a comment - skipping
Removing comment
Removing comment, line = 
Exception in thread "main" java.lang.StringIndexOutOfBoundsException: String index out of range: 0
 at java.lang.String.charAt(String.java:686)
 at nodebugger.DebugExample2.removeComment(DebugExample2.java:12)
 at nodebugger.DebugExample2.main(DebugExample2.java:51)

Note how much easier this is. You immediately see that there are two places where you are "removing comment", which immediately leads you to the problem (that comment lines are being removed twice).

Logging is expensive and ugly

This is a great technique when you are in the middle of developing new code, or in any situation where you can reproduce the problem yourself. You can add System.out.println calls wherever you want, reproduce the problem, look at the logs, and figure out where the problem is. However, you then need to remove all those ugly log lines before you give the code to anyone else. This means that if someone else encounters a bug in the same code, you need to get the code back, recreate the problem to ensure you can, add all the logging back in, then recreate the problem again with the logging, fix the problem, verify the fix, then remember to remove all the logging again before you give the code back to your customer.

Even worse, what if you can't reproduce the problem? You would have to get the code, add all this logging, send it to the customer who can reproduce the problem, ask them to install it and recreate the problem, then send you the log output so you can deduce what's happening. Now imagine you have a customer who wants a fix immediately - you will not be popular with this customer if you propose all that.

java.util.logging to the rescue

You can avoid these issues with the use of classes in the java.util.logging package (found at http://java.sun.com/javase/6/docs/api/java/util/logging/package-summary.html). They allow you to keep your logging statements around all the time, but only turn them on when the user wants them turned on.

Now look at this example with modified logging:

package nodebugger;

import java.io.File;
import java.io.FileInputStream;
import java.io.IOException;
import java.util.ArrayList;
import java.util.List;
import java.util.logging.*;

public class DebugExample2 {
  private static final String JIM = "Jim";
  private static final String JAVA = "Java";
  private static final Logger LOG =
    Logger.getLogger("DebugExample2");
  static {
    File file = new File("logging.properties");
    try {
      LogManager.getLogManager()
        .readConfiguration(new FileInputStream(file));
    } catch (IOException e) {
      e.printStackTrace();
    }
    ConsoleHandler consoleHandler =
      new ConsoleHandler();
    consoleHandler.setLevel(Level.FINE);
    LOG.addHandler(consoleHandler);
  }

  public String removeComment(String line) {
    LOG.fine("Removing comment, line = " + 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 +
      "";
    newLine += line.substring(pos + str.length());
    return newLine;
  }

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

There are 7 logging levels:

• SEVERE
  
• WARNING
  
• INFO
  
• CONFIG
  
• FINE
  
• FINER
  
• FINEST
  

The things to note are line 13 (where a java.util.logging.Logger is obtained), the static initializer starting at line 15 (where the logger is configured), and lines like line 30 (where logging is actually performed).

By default, anything logged at INFO level or higher will be written to the console. Any call to logging methods that log at a level lower than that will be ignored by the logger itself. However, the user can change this behavior by editing the logging configuration file. In this case, it is called "logging.properties" and is in the root directory of the application, but you can put it anywhere.

With this, you can now put in "FINE" log calls instead of System.out.println calls. When you are debugging your code initially, you can ensure that your logging configuration is set to FINE level or higher by having this line in your configuration file:

.level=FINE

Then when you run your code yourself, you will see something like the following:

May 31, 2010 6:20:37 PM nodebugger.DebugExample2 main
FINE: newLine = * Comment 1
May 31, 2010 6:20:37 PM nodebugger.DebugExample2 main
FINE: Line is a comment - skipping
May 31, 2010 6:20:37 PM nodebugger.DebugExample2 main
FINE: Removing comment
May 31, 2010 6:20:37 PM nodebugger.DebugExample2 removeComment
FINE: Removing comment, line = 
Exception in thread "main" java.lang.StringIndexOutOfBoundsException: String index out of range: 0
 at java.lang.String.charAt(String.java:686)
 at nodebugger.DebugExample2.removeComment(DebugExample2.java:31)
 at nodebugger.DebugExample2.main(DebugExample2.java:70)

Notice that on lines 1, 3, 5, and 7, the logging has included additional information for you:

• The date and time the line was logged


• The full package and class name where the log entry was written


• The method name in which the log was written

This is followed on the next line by the level at which the log was written, then the actual log line itself.

If, however, the logging configuration is not set to FINE or higher, then this is all you will see:

Exception in thread "main" java.lang.StringIndexOutOfBoundsException: String index out of range: 0
 at java.lang.String.charAt(String.java:686)
 at nodebugger.DebugExample2.removeComment(DebugExample2.java:31)
 at nodebugger.DebugExample2.main(DebugExample2.java:70)

This way, your code still appears professional, but you don't have to give up on the diagnosis abilities logging gives you.

Expensive logging parameters

This is fine for most situations, but what if the code is very sensitive for performance? Imagine a line like the following:

LOG.fine("My " + foo " "has value " + foo.getValue() +
 " and " + bar + " has value " + bar.getValue());

There's a whole lot of concatenation going on here. Also, there are two method calls, which themselves may be quite expensive. All this concatenation and these method calls must take place before the call to the fine() method is made. If that method is going to turn around and throw everything away, you've wasted a lot of time and effort for nothing.

This can be avoided, though, by use of the isLoggable() method. Here's an example where I've modified the previous example code:

    if (LOG.isLoggable(Level.FINE)) {
      LOG.fine("Removing comment, line = " + line);
    }

By using isLoggable(), you only pay the cost of building up the parameter list if the log will actually be written.

A note about J2EE containers

Many J2EE containers (e.g. WebSphere Application Server) configure Java logging for you, and provide users with a simple interface for modifying the logging configuration (instead of forcing users to find and edit a configuration file). If this is the case, then the static initializer that configures the logger is probably not necessary.

Also, note that J2EE containers may even allow dynamic changes to take immediate effect. For this reason, it is not a good idea to cache the logging state at startup - your code should make the calls repeatedly.

Conclusion

Java logging is very useful for debugging. It is a good habit to use this logging instead of System.out.println for debug logging, because you can then leave the logs in place for use later if/when a problem occurs.

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.