Question: How can we make logs more useful?
Answer: Lil Bit O’ Magic ✨
Hiding Timber behind an interface
Let’s say we have an app that is using Timber for logging. We don’t want to call Timber directly so we hide Timber behind an interface. We do this so we can swap out the implementation depending on the environment. We’ll have an Android implementation and a Java implementation. We’ll inject, via Dagger, the Java Impl when running JUnit test and the Android Impl for everything else. So to summarize:
Great! And Simple! But wait … my Android implementation prints the tag as AndroidLogger… what gives?!
Fixing the Tag
A nifty feature of Timber is the automatic class tag generation. This means that we only need to pass in a message to Timber and it will generate a tag for us. Say goodbye to always passing in the same tag for all your messages (e.g. “asd”😛). To do this, Timber creates a new Throwable and gets a StackTraceElement at a certain position in the stack trace. You can think of a StackTraceElement as a method invocation. So, we can get the calling class of our logger if we sift the through the stack trace and find that element. Let’s look at this in the following example:
We have a simple Activity that prints a message when onCreate and onResume are called. The LogCat will look something like this:
If we look at the center of our log we can see our log statements. At the end of the log statements we see the source that called them. Cool! But how’d that work and why do we call throwable.getStackTrace()[1] with a hardcoded index?
As mentioned earlier, a Throwable will generate a stack trace when it’s created. That stack trace is a list of methods which were invoked that lead up to that Throwable instance creation. Think of this stack trace as a bunch of dominos in a line. One domino will push the next one, so on and so forth. In this case, we are trying to find the finger that pushed the fist domino. That first domino is our printToLogCat method.
We can find this mystical finger(🔮👉) by checking out the stack trace. We can get this stack trace by calling Throwable.getStrackTrace(). This will return an array of StackTraceElement. We see that that the first element (index 0) is the method that is printing the message, same method that creates the instance of the Throwable! If we look at the next element (index 1) we can see a method invocation from MainActivity.onCreate(), BINGO! This is the magic number we need to reference for our log statement and any future log statement within MainActivity.
So, with that knowledge in hand, we can go ahead and fix this tag! Technically, we didn't break the tag creation feature, but we do need to compensate for our abstraction. We can fix this by planting our own DebugTree and overriding the createStackElementTag method. We can take a hint from Timber.DebugTree and see how the tag is generated. Using that same code, we can fix the problem with something like the following:
Let’s break it down 🕺 :
1.) Create a new instance of Throwable and get the stack trace. The stack trace is a StackTraceElement array which is a sequence of method invocations with the first element(index 0) being the method that the Throwable was created.
2.) Pick the correct StackTraceElement. Timber has a hardcoded index of 5, yet our example had an index of 1. Thats because Timber has some extra method invocations to generate a tag before its ready to print. In our case, we really need the 8th element. We need compensate for two extra method invocations in our custom FooTree: createStackElementTag and newStackTraceElement. This gets us to an Index of 7, which equates to the AndroidLogger method invocation. We want to compensate once more to get the caller of AndroidLogger.v()
3.) Clean it up. If on API 24 or greater, we don’t need to limit character length of the tag (23 chars), but we do need to compensate for anonymous classes. We also want to remove the class path as well, same that Timber does.
4.) Profit… via Timber.plant(new FooTree());
Great! Once thats done we now have an abstraction around Logging with the same functionality! So how can we make this even better?
Let’s make logging great again
We can do some cool stuff now that we can fetch the proper stack trace element. If you’ve seen a printed stack trace in LogCat, you’ll notice that the file name and the line number are printed at the end of a single stack element frame, linkify’d in blue, like so:
What if we can do that same thing but for all logs? We can! LogCat will (usually) see (class_file_name.ext:###) sequence and highlight it as a link. Clicking this link will open the file within the IDE. We can prove this in our example:
Which would look something like the following:
In our Timber Abstraction classes we can do the same by appending the same sort of formatted string to the end of our message (i.e. inAndroidLogger.v()). Better yet, if we have a minSdk of 24, we can have this special format be the tag so it could print a message as I/(MainActivity.java:13): This is My Message.
Hope this was helpful, happy logging!
