What is a good way to pass useful state informatio

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

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 2

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 3

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 4

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 5

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 6

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.