Logging is an inevitable part of debugging. Well, at least in modern high-level programming languages and architectures. It wasn’t thirty years ago, in Assembly, but it is now. Sometimes we trace variables, but rarely. More often we just print them to console. Moreover, we don’t just print them using println or whatever it is we have for console printing; instead, we send messages to a logging framework, which deals with the console or any other logging destinations, like files. The beauty of such frameworks is that we don’t need to remove logging after debugging is finished—we just configure the framework to suppress all debug-level messages in the production environment. Some logging may happen inside unit tests. Do we also leave them there or maybe not?
Here is an example (it’s a simplification of a real unit test at CalcTest.java from Polystat, a static analyzer we’re working on right now):
import com.jcabi.log.Logger;
import com.jcabi.xml.XML;
import org.hamcrest.MatcherAssert;
import org.hamcrest.Matchers;
import org.junit.jupiter.api.Test;
public final class FooTest {
@Test
public void buildsSimpleXml() {
final XML xml = new Foo().build();
Logger.debug(this, "This is the XML:\n%s", xml.toString());
MatcherAssert.assertThat(
xml,
Matchers.notNullValue()
);
}
}This is Java and I’m using JUnit5+Hamcrest together with my own logging framework jcabi-log, which is a decorator of Slf4j, which uses Log4j to print to the console.
What is going on here? There is a class Foo with a method build(), which makes an XML document (I’m using jcabi-xml library, which is a decorator of JDK DOM). Then, the unit test prints the contents of the XML document to the console and makes a pretty silly assertion: the document is not NULL. It is silly because if it were NULL, the logging statement would already fail at the .toString() call.
I’m the developer of this code, so I know what was going on: I was too lazy to write a proper assertion, which would look into the XML document and ensure that there were proper elements inside. I just printed it to the console, visually confirmed its validity and called it a day. If I’d had more time, this is how I would have written a much better unit test (I made the improvements in Polystat tests just now):
import com.jcabi.matchers.XhtmlMatchers;
import org.hamcrest.MatcherAssert;
import org.junit.jupiter.api.Test;
public final class FooTest {
@Test
public void buildsSimpleXml() {
MatcherAssert.assertThat(
XhtmlMatchers.xhtml(new Foo().build()),
XhtmlMatchers.hasXPath("//foo")
);
}
}Now, the XML document is built and then tested for the presence of //foo XPath inside it. The content of the document will be printed to the console only in the case where the assertion fails. If the XML has the required XPath, there will be no console output, which means no noise for future developers.
Moreover, now it’s a single-statement test, which by itself is good practice.
Looking back on my experience of testing and logging, I believe that logging in unit tests is a bad idea. Sometimes inevitable, because we are lazy or simply don’t have enough time, but still bad. Logging helps us confirm visually the correctness of the output, but it takes this knowledge away from the project. Those who will work with the test later on won’t know what we’ve seen there. They will see the output at the console, but will not understand whether it still matches my expectations at the time of writing.
I would say that every logging line in a unit test is a message from its author: “I know something about the data I see now, but I’m too lazy to tell you about it, you just have to believe me that it looks good.”
I suggest we don’t leave such messages in our code.
Published on Java Code Geeks with permission by Yegor Bugayenko, partner at our JCG program. See the original article here: Logging in Unit Tests, a Bad Practice Opinions expressed by Java Code Geeks contributors are their own. |
