Using Logs in Unit Tests

Have you found yourself needing to look at log messages from inside a unit test? I asked myself this question recently and have found that logging might be one of the best examples in the Java world to see how screwy our concepts of framework maturity are.

I love LogBack, and greatly appreciate the improvements it made over log4j. It‘s worth switching just so that you never have to see the insanely stupid ‘no configuration found..‘ blah, blah, blah. Who designs software to not have a simple default configuration? Well.. Though I love logback, I began to worry about framework maturity. Why? Well here are a few reasons:

1. Everyone agrees now that commons-logging was a useless boondoggle. I would argue that it‘s a great example of rottenness, but a special kind: an over-ripening of a ‘fruit‘ that was never worth reaching for in the first place. (Part of the reason this happens, I believe, is that cabals of coders follow their own silly notions of what would be cool. Like programmers who attempt to preMATUREly optimize their apps, the problem is they are almost always wrong.)
2. The commitment to said campaigns ends up doing great damage not only to the product, but the corresponding community, and the ability to do other/better things. Log4j is a good example of this.
3. Finally, the main reason this stuff happens is because there are poor architectural choices that inhibit the more intelligible approaches that would clearly make things better.

For instance, consider these questions:

1. Why on earth, in an age where most of us have some kind of container-based wiring, are loggers not wired through said container?
2. Ever looked at what you have to do to get your hands on log messages? It‘s completely insane. Has anyone who ever worked on a logger heard of the Observer pattern?? Why on earth can‘t I write a unit test where I attach a listener to a log? That would be too simple.
3. One of the advances in logback is that Logger and LoggerFactory are both interfaces! Alright, so I should be able to substitute my own implementations? Well, not so fast. They are also stitched together using everyone‘s favorite pattern: Singleton. (Wow, isn‘t there a cure for stupid framework singletons? Yeah there is!: move them into a DI container!)

Here‘s how I ended up down this road: I wanted to write a logging aspect for repository operations that would show the sequence of calls in debug mode, and the transformed entities in trace mode. Should have taken half an hour. Decided, though, that I should finally just get my hands on the actual log messages so I can really know it‘s doing what I want. First, I thought that the quickest answer would be to make a mock logger. That‘s pointless. Why? Because I could make a mock logger, and inject it into my class, but that meant leaving a setLogger method permanently in the class. So then I figured, well, wouldn‘t it make sense if there was a way to manipulate the chain of loggers? Well there isn‘t. The LoggerFactory will return loggers, but it exposes NO interfaces for registering your own loggers programmatically. This is a hallmark, to me, of fascist frameworks: you, the User, are too stupid to be trusted. (I don‘t blame LogBack for this because the whole structure is like a crucible now: there is no way to do anything with the mold, just what goes in.) Next, I thought about replacing the factory, but that‘s a singleton, so that would mean a lot of silly classpath nonsense, which could turn into a nightmare.

So then, I decided to make a custom appender. The documentation makes it seem like it‘s going to be simple. But right away, we end up back in hell. Why? Well, if you configure the appender in the xml file, how are you going to get your hands on it so you can get the events that are enqueued within? Make the appender a Singleton you say (rots from the head down)? Can‘t do that, because the logging framework creates an instance through a public constructor. I finally resorted to just making an appender with NOTHING in it, extending AppenderBase, and made a great discovery, that you can simply add debug=“true” to the toplevel tag and it will show you what it is doing when it is created. For some reason, the simplest appender possible, wired in the designated way, spat out the following error:

Caused by: java.lang.IllegalStateException: Logging factory implementation cannot be null. See also http://www.slf4j.org/codes.html#null_LF

When you go lookup the error, it tells you that you need to put one and only one of a list of jars in your path. Well, the jars are there. After mucking with this for a bit, I decided, maybe the JoranConfigurator will let me create the appender inside the unit test then inject it into the logger programmatically. Read the docs on the configurator, does not appear to address such mundane concerns.

Folks, this is a world gone completely mad. I used to think people who talked about writing their own loggers were complete loons, now they are starting to look like the sane ones: the nuthouse escapees who threw off their dribble bibs.

Solution

Ok, figured out why the file-based config was not working: I had a logger inside my appender. Once I took that out, it initialized it properly. Then, of course, since I am not programmatically creating the appender in the test (this, logback does deserve some grief for since it shut that down (log4j has it)), I could not get the messages, so I just have the appender chaining to a singleton. This sounds ugly, but it means that I can use this in unit tests that do not startup the Spring container. And frankly, I am going to keep an instance in the test class so who really cares: it‘s a test class, universally accessible bucket, nothing more. When I do want to do tests at the container level, I can inject the collector that will hold the events.

BTW, in commission of this phase, found two cool things:

1. Seam supports injected loggers through annotations. We were already planning to move to Seam for a whole host of other reasons, so this was a good thing to see.
2. I went back to Q again, and was thrilled to see it has a download sources task in its submenu, v. the common one time checkbox in the preferences pane from Codehaus‘ plugin, that made you look at attempts to retrieve non-existent jars every damn time it sneezed.