Timbering Unit Tests

Logging is an essential part of app development and even though the Android framework provides us a convenient class Log which has some nice features like tagging logs, verbosity levels or logging exceptions, this class is not really customizable regarding where to log. 

That's why the community (JW 🙏) came up with a replacement for this Log class called Timber. It allows you to “plant trees into timber” where the Tree represents a service you want to log into. There is a built-in DebugTree which uses the Android's Log class and it has some nice addons like splitting the message if it's too long or automatically prefilling the log's tag based on a class the log was printed from. 

Ok, now you're like “OMG everyone knows this, what does it have to do with tests?”

Unit testing ft. Timber

If you write any unit test that uses a class calling some Timber logs you don't have a chance to see those logs. Those logs could have a huge benefit to you: you could see the call path of the code (in case you of course have those logs there) or you could even add some debug ones when debugging a test. I personally use breakpoints with the debugger as a last resort if the logging fails due to its low speed.

Then how to enable those logs? You need to plant a new Tree inside Timber.

  Timber.plant(object: Timber.Tree() {
   override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
       println("$tag: $message")
   }
})

There is a single method Log you need to override and you'll receive priority (verbosity level), tag, message and optional exception. In this simple implementation the Tag and Message are printed using the println method which prints the output to the test console.

If you try to put this code to the beginning of every test method you 

1. Do not respect DRY principle much 😬
2. Notice that the logs are multiplying with each new method.
3. Notice that the tag is null

We will cover the first problem in a moment.

The second problem happens because Timber stores the Trees into a static variable and it outlives the single test method run and with each new test method you plant a new Tree. The solution is pretty simple, you need to ensure that the planting runs only once and with JUnit4 you achieve that with @BeforeClass annotation on a static method.

class MyClassTest {

   companion object {

       @JvmStatic
       @BeforeClass
       fun setupClass() {
           Timber.plant(object: Timber.Tree() {
               override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
                   println("$tag: $message")
               }
           })
       }
   } 

   ... 

}

It's a little verbose in the Kotlin world but it does the trick. But we are still not finished with the duplicating of logs. If you would use this in multiple tests the logs are duplicating again. 🤯 You need to remove, or uproot, the instance of the Tree from the Timber.

  companion object {
   private val printlnTree = object: Timber.Tree() {
       override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
           println("$tag: $message")
       }
   }

   @JvmStatic
   @BeforeClass
   fun setupClass() {
       Timber.plant(printlnTree)
   }

   @JvmStatic
   @AfterClass
   fun cleanupClass() {
       Timber.uproot(printlnTree)
   }
}

Regarding the third problem, you can just make a small change to inherit from Timber.DebugTree instead of a Timber.Tree and the Tag will be filled with a class name.

You must agree that this is still a little bit verbose to use in multiple test classes. One improvement would be to extract the Tree to a special class PrintlnTree, but we can go even further by removing the planting/uprooting from the test class altogether by creating a custom JUnit Rule. 😱

  class TimberRule : TestWatcher() {
   private val printlnTree = object : Timber.DebugTree() {
       override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
           println("$tag: $message")
       }
   }

   override fun starting(description: Description?) 
       super.starting(description)
       Timber.plant(printlnTree)
   }

   override fun finished(description: Description?) {
 super.finished(description)
 Timber.uproot(printlnTree)
   }
}

and then in your test class 

companion object {    @get:ClassRule    @JvmStatic    var timberRule = TimberRule() } 

Still a little bit verbose but hey, you've saved two methods with a single variable 😏 Favour using TestWatcher instead of TestRule directly because TestWatcher provides convenient methods for hooking into lifecycle of the tests. 

JUnit5 goodies

If you're all up for JUnit5 I have something for you as well:  

  class TimberExtension : BeforeAllCallback, AfterAllCallback {
   private val printlnTree = object : Timber.DebugTree() {
       override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
           println("$tag: $message")
       }
   }

   override fun beforeAll(context: ExtensionContext?) {
       Timber.plant(printlnTree)
   }

   override fun afterAll(context: ExtensionContext?) {
       Timber.uproot(printlnTree)
   }
}

and then you just register this extension with 

  @ExtendWith(TimberExtension::class)

class MyClassTest {

 ...

}

Conclusion

If you want to see the logs of your production code in your tests with Timber, it's really easy by just planting your own Tree. With a few tricks you can extract this to a composable JUnit Rule/Extension and use it in all of your tests and projects.