Making assertions with jUnit against log4j console output

I will open by saying that making assertions against your log output is probably a bad idea.  Probably violates every rule of good testing.  That said, I found myself writing characterization tests against some legacy code and I wanted to make sure I didn't break the logging.  So I decided to write some flakey, brittle unit tests.  It was several hours of pain, and I figured it would be a good idea to document my pain so you can avoid some of it (hopefully by not following in my footsteps at all... sigh)

This worked before, how hard could it be?

Part of the reason my mind immediately went to the idea of using System.setOut() to capture stdout is because I'd already done it, with great success, on the Gitlet project (project 2) for 61B (yeesh that code... it hurts...).  The code in there was relatively straight forward (assuming you could find it...):

• Before each test, cache System.out and System.err to variables (oldOut and oldErr)
• Create ByteArrayOutputStreams (BAOS), wrap them in a PrintStream, and use System.setOut/Err to plug them into the pipeline.
• Call .toString() on this BAOS to make assertions against it.
• After each test, put oldOut and oldErr back where I found them

Worked like a charm, and I thought I could apply the exact same solution to my current code.  And for a single test, it worked like a charm.  Here's the catch though:  the project is using log4j, and the logger instance is static.  The ramifications of this were slow to dawn on me, and I paid for my ignorance with several hours of thrashing.

Where the hell did my output go??

So my one test works, I'm happy.  Go home for the day feeling good, all is well.  Well, the next day I sit down to really get down to business.  I write the next test, which advances a little further into the code (this is after creating a couple of fake subclasses for annoying external depencies... but I digress), and suddenly the first test, which was passing before, is failing.  To give me visibility into what I thought my tests were seeing, in the @After code, I'm restoring stdout and stderr and then echoing out what I captured in the test:

 private ByteArrayOutputStream out = null;
 private ByteArrayOutputStream err = null;
 private PrintStream oldOut = System.out;
 private PrintStream oldErr = System.err;
 
 @Before
 public void setup(){
  out = new ByteArrayOutputStream();
  err = new ByteArrayOutputStream();
  System.setOut(new PrintStream(out));
  System.setOut(new PrintStream(err));
 }
 
 @After
 public void teardown(){
  System.setOut(oldOut);
  System.setErr(oldErr);
  System.out.println(out.toString());
  System.err.println(err.toString());
 }

After running these tests a few times, I noticed that only the first run of the test produced any output on stdout.  I was testing failure conditions, which resulted in exceptions being thrown and stack traces being printed to stderr.  So it kind of looked like it was still working.  The difference was that the console output wasn't the result of calls to System.out.print(), instead it was being fed through the log4j logger.  So what, right?  The logger was configured to use stdout, so if I set stdout to be my own stream it should just work... right?

I suspected that somehow the way I was reassigning the stream variable was maybe causing problems.  Like log4j was holding on to a pointer to the old stream and I was reassigning it.  Or something like that.  So I created a TeeStream class.  My thinking was that I set an instance of this class to be stdout and stderr, and instead of reassigning it to reset the stream for each test, I just make it reset a stream internally (sort of adding a layer of indirection).  Here is what the final version of the TeeStream class looked like (inspired by StackOverflow):

public class TeeStream extends OutputStream{
 
 private ByteArrayOutputStream captureStream;
 private OutputStream printStream;

 public TeeStream(OutputStream printStream){
  captureStream = new ByteArrayOutputStream();
  this.printStream = printStream;
 }
 
 @Override
 public void write(int b) throws IOException { 
  captureStream.write(b);
  printStream.write(b);   
 } 
 
 @Override
 public String toString(){
  return captureStream.toString();
 }

 public void reset() {
  captureStream.reset();
 }
}

The idea is that I can pass in any stream I want for "printing" (so stdout or stderr), and everything also gets written to the internal BAOS, so when I call "toString()" on the TeeStream, this content is what I'm getting.  And when I need to start over, I can just call reset() on the internal BAOS (at first I was newing up another one, but I like this way better).

Surely this would solve all my problems, right?

Well after much fiddling around, I did start seeing all the output on the console again.  But the unit tests were still failing.  I tried the debugger, but when I stopped on the assertions, my out and err streams were empty.  They weren't being written to.  So what the hell??

Static cling

I was this close to giving up, when one thought occured to me...

"The logger is static... I wonder if making all my stream instances static would fix this?"

So I tried that, with zero expectation of success... and it worked.  Tests all passed.  Life was good.  But what the hell happened?  I'm not 100% sure, honestly, because I don't know the exact object life cycle for either log4j OR jUnit.  I think the logger is a singleton... it is certainly retrieved from a static method on the Logger class.  I don't think the test class is reinstantiated for every class... but it might be.  Was log4j holding onto the old stream?  Was the old stream getting whipped out because the test class got newed up for every test?  ¯\_(ツ)_/¯

Whatever was going on under the covers, changing the streams to static class variables instead of instance variables fixed the behavior.  Here is what the final code looks like (I threw it in a base class for my tests for easier reuse... we'll see how that works out):

public class TestBase {
 private final static PrintStream oldOut = System.out;
 private final static PrintStream oldErr = System.err;
 protected final static TeeStream out = new TeeStream(oldOut);
 protected final static TeeStream err = new TeeStream(oldErr);

 @BeforeClass
 public static void setup(){  
  System.setOut(new PrintStream(out, true));
  System.setErr(new PrintStream(err, true));
 }

 @After
 public void teardown(){
  err.reset();
  out.reset();
 }
}

//example usage
public class SomeTests extends TestBase { 
 
 @Test
 public void StreamCapture_WorksAsExpected(){
  System.out.println("This test works");
  assertTrue(out.toString().contains("This test works"));
 }
}

This still feels very much like a ticking time bomb, and I feel like somewhere I should be putting stdout and stderr back the way I found them, but for now... it works. And sometimes that just has to be good enough.

... Until it isn't good enough

So I thought I was very clever and had this all figured out, but playing around with this for a couple weeks made me realize I was mistaken.  When you are only dealing with a single test class at a time, the above strategy works fine.  When you try to run several classes, though, this approach breaks down.  If there are multiple appenders configured for log4j, stuff breaks. So I went down the rabbit hole again to try and figure this out.

After screwing around for a while trying to tweak the stream based approach, I took a step back and decided to try working with the file system.  This felt really gross, but I though "Hey, I was able to work with the file system on the Berkeley Gitlet project, so this should at least work even if it's ugly, right?".  So I wired log4j up to use a static text file, used the java.nio.File to get a reference to it in my tests.  I didn't want to have to change all my tests that were calling out.toString(), so I created a kind of dummy class that would mimic this behavior with the log file.  I figured I could just delete the file after every test, and I'd be golden.

public class LogCaptureTest {
 protected static FileDumpr out;
 private static File log;
 private FileAppender fa;

 @Before
 public void logCaptureSetup(){  
  log = new File("src/test/java/ir/mwfbi/testing/temp.log");
  out = new FileDumpr(log);
 }

 @After
 public void logCaptureTeardown(){
  log.delete();
 }
}

public class FileDumpr{
 
 private File log;

 public FileDumpr(File log){
  this.log = log;
 }
 
 
 @Override
 public String toString() {
  try {
   return new String(Files.readAllBytes(log.toPath()));
  } catch (Exception e) {
   e.printStackTrace();
  }
  return "";
 }
}

The problem was, the call to log.delete() failed.  I suspect that log4j had the file locked, so no dice.  If I configured the file appender to append=false, then some of the log output wouldn't show up in the log file when the test was run.  After some fumbling around with removing appenders, StackOverflow saved the day and showed me the light.... well, or so I thought.  I thought the following code was behaving:

public class LogCaptureTest {
 protected static FileDumpr out;
 private static File log;
 private FileAppender fa;

 @Before
 public void logCaptureSetup(){  
  log = new File("src/test/java/ir/mwfbi/testing/temp.log");
  out = new FileDumpr(log);

                fa = new FileAppender();
  fa.setName("FileLogger");
  fa.setFile("src/test/java/ir/mwfbi/testing/temp.log");
  fa.setLayout(new PatternLayout("%-5p %d [%t] %c: %m%n"));
  fa.setThreshold(Level.DEBUG);
  fa.setAppend(false);
  fa.activateOptions();
    
  Appender app = fa;
    
  //add appender to any Logger (here is root)
  Logger.getRootLogger().addAppender(fa);
 }

 @After
 public void logCaptureTeardown(){
  Logger.getRootLogger().removeAllAppenders();
 }
}

LIES!

Turns out these are actually a bunch of no-ops.  The preconfigured logger was just running and by coincidence whatever the last fidget I'd made caused my tests to pass.  But it was still fundamentally broken, because I was tied to this static text file that was creating possible coupling between my tests.  I wanted complete isolation and even better, all in memory.  Next stop: pain city.

Log4j docs are sooooooo helpful </sarcasm>

I ended up finding an article in the documentation that looked promising: Programmatic Configuration.  It looked a bit daunting, so I created another class to muck around with the logger called LoggerFacade, which had one static method resetLogger();  Because that is ultimately all I wanted it to do.  Just reset everything after each test.  The big hairy examples were mostly useless, in no small part because they didn't include the import statements (most of what I needed was in the org.apache.logging.log4j.core.* tree).  After a solid hour of thrashing, this is what I got to work:

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.Filter.Result;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.appender.ConsoleAppender;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.filter.ThresholdFilter;
import org.apache.logging.log4j.core.layout.PatternLayout;

public class LoggerFacade {

 public static void resetLogger(){
  
  final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        final Configuration config = ctx.getConfiguration();
        removeEverything(config);
        
        PatternLayout layout = PatternLayout.createLayout(
          PatternLayout.SIMPLE_CONVERSION_PATTERN, 
          null, config, null, null, false, false, null, null);
        Appender appender = ConsoleAppender.createDefaultAppenderForLayout(layout); 
        appender.start();
        
        Filter filter = ThresholdFilter.createFilter(
          Level.ALL, Result.ACCEPT, Result.NEUTRAL);
        config.getRootLogger().addAppender(appender, Level.INFO, filter);
        ctx.updateLoggers(config);
 }
 
 private static void removeEverything(Configuration config){
  for(String appName : config.getRootLogger().getAppenders().keySet()){
   config.getRootLogger().removeAppender(appName);
  }
 }
}

This gave me a very simple mechanism to do what I wanted to do.  This creates a brand new appender before every test.  I just needed to set StdOut and StdErr to be a TeeStream so I could grab the output, and voila.  I was not full circle, only this time stuff actually works correctly:

public class LogCaptureTest {
  private final static PrintStream oldOut = System.out;
  private final static PrintStream oldErr = System.err;
  protected final static TeeStream out = new TeeStream(oldOut);
  protected final static TeeStream err = new TeeStream(oldErr);
 
 @Before
 public void logCaptureSetup(){  
  System.setOut(new PrintStream(out, true));
  System.setErr(new PrintStream(err, true));
  LoggerFacade.resetLogger();
 }

 @After
 public void logCaptureTeardown(){
  err.reset();
  out.reset();
 }
}

Oh, and if you decide to use the enclosing class organizational technique, make sure the inner classes subclass the LogCaptureTest (or whatever base test class you are using).  Otherwise @Before and @After don't run.  I may or may not have found this out the hard way...  ಠ_ಠ