How To Make Comprehensible Stack Traces with Decorator Chains

Jan 8, 2012

When catching an exception, it’s often vital to understand the context of the issue by reading the stack trace. However, with third-party code and certain design patterns it’s often hard to comprehend it. Here’s why and what you can do about it in your own code.

To illustrate the point, let’s look at a simple decorator chain:

package com.stackoverflow;

import java.io.*;

public class StackTrace {
    public static void main(String[] args) throws IOException {
        OutputStream out = new MyFilterOutputStream(new MyOutputStream());
        try {
            out.write(0); // throws IOException!
        } finally {
            out.close(); // be a good girl and close streams in a finally-block
        }
    }
}

class MyFilterOutputStream extends FilterOutputStream {
    MyFilterOutputStream(OutputStream out) { super(out); }
}

class MyOutputStream extends OutputStream {
    public void write(int b) throws IOException {
        throw new IOException("Too bad!");
    }
}

This example sets up a MyOutputStream and decorates it with a MyFilterOutputStream. It then calls write(int) on the decorator chain. The call passes through MyFilterOutputStream because this class does not override FilterOutputStream.write(int). Next, MyOutputStream.write(int) is called, which throws an IOException. This exception pops up through FilterOutputStream.write(int) and StackTrace.main(String[]) again back to the JVM, which finally prints its stack trace.

Simple, isn’t it? Now what do you think is the output of this ill-conceived example? Here it is:

Exception in thread main java.io.IOException: Too bad!
        at com.stackoverflow.MyOutputStream.write(StackTrace.java:22)
        at java.io.FilterOutputStream.write(FilterOutputStream.java:77)
        at com.stackoverflow.StackTrace.main(StackTrace.java:9)

Now the interesting part of this stack trace is line 3: Although the decorator chain contains the class MyFilterOutputStream, it isn’t mentioned there or anywhere else. This is because MyFilterOutputStream doesn’t override FilterOutputStream.write(int) and a stack trace never contains runtime type information, i.e. getClass() cannot get called to figure the run time type which runs a stack frame to display.

This can be problematic because the hidden run time type may be actually involved in causing the exception, i.e. the behavior of the run time type in a prior call may have altered the overall state of the application so that an exception gets triggered then. With this simplistic example, it doesn’t really matter because we have all the code in one file, so it’s easy to figure what the runtime type of the components of the decorator chain are. However, in a large application where a complex decorator chain may even get dynamically created, this really hurts.

So what can we do about it? We can’t change the display of the stack trace because (a) it’s printed by the JVM here and more importantly (b) a stack trace simply does not contain run time type information, so it’s impossible to solve this problem there. Instead, we can only change the decorator code so that it overrides the “missing” method like this:

package com.stackoverflow;

import java.io.*;

public class StackTrace {
    public static void main(String[] args) throws IOException {
        OutputStream out = new MyFilterOutputStream(new MyOutputStream());
        try {
            out.write(0); // throws IOException!
        } finally {
            out.close(); // be a good girl and close streams in a finally-block
        }
    }
}

class MyFilterOutputStream extends FilterOutputStream {
    MyFilterOutputStream(OutputStream out) { super(out); }

    public void write(int b) throws IOException {
        // Simply repeating the super implementation will make the stack trace
        // more comprehensible with complex decorator chains.
        out.write(b); // or more general: super.write(b);
    }
}

class MyOutputStream extends OutputStream {
    public void write(int b) throws IOException {
        throw new IOException(Too bad!);
    }
}

With this version, MyFilterOutputStream.write(int) has been introduced solely for the purpose of improving the stack trace. The result is this:

Exception in thread main java.io.IOException: Too bad!
        at com.stackoverflow.MyOutputStream.write(StackTrace.java:28)
        at com.stackoverflow.MyFilterOutputStream.write(StackTrace.java:22)
        at com.stackoverflow.StackTrace.main(StackTrace.java:9)

As you see, MyFilterOutputStream is now displayed in the stack trace. All good now? No, there are a few things to consider:

Only the write(int) method has been overridden. Had the IOException been thrown anywhere else, e.g. in the close() method, this wouldn’t help. So to be useful, each and every method would need to get overridden!
Similar, if MyFilterOutputStream gets subclassed again, the subclass would have to apply the same idiom in order to prevent the same issue again. Because subclassing isn’t useful for most decorator classes anyway, MyFilterOutputStream should be declared final.

So while this idiom may really help in large application, it should be used judiciously. Here’s a simple recipe:

Make sure the decorator class can get declared final or private in order to prevent falling into the same trap by subclassing it again.
Make sure to override each and every method of its superclass. This is only reasonable if the number of methods to override is small, however.

Last but not least, in a final effort to sell this idiom to you, let me show you a real life example: In TrueZIP, the state of the virtual file system is managed by a decorator chain of file system controller objects. Each file system controller object manages a distinct, fine grained aspect of the virtual file system, e.g. locking. Because of this design, some methods of a typical controller don’t need to do anything but delegate the call to the next object in the chain, whereas the exact setup of the controller chain is determined at run time and depends on the type of the virtual file system, e.g. ZIP files. Now if I hadn’t overridden all controller methods, then when I get a stack trace from a user, I’ld be lost with a complex decorator chain.

Now look at the following stack trace:

de.schlichtherle.truezip.crypto.raes.RaesKeyException: de.schlichtherle.truezip.key.KeyPromptingCancelledException: Key prompting has been cancelled!
        at de.schlichtherle.truezip.crypto.raes.param.KeyManagerRaesParameters$Type0.getKeyStrength(KeyManagerRaesParameters.java:127)
        at de.schlichtherle.truezip.crypto.raes.Type0RaesOutputStream.(Type0RaesOutputStream.java:82)
        at de.schlichtherle.truezip.crypto.raes.RaesOutputStream.getInstance(RaesOutputStream.java:81)
        at de.schlichtherle.truezip.fs.archive.zip.raes.ZipRaesDriver.newOutputShop(ZipRaesDriver.java:263)
        at de.schlichtherle.truezip.fs.archive.zip.ZipDriver.newOutputShop0(ZipDriver.java:533)
        at de.schlichtherle.truezip.fs.archive.zip.ZipDriver.newOutputShop(ZipDriver.java:519)
        at de.schlichtherle.truezip.fs.archive.FsDefaultArchiveController.makeOutput(FsDefaultArchiveController.java:228)
        at de.schlichtherle.truezip.fs.archive.FsDefaultArchiveController.mount(FsDefaultArchiveController.java:201)
        at de.schlichtherle.truezip.fs.archive.FsFileSystemArchiveController$ResetFileSystem.autoMount(FsFileSystemArchiveController.java:98)
        at de.schlichtherle.truezip.fs.archive.FsFileSystemArchiveController.autoMount(FsFileSystemArchiveController.java:47)
        at de.schlichtherle.truezip.fs.archive.FsArchiveController.mknod(FsArchiveController.java:379)
        at de.schlichtherle.truezip.fs.archive.FsContextController.mknod(FsContextController.java:218)
        at de.schlichtherle.truezip.fs.FsDecoratingController.mknod(FsDecoratingController.java:140)
        at de.schlichtherle.truezip.fs.FsCachingController.mknod(FsCachingController.java:141)
        at de.schlichtherle.truezip.fs.FsConcurrentController.mknod(FsConcurrentController.java:278)
        at de.schlichtherle.truezip.fs.FsSyncController.mknod(FsSyncController.java:203)
        at de.schlichtherle.truezip.fs.archive.zip.raes.ZipRaesController.mknod(ZipRaesController.java:157)
        at de.schlichtherle.truezip.fs.FsFederatingController.mknod(FsFederatingController.java:283)
        at de.schlichtherle.truezip.file.TFile.createNewFile(TFile.java:2550)
        at de.schlichtherle.truezip.sample.file.app.Nzip.touch(Nzip.java:430)
        at de.schlichtherle.truezip.sample.file.app.Nzip.runChecked(Nzip.java:174)
        at de.schlichtherle.truezip.sample.file.app.Application.work(Application.java:101)
        at de.schlichtherle.truezip.file.TApplication.run(TApplication.java:67)
        at de.schlichtherle.truezip.sample.file.app.Nzip.main(Nzip.java:130)
Caused by: de.schlichtherle.truezip.key.KeyPromptingCancelledException: Key prompting has been cancelled!
        at de.schlichtherle.truezip.key.PromptingKeyProvider$State.getException(PromptingKeyProvider.java:300)
        at de.schlichtherle.truezip.key.PromptingKeyProvider$State$3.retrieveWriteKey(PromptingKeyProvider.java:247)
        at de.schlichtherle.truezip.key.PromptingKeyProvider$State$1.retrieveWriteKey(PromptingKeyProvider.java:184)
        at de.schlichtherle.truezip.key.PromptingKeyProvider.retrieveWriteKey(PromptingKeyProvider.java:84)
        at de.schlichtherle.truezip.key.SafeKeyProvider.getWriteKey(SafeKeyProvider.java:62)
        at de.schlichtherle.truezip.key.SafeKeyProvider.getWriteKey(SafeKeyProvider.java:28)
        at de.schlichtherle.truezip.crypto.raes.param.KeyManagerRaesParameters$Type0.getKeyStrength(KeyManagerRaesParameters.java:125)
        ... 23 more

The controller chain is easily identifiable in the lines 12 to 19. By looking at it, I can figure what file system has been accessed here (the ZipRaesController is unique) and I can tell that the controller chain is complete. Of course, this would not be necessary in this particular case, but you should’ve got the idea by now.