Implicit selection of log tags in Timber library on Android
I assume every Android developer knows and uses the logging facilities provided by the Android SDK. For example, when you need to log something for debugging purposes, you’d end up writing something like that:
Log.d("MainActivity", "Here comes the story of a sleepless night which was spent trying to nail that nasty issue...");
The first argument is the tag:
* @param tag Used to identify the source of a log message. It usually identifies the class or activity where the log call occurs.
Sooner or later you may find out that you need more flexibility with your logs — let’s say that you want to send all crash reports into the Firebase Crashlytics service (but only if they are from release builds, since on debug builds you want them to end up in logcat only), you want your debug logs to be sent to the special SQLite table, etc., etc. This is where some developers end up using the library called Timber. The thing that you notice immediately is that you don’t need to specify the tag:
Timber.d("Another sleepless night, same issue, but at least we don't need tags...");
And yet when you look at the logcat, the tag is here:
05-01 21:39:10.763 9350-9350/com.application D/MainActivity: Another sleepless night, same issue, but at least we don't need tags...
I admit, when I started using Timber, I didn’t stop to think how exactly does it work. It’s time to fill that knowledge gap.
It all ends with the logcat…
…so this is where we’re going to start looking. I was using the Java version of Timber, so here’s the link if you want to take a look for yourself.
My initial idea was that if the logged lines end up in the logcat, we need to search for some standard log invocations (e.g. Log.d
), and we’ll see how the tags are created. The search raises nothing of the sort, but there is something else (lines 425–428):
If you scroll further, you’ll see more and more invocations of prepareLog
. Ok, that’s something, let’s see what’s going on in this method (lines 530–555):
Does it look like the tag is created in getTag
(lines 401–408)?
No, apparently not.
Explicit tags? I thought we’re talking about implicit ones here!
All getTag
does is it gets the tag from the explicitTag
field (which has the type of ThreadLocal
; I’m not going to discuss it in detail here, except for saying that this class provides thread-local variables — each thread that accesses ThreadLocal
variable gets its own copy of it, which is inaccessible to other threads). But if it gets the tag from the ThreadLocal
container, then it means that someone puts it in here, right? Let’s search for explicitTag.set
(we have a single result, lines 135–144):
Ok, I feel like we’re getting to the end of the journey. How does the actual call of the tag
method look like?
Well, there’re no invocations of that method in Timber
, so I assume that’s a dead end. Let’s return to the previous step and look at getTag
again. This method is defined in the abstract class called Tree
, and it is overridden in the class called DebugTree
, so let’s take a look at how the overridden version looks like (lines 615–629):
Wait, what? Do we create an instance of Throwable
only to get a tag from its stack trace?
We do (lines 600–613):
StackTraceElement#getClassName
does the following:
Returns the fully qualified name of the class containing the execution point represented by this stack trace element.
The mystery is solved. What I thought was achieved through the dark reflection witchery ended up being nothing more than a smart usage* of a Throwable
instance.
One more thing
By the way, if we take a look at the comment accompanying the createStackTraceElement
, we’ll notice the following comment:
Note: This will not be called if a {@linkplain #tag(String) manual tag} was specified.
Ok, now I get why do we need the tag
method that we’ve encountered before and why we didn’t see it being invoked in the Timber source code. This method is meant to be used in cases where we want to override the tag extracted from the stack trace with our own tag for the next logging call. And the most likely reason for storing it in the ThreadLocal
container is that we don’t want to end up having a race condition.
For example, Thread A sets an explicit tag to be used for the next logging call, but Thread B gets its chance to access the explicit tag first, effectively using the tag for its intents and purposes (while it shouldn’t). After that, it might get a chance to clean up the explicit tag before Thread A accesses it (which is wrong, because Thread A needs it) or it will not manage to clean it up soon enough (which is also illegal, since Thread A will use the explicit tag and we’ll end up having two log lines with an explicit tag which was meant to be used once). ThreadLocal
container solves this issue nicely by making sure each thread has its own copy of an explicit tag, and no other thread can access it.
Ok, this definitely was an exciting journey, and I hope you’ve learned a trick or two here. Stay tuned for the next articles!
Notes
* Another clever (or should I say non-ordinary instead?) usage of exceptions was in some Python project I’ve heard about a couple of years ago. Unfortunately, I don’t remember the project’s name, but I still remember that the exceptions were being used here to pass the information and control between various parts of a program, so the result looked much more like an event bus, than the mechanism to handle the exceptional situations.