Rob Williams is a probabilistic Lean coder of Java and Objective-C. Rob is a DZone MVB and is not an employee of DZone and has posted 170 posts at DZone. You can read more from them at their website. View Full User Profile

Using Logs in Unit Tests

04.12.2008
| 7699 views |
  • submit to reddit
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.
AttachmentSize
images.jpeg4.64 KB
Published at DZone with permission of Rob Williams, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Tags:

Comments

Ronald Miura replied on Sun, 2008/04/13 - 12:07pm

Well, I don't agree that commons-logging is useless. It may be bad implemented (I've never had those classloader issues people often mention, but they may exist), but it certainly have its place.

What if Spring used LogKit, and Hibernate used Log4j, Seam used its own home-baked logging framework, and I used java.util.logging in my application? I'd have to ship two extra jars (log4j and logkit) and have four logging configuration files? What if it was a desktop application deployed by Java WebStart, and I needed to make it as small as possible?

I had this problem once, because I had to use a library that used Log4j directly, and my module was a Swing application. My luck is that the library's implementor worked by my side, and I simply asked him to change it to commons-logging, so he could still use his log4j configuration on the server (it was shared between server and clients), and I could use java.util.logging for my client. I certainly wouldn't be able to ask Gavin King to do that for me (thanks Gavin, for using commons-logging in Hibernate!).

And this idea of 'injecting' loggers is silly... So, now I have to use a container to print some error messages to the console? It may work in a server environment, since you're already stuck with some kind of container anyway, but even then, maybe your container is not my container (say, Spring, EJB, or Guice), and they don't support the same APIs for logger injection? If the did, they'd have to agree in a single common API. Maybe it would be... commons-logging's? :)

Marcos Silva Pereira replied on Sun, 2008/04/13 - 10:40pm

Logs in my Unit Tests? No, thanks. Could you please show me an example where you need such thing?

Kind Regards 

Walter Laan replied on Mon, 2008/04/14 - 3:24am

I've only used java.util.logging, but if would want to do something with the log in a unit test (maybe fail on a logged error?), you could just use addHandler() to do that in the unit test setup.

Greg Allen replied on Mon, 2008/04/14 - 4:23am

There is a flaw in your premise, that you can test something on the basis of what it logs that is doing.

 Such an approach obviously neglects to test whether the subject actually did what it claimed. e.g. if you checked for "entry" would this pass?

12:00 ACMEmodule: entry
12:00 ACMEmodule: config error, abandoning

 Sounds like a dangerous pattern...

just my 2p :) 

Rob Williams replied on Mon, 2008/04/14 - 9:59pm in response to: Ronald Miura

@Ronald: Seam does inject the commons logger. The injection idea does make some amount of sense because you can have some control over setting up the state of the logger before it is stuffed into your class. You could make your own log factory for that I spose, but if you are doing DI, might as well do it.

@Marcos, et al: Well, in this case I was writing an aspect that logs Repository activities. Wow, I really didn't expect people would think the idea repellent. If the aspect's job is to put messages in the log, unit testing that the right messages are going in at the right levels makes sense, no?? As to the idea of a 'bad pattern' I don't get that at all. I am not taking the log message as a proof of some other thing occurring. Frankly, the bad pattern there is to only look at unit tests as proofs. You should look at them also as guarantees of desired behavior, so if someone unwires the aspect, or changes the declarations, your test fails, rather than you pushing out a release that doesn't have any logging in it. Right?

Thanks for the feedback, Guys. 

 

Aaron Digulla replied on Thu, 2008/05/08 - 4:49am

I ran into the same problems while writing a new appender for log4j. Implementing the appender is simple - as long as you don't intend to test it. Testing log4j is insane. I was close to using reflection and setAccessible(true).

Ceki Gulcu replied on Tue, 2008/10/14 - 8:37am

Actually logback comes with hundreds of unit test cases which one can
use as a starting point. For specific recommendations, I would
encourage you to post your questions on the logback user mailing list.

HTH,

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.