What is a good way to pass useful state information to an exception in Java?

Question

I noticed some confusion initially with my question. I'm not asking about how to configure a logger nor how to use a logger properly, but rather how to capture all of the information that would have been logged at a lower logging level than what the current logging level is in the exception message.

I have been noticing two patterns in Java for logging information that may be useful to a developer when an exception occurs.

The following pattern seems very common. Basically, you just have your logger log information in-line as needed, so that when an exception occurs you have the log trace.

try {
    String myValue = someObject.getValue();
    logger.debug("Value: {}", myValue);
    doSomething(myValue);
}
catch (BadThingsHappenException bthe) {
    // consider this a RuntimeException wrapper class
    throw new UnhandledException(bthe);
}

The drawback with the above approach is that if your users require relatively quiet logs and need a high level of reliability to the point where they just can't "try it again in debug mode", the exception message contains insufficient data by itself to be useful to the developer.

The next pattern is one that I have seen that tries to mitigate this problem but seems ugly:

String myValue = null;
try {
    myValue = someObject.getValue();
    doSomething(myValue);
}
catch (BadThingsHappenException bthe) {
    String pattern = "An error occurred when setting value. [value={}]";
    // note that the format method below doesn't barf on nulls
    String detail = MessageFormatter.format(pattern, myValue);
    // consider this a RuntimeException wrapper class
    throw new UnhandledException(detail, bthe);
}

The above pattern seems to somewhat solve the problem, however I'm not sure I like to declare so many variables outside the scope of the the try block. Especially, when I have to deal with very complicated states.

The only other approach I have seen is using a Map to store key value pairs that are then dumped into the exception message. I'm not sure I like that approach either since it seems to create code bloat.

Is there some Java vodoo out there that I am missing? How do you handle your exception state information?

Answer 1

Another good logging API is SLF4J. It can be configured to also intercept log APIs for Log4J, Java Util Logging, and Jakarta Commons Logging. And it can also be configured to use various logging implementations, including Log4J, Logback, Java Util Logging, and one or two others. This gives it enormous flexibility. It was developed by the author of Log4J to be its successor.

Of relevance to this question, the SLF4J API has a mechanism to concatenate string valued expressions into a log message. The following calls are equivalent, but the second is about 30x faster to process if you're not outputting debug level messages, since the concatenation is avoided:

logger.debug("The new entry is " + entry + ".");
logger.debug("The new entry is {}.", entry);

There's a two argument version too:

logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry);

And for more than two you can pass in an array of Object like this:

logger.debug("Value {} was inserted between {} and {}.", 
             new Object[] {newVal, below, above});

This is a nice terse format that eliminates clutter.

Example source is from the SLF4J FAQ.

Edit: Here's a possible refactoring of your example:

try {
    doSomething(someObject.getValue());
}
catch (BadThingsHappenException bthe) {
  throw new UnhandledException(
    MessageFormatter.format("An error occurred when setting value. [value={}]", 
                              someObject.getValue()), 
    bthe);
}

Or if this pattern occurs more than a few places you could write a set of static methods that capture the commonality, something like:

try {
    doSomething(someObject.getValue());
}
catch (BadThingsHappenException bthe) {
    throwFormattedException(logger, bthe,
                            "An error occurred when setting value. [value={}]", 
                            someObject.getValue()));
}

and of course the method would also put the formatted message out on the logger for you.

Answer 2

We tend to create our most important application specific runtime exception classes with some special constructors, some constants and a ResourceBundle.

Example snippet:

 public class MyException extends RuntimeException
 {
    private static final long serialVersionUID = 5224152764776895846L;

    private static final ResourceBundle MESSAGES;
    static
    {
     MESSAGES = ResourceBundle.getBundle("....MyExceptionMessages");
    }

    public static final String NO_CODE = "unknown";
    public static final String PROBLEMCODEONE = "problemCodeOne";
    public static final String PROBLEMCODETWO = "problemCodeTwo";
    // ... some more self-descriptive problem code constants

    private String errorCode = NO_CODE;
    private Object[] parameters = null;

    // Define some constructors

    public MyException(String errorCode)
    {
     super();
     this.errorCode = errorCode;
    }

    public MyException(String errorCode, Object[] parameters) 
    {
     this.errorCode = errorCode;
     this.parameters = parameters;
    }

    public MyException(String errorCode, Throwable cause)
    {
     super(cause);
     this.errorCode = errorCode;
    }

    public MyException(String errorCode, Object[] parameters, Throwable cause)
    {
     super(cause);
     this.errorCode = errorCode;
     this.parameters = parameters;
    } 

    @Override
    public String getLocalizedMessage()
    {
     if (NO_CODE.equals(errorCode))
     {
      return super.getLocalizedMessage();
     }

     String msg = MESSAGES.getString(errorCode); 
     if(parameters == null)
     {
      return msg;
     }
     return MessageFormat.format(msg, parameters);
    }
 }

In the properties file we specify the exception descriptions, e.g.:

 problemCodeOne=Simple exception message
 problemCodeTwo=Parameterized exception message for {0} value

Using this approach

• We can use quite readable and understandable throw clauses (throw new MyException(MyException.PROBLEMCODETWO, new Object[] {parameter}, bthe))
• The exception messages are "centralized", can easily maintained and "internationalized"

EDIT: change getMessage to getLocalizedMessage as Elijah suggested.

EDIT2: Forgot to mention: this approach does not support Locale changing "on-the-fly" but it is intentional (it can be implemented if you need it).

Answer 3

Besides your example which declares local fields outside the try block in order to be accessible inside the catch block, one very simple way of handling this is to dump the state of the class out in the Exception using the class's overridden toString method. Granted, this is only useful in Classes that maintain state.

try {
   setMyValue(someObject.getValue());
   doSomething(getMyValue());
}
catch (BadThingsHappenException bthe) {
   // consider this a RuntimeException wrapper class
  throw new UnhandledException(toString(), bthe);
}

Your toString() would need to be overridden:

public String toString() {
   return super.toString() + "[myValue: " + getMyValue() +"]";
}

edit:

another idea:

You could maintain state in a ThreadLocal debug context. Suppose you create a class called MyDebugUtils which holds a ThreadLocal that contains a Map per Thread. You allow for static access to this ThreadLocal and maintenance methods (ie, to clear the context when your debugging is finished).

The interface could be:

public static void setValue(Object key, Object value)
public static void clearContext()
public static String getContextString()

and in our example:

try {
   MyDebugUtils.setValue("someObeject.value", someObject.getValue());
   doSomething(someObject.getValue());
} catch (BadThingsHappenException bthe) {
   // consider this a RuntimeException wrapper class
  throw new UnhandledException(MyDebugUtils.getContextString(), bthe);
} finally {
  MyDebugUtils.clearContext(); 
}

There might be some issues that you would want to iron out, such as handling cases where your doSomething method also contains a try/catch/finally set that clears the debug context. This could be handled by allowing for finer granularity in the context Map than just the Thread in the process:

public static void setValue(Object contextID, Object key, Object value)
public static void clearContext(Object contextID)
public static String getContextString(Object contextID)

Answer 4

I have created a key combintation in eclipse for a catch block creation.

logmsg as key and the result will be

catch(SomeException se){
   String msg = ""; //$NON-NLS-1$
   Object[] args = new Object[]{};

   throw new SomeException(Message.format(msg, args), se);
}

You can put as many informations as you want in the Message like:

msg = "Dump:\n varA({0}), varB({1}), varC({2}), varD({3})";
args = new Object[]{varA, varB, varC, varD};

Or some user informations

msg = "Please correct the SMTP client because ({0}) seems to be wrong";
args = new Object[]{ smptClient };

You should think about using log4j as logger, so you can print your states where ever you want. With the options DEBUG, INFO, ERROR you can define how many loggings you want to see in your log file.

When you deliver your application you will set the log level to ERROR, but when you want to debu your application you can use DEBUG as default.

When you are using a logger, you only have to print a hand full of informations in your exceotion, because the state of some variables you would print into the log file, before you are calling the critical try...catch block.

String msg = "Dump:\n varA({0}), varB({1}), varC({2}), varD({3})";
Object[] args = new Object[]{varA, varB, varC, varD};
logger.debug(Message.format(msg, args));

try{

// do action
}catch(ActionException ae){
    msg = "Please correct the SMTP client because ({0}) seems to be wrong";
    args = new Object[]{ smptClient };

    logger.error(Message.format(msg, args), se);
    throw new SomeException(Message.format(msg, args), se);
}

Answer 5

If you want to somehow process the details of the error message, you could:

• Use an XML text as the message, so you get a structured way:

  throw new UnhandledException(String.format(
      "<e><m>Unexpected things</m><value>%s</value></e>", value), bthe);
  

• Use your own (and one for every case) exception types to capture variable information into named properties:

  throw new UnhandledValueException("Unexpected value things", value, bthe);
  

Or else you could include it in the raw message, as suggested by others.

Answer 6

Perhaps I'm missing something, but if the users really require a relatively quiet log file, why don't you just configure your debug logs to go to a separate spot?

If that's insufficient, then capture a fixed amount of the debug logs in RAM. E.g., the last 500 entries. Then, when something ugly happens, dump the debug logs along with the problem report. You don't mention your logging framework, but this would be pretty easy to do in Log4J.

Even better, assuming you have the user's permission, just send an automatic error report rather than logging. I recently helped some folks run down a hard-to-find bug and made the error reporting automatic. We got 50x the number of bug reports, making the problem pretty easy to find.

Answer 7

Take a look at the MemoryHandler class from java.util.logging. It acts as a buffer between your log.$level() invocations and the actual output, and will pass it's buffer content into the output only if some condition is met.

For example you could configure it to dump content only if it sees ERROR level message. Then you can safely output DEBUG level messages and no one will see them unless actual error occurs and then all messages are written to log file.

I would guess there are similar implementations for other logging frameworks.

EDIT: One possible issue with this approach is a performance lost on generating all the debug messages (see @djna comment). Because of this it could be a good idea to make the level of logging going into the buffer configurable - in production it should be INFO or higher, and only if you are actively hunting a problem down it could be turned down to DEBUG.

Answer 8

As for the type of debug information you need, why don't you just always log the value and don't bother so much with a local try/catch. Just use the Log4J config file to point your debug messages to a different log, or use chainsaw so you can remotely follow the log messages. If all that fails maybe you need a new log message type to add to debug()/info()/warn()/error()/fatal() so you have more control over which messages get sent where. This would be the case when defining appenders in the log4j config file is impractical due to the high number of places where this type of debug logging needs to be inserted.

While we're on the subject, you've touched on one of my pet peeves. Constructing a new exception in the catch block is a code smell.

Catch(MyDBException eDB)
{
    throw new UnhandledException("Something bad happened!", eDB);
}

Put the message in the log and then rethrow the exception. Constructing Exceptions is expensive and can easily hide useful debugging information.

First off, inexperienced coders and those who like to cut-n-paste (or begin-mark-bug, end-mark-bug, copy-bug, copy-bug, copy-bug) it can transform easily to this:

Catch(MyDBException eDB)
{
    throw new UnhandledException("Something bad happened!");
}

Now you've lost the original stacktrace. Even in the first case, unless the wrapping Exception handles the wrapped exception properly, you can still lose details of the original exception, the stacktrace being the most likely.

Rethrowing exceptions might be necessary but I've found that it should be handled more generally and as a strategy to communicate between layers, like between your business code and the persistance layer, like so:

Catch(SqlException eDB)
{
    throw new UnhandledAppException("Something bad happened!", eDB);
}

and in this case, the catch block for the UnhandledAppException is much further up the call stack where we can give the user an indication that they either need to retry their action, report a bug, or whatever.

This let our main() code do something like this

catch(UnhandledAppException uae)
{
    \\notify user
    \\log exception
}
catch(Throwable tExcp)
{
    \\for all other unknown failures
    \\log exception

}
finally
{
    \\die gracefully
}

Doing it this way meant that local code could catch the immediate and recoverable exceptions where debug logs could be done and the exception not have to be rethrown. This would be like for DivideByZero or maybe a ParseException of some sort.

As for "throws" clauses, having a layer-based exception strategy meant being able to limit the number of exception types that have to be listed for each method.

Answer 9

Why not keep a local copy/list of all messages that would have gone to the debug log if it was enabled, and pass that to the custom exception when you throw it? Something like:

static void logDebug(String message, List<String> msgs) {
    msgs.add(message);
    log.debug(message);
}

//...

try {

    List<String> debugMsgs = new ArrayList<String>();

    String myValue = someObject.getValue();
    logDebug("Value: " + myValue, debugMsgs);
    doSomething(myValue);

    int x = doSomething2();
    logDebug("doSomething2() returned " + x, debugMsgs);

}
catch (BadThingsHappenException bthe) {
    // at the point when the exception is caught, 
    // debugMsgs contains some or all of the messages 
    // which should have gone to the debug log
    throw new UnhandledException(bthe, debugMsgs);
}

Your exception class can make use of this List parameter when forming getMessage():

public class UnhandledException extends Exception {
    private List<String> debugMessages;

    public UnhandledException(String message, List<String> debugMessages) {
        super(message);
        this.debugMessages = debugMessages;
    }

    @Override
    public String getMessage() {
        //return concatentation of super.getMessage() and debugMessages
    }
}

The usage of this would be tedious - as you'd have to declare the local variable in every single try/catch where you wanted this type of information - but it might be worth it if you have just a few critical sections of code in which you'd like to maintain this state information on an exception.

Answer 10

You answered your own question. If you want to pass the state to the exception, you need to store your state somewhere.

You have mentioned adding extra variables to do this, but didn't like all the extra variables. Someone else mentioned a MemoryHandler as a buffer (holds state) between the logger and the application.

These are all the same idea. Create an object that will hold the state you want you show in your exception. Update that object as your code executes. If an error occurs pass that object into the exception.

Exceptions already do this with StackTraceElements. Each thread keeps a list of the stack trace (method, file, line) which represents its 'state'. When the exception happens, it passes the stack trace to the exception.

What you seem to be wanting, is a copy of all the local variables also.

This would mean making a object to hold all your locals and using that object, instead of the locals directly. Then passing the object to the exception.

Answer 11

One option that no one seems to have mentioned yet is to use a logger that logs to an in memory buffer, and only pushes the information into the actual log target under certain circumstances (e.g., an error level message is logged).

If you're using the JDK 1.4 logging facilities, MemoryHandler does exactly this. I'm not sure if the logging system you're using does this, but I imagine you should be able to implement your own appender/handler/whatever that does something similar.

Also, I just want to point out that in your original example, if your concern is variable scope, you could always define a block to reduce the scope of your variable:

{
    String myValue = null;
    try {
        myValue = someObject.getValue();
        doSomething(myValue);
    }
    catch (BadThingsHappenException bthe) {
        String pattern = "An error occurred when setting value. [value={}]";
        // note that the format method below doesn't barf on nulls
        String detail = MessageFormatter.format(pattern, myValue);
        // consider this a RuntimeException wrapper class
        throw new UnhandledException(detail, bthe);
    }
}