Don’t mock static: test Timber Logger with trees

What is Timber?

Timber is golden standard in Android logging. It makes use of trees concept – you can treat them as different output channels for log messages.

Usually in Android app you would write following code to have Timber in debug mode:

class App: Application(){
  override fun onCreate(){
    	
   super.onCreate()
    
   if(BuildConfig.DEBUG){
   	Timber.plant(Timber.DebugTree())
   }
  }
}

You may also use Timber to log messages into remote analytics services such as Sentry or Firebase:

class FirebaseLogging: Timber.Tree(){
    override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
        FirebaseCrash.logcat(priority, tag, message);
        FirebaseCrash.report(t);
    }
}

As I mentioned in previous article, sometimes testing our logs may be crucial for debugging. So in the next section we will dive into techniques of using Timber to test logs.

How to mock Timber?

First of all, forget about using mock-static constructs from Mockito, MockK or PowerMock for that purpose. While those tools are useful, they are not needed in most cases.

So how are we gonna provide test implementation for logging framework? We will make use of indirect injection – we will provide custom Timber.Tree in the unit test scope.

Let’s consider a system under test:

import timber.log.Timber
import java.lang.Exception

class SystemUnderTest(private val service: ItemsService) {
  fun fetchData(): List<Entity> {
    return try {
      service.getAll()
    } catch (exception: Exception) {
      Timber.w(exception, "Service.getAll returned exception instead of empty list")
      emptyList<Entity>()
    }
  }
}

interface ItemsService {
  fun getAll(): List<Entity>
}

data class Entity(val id: String)

Now let’s create Timber tree in the same fashion as we created TestAppender for SLF4J test:

1. Extend Timber.Tree
2. Capture incoming log (we are also creating additional data class)
3. Add log to list
4. Plant that Tree

import timber.log.Timber

class TestTree : Timber.Tree() {
  val logs = mutableListOf<Log>()

  override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
    logs.add(Log(priority, tag, message, t))
  }

  data class Log(val priority: Int, val tag: String?, val message: String, val t: Throwable?)
}

Now using this TestTree we can actually write unit test for happy and error path:

import android.util.Log
import io.kotlintest.assertSoftly
import io.kotlintest.matchers.collections.shouldBeEmpty
import io.kotlintest.matchers.string.shouldContain
import io.kotlintest.shouldBe
import io.kotlintest.specs.StringSpec
import io.mockk.every
import io.mockk.mockk
import timber.log.Timber

class Test : StringSpec({
  "given service error when get all called then log warn" {

    //prepare logging context

    val testTree = TestTree()
    Timber.plant(testTree)

    //setup system under test
    val service = mockk<ItemsService> {
      every { getAll() } throws Exception("Something failed :(")
    }
    val systemUnderTest = SystemUnderTest(service)

    //execute system under test
    systemUnderTest.fetchData()

    //capture last logged event
    val lastLoggedEvent = testTree.logs.last()

    assertSoftly {
      lastLoggedEvent.message shouldContain "Service.getAll returned exception instead of empty list"
      lastLoggedEvent.priority shouldBe Log.WARN
    }
  }

  "given service return values when get all called then do not log anything" {

    //prepare logging context
    val testTree = TestTree()
    Timber.plant(testTree)

    //setup system under test
    val service = mockk<ItemsService> {
      every { getAll() } returns listOf(Entity(id = "1"))
    }
    val systemUnderTest = SystemUnderTest(service)

    //execute system under test
    systemUnderTest.fetchData()

    testTree.logs.shouldBeEmpty()
  }
})

In the first test case we have the following flow:

a) Prepare logging context and plant test tree:

val testTree = TestTree()Timber.plant(testTree)

We can also quickly verify if we planted Tree correctly:

println(Timber.forest()) //[tech.michalik.project.TestTree@1e7a45e0]

b) Execute given and when statements:

//setup system under testval service = mockk<ItemsService> {  every { getAll() } throws Exception("Something failed :(")}val systemUnderTest = SystemUnderTest(service)//execute system under testsystemUnderTest.fetchData()

c) Grab last logged event from test logger and make soft assertion:

//setup system under test
val service = mockk<ItemsService> {
  every { getAll() } throws Exception("Something failed :(")
}
val systemUnderTest = SystemUnderTest(service)

//execute system under test
systemUnderTest.fetchData()

I also create helper function to provide TestTree context anywhere in the test:

fun withTestTree(body: TestTree.() -> Unit) {
  val testTree = TestTree()
  Timber.plant(testTree)
  body(testTree)
  Timber.uproot(testTree)
}

With this syntax we can reuse test tree more easily:

"given service error when get all called then log warn" {

  //setup system under test
  withTestTree {
    val service = mockk<ItemsService> {
      every { getAll() } throws Exception("Something failed :(")
    }
    val systemUnderTest = SystemUnderTest(service)

    //execute system under test
    systemUnderTest.fetchData()

    //capture last logged event
    val lastLoggedEvent = logs.last()

    assertSoftly {
      lastLoggedEvent.message shouldContain "fetchData returned exception instead of empty list"
      lastLoggedEvent.priority shouldBe Log.WARN
    }
  }
}

If you want to always explicitly create and plant TestTree, that’s fine. Reusing test configurations in that way is matter of your and your team preference. Keep in mind that readability comes first and not everyone may be comfortable with this syntax.

Summary:

1. If you need to verify/assert loggers in tests, use indirect injection instead of mocking static method
2. Plant Timber.Tree for tests the same way you would plant Timber trees in production code
3. Create helper methods when there is need to reuse configurations easily.