Best-practice Android logging
A blog post about Android logging? Must be a slow news day you are probably already thinking, but hear me out on this one. This is a quick tour around my personal best-practices and you may likely not agree with all of them - if so, let me know in the comments. ;)
This makes so-called logging breakpoints a perfect fit what you would otherwise have put in verbose logging statements at the source level. You can see this feature demoed here.
Even with filtering in place, sometimes you just have groups of related log info you'd rather be collapsed somehow. This is easy to do by right-clicking on the line in question (typically first line of what you want hidden in the fold) and writing an expression to match what will get folded. It's also here you can shorten excessive stack-traces and hide irrelevant internal calls.
The above screenshot shows 3 similar lines for each Firebase remote config property loaded. The screenshot below shows how the 3 related yet different lines are now folded up under the parent "Successfully obtained Firebase remote config" log line.
Last but not least, the color scheme used by Android Studio for LogCat can be improved upon a bit by making level-indication a bit more obvious (this becomes even more important when you are running a dark theme). I like to make all levels different in color and style so its easy to identify.
During execution of an app, one is typically interested in certain course-grained aspects of an app, and probably not so much which file logic lives in. For this reason, I like to define global logging tags based on app aspects. It doesn't matter too much what you choose for these aspect names, but make them generic and/or something that makes sense to your app. I typically always have the following:
To easily log UI lifecycle events for any and all activities, simply provide a custom application class and in its onCreate() method, register for lifecycle callbacks:
Oh and while you are in there, do yourself the favor and enable StrictMode for your debugging builds so that you bad dynamic behaviors of your app are logged.
Modern apps are often revolving around just one activity but many fragments instead, so it's equally if not more important (due to their insane complex lifecycle) to be able to log fragment events. It can be done in a similar way, by overriding onAttachFragment() in a base class for your activities:
Simply enter the template characters and expand with the tab key. The templates "logm", "logr" and "logi" remains my favorites.
The first matrix demonstrates filter settings when just wanting to following along and learn how the UI is put together when i.e. getting to know a new application. The second matrix is how you would think (and thus configure the logging) when wanting to screen an app quickly after a test suite has run, whether something exceptional happened anywhere. The last example shows how one would configure the filter when looking for issues in some app logic doing network communication.
Android Studio and LogCat
On Android, logging has always been an integral part of the development experience, first through the standalone LogCat utility and since through the Android Studio integration. The build-in LogCat now even offers advanced filtering capabilities based on logging level, regular expressions for package names, logging tag and the actual log messages. However, all this power is really only useful if you play along nicely at the source level as well, or you will drown in log messages without really knowing how to specify what you want to see. This is a common problem as the Android OS and any libraries you may use will spit out an obscene amount of logging, especially at the verbose level.Use correct log levels
This isn't really Android specific since it's a problem all over the Java space. Many projects don't classify log severity correctly and some can't even be bothered to use logging at all and pipes stuff to System.out and System.err. While there are a LOT of logging frameworks for Java and they differ in functionality, most of them agree on the logging levels. On Android, the levels are:-
ERROR– Don't use; if something this severe has happened, it is the result of an exceptional state rendering the application context invalid! The application should crash gracefully and collect relevant info for submission as a crash report to Google, CrashLytics, TPA etc. - WARN – Something bad happened, but the application is still able to recover and continue executing albeit perhaps in a limited fashion. A developer can filter on the WARN level in order to learn about application states which are candidates for being handled better.
- INFO – Important business process that changes the state of the application significantly (database update, external system request, network connectivity change etc.) has completed. A developer can filter on the INFO level in order to get the big picture of what is going on at the task and flow level, which a non-developer should also be able to understand.
- DEBUG – Detailed developer insight into core decisions, states and events.
-
VERBOSE– Don't use; very detailed trace information, intended only for temporary development insight (debugging and troubleshooting), should not risk being left in code and potentially be checked into Git (you are using Git right?). Instead you'll want to use a logging breakpoint as explained below.
Logging breakpoint
I mentioned in the above section, that VERBOSE should not be used. This is because the stuff you'd put at the VERBOSE level is so detailed that it doesn't belong in source code (logging statements riddled everywhere makes code harder to read). Instead, Android Studio offers a powerful hybrid mechanism between debugging and logging - basically it allows you to set breakpoints and rather than have these suspend program execution as usually happens, they merely log an expression to LogCat.
This makes so-called logging breakpoints a perfect fit what you would otherwise have put in verbose logging statements at the source level. You can see this feature demoed here.
LogCat Filtering
As an alternative to viewing the complete system log, the "Show only selected application" context filter is not too hard to understand and use, but even this filter will result in a lot of irrelevant garbage from app and OS libraries being used from the app process. I would like to be able to recommend using custom logging filter configurations, but unfortunately I find them too unreliable to trust in practice. For instance, it seems like (with the present version of Android Studio anyway) there is no way to whitelist debug and verbose messages (anything more detailed than info messages) and that's just a no-go for me. However, it's Ok as we can filter at a line level instead and accomplish much the same. Unless I'm hunting for something specific, I always use a black-list approach, since you never want to exclude relevant messages you do not know about in advance! This means entering a rather long and complex regular expression, but it only has to be done once. The following filter clause is a common one I use, but it will vary a lot depending on the amount of noise being generated on the specific device you are using:^((?!(?:art|ResourceType|System|GED|libEGL| DynamiteModule|Timeline|OpenGLRenderer)).)*$This way it becomes a joy to see what's going on and simply jump up or down in the severity filter depending on how fine grained you want to follow along.
Tweak the LogCat settings
To the left of the LogCat window is a vertical toolbar which you may also want to utilize a bit more - it took me a while before I started taking full advantage. Press the cog wheel to go to Settings to configure the LogCat headers and remove the checkbox in "Show date and time" as well as "Show process and thread IDs". This will give you 30 characters more on each line for actual valuable info. If you need to time something, there are better ways to do so using profiling tools like i.e. systrace. Sometimes I also remove the package name since the truly interesting part remains the TAG and associated message. While you are in the LogCat toolbar, familiarize yourself with the other options. Soft wraps can be very handy when you'd rather not miss something in a large message - typically serialized data. The restart button is also going to be needed from time to time, as adb or its integration with the device, is notoriously unstable and can play tricks on you.
Even with filtering in place, sometimes you just have groups of related log info you'd rather be collapsed somehow. This is easy to do by right-clicking on the line in question (typically first line of what you want hidden in the fold) and writing an expression to match what will get folded. It's also here you can shorten excessive stack-traces and hide irrelevant internal calls.
The above screenshot shows 3 similar lines for each Firebase remote config property loaded. The screenshot below shows how the 3 related yet different lines are now folded up under the parent "Successfully obtained Firebase remote config" log line.
Last but not least, the color scheme used by Android Studio for LogCat can be improved upon a bit by making level-indication a bit more obvious (this becomes even more important when you are running a dark theme). I like to make all levels different in color and style so its easy to identify.
Log application aspects rather than class names
While the vanilla approach to writing logging statements on Android is to define a TAG constant with the same name as the class, this is a stupid practice in my opinion. Sure it is easy to adhere to (no thinking required) and can work well for small projects with only a few activities or views. This however, does not scale to projects with 50+ views and/or apps with complex life-cycles - it is simply too difficult to troubleshoot a problem and sooner rather than later you'd have to resort to a slow and tedious debugging session. So what to do instead then?During execution of an app, one is typically interested in certain course-grained aspects of an app, and probably not so much which file logic lives in. For this reason, I like to define global logging tags based on app aspects. It doesn't matter too much what you choose for these aspect names, but make them generic and/or something that makes sense to your app. I typically always have the following:
/**
* Logging tag used for common UI lifecycle events
*/
public static final String LOG_UI = "UI";
/**
* Logging tag used for any kind of network I/O communication
*/
public static final String LOG_NET = "NET";
/**
* Logging tag used for storage; local files, preferences and databases
*/
public static final String LOG_DATA = "DATA";
/**
* Logging tag used for business logic and app related things not
* already covered by the other log tags
*/
public static final String LOG_APP = "APP";
Reading a log now becomes super easy and at the INFO level, even non-technical people should be able to follow along if need be:
Always log major UI flow events
Apps are, by definition, highly interactive and UI heavy. It thus makes a whole lot of sense, to trace UI aspects accordingly. The nice thing about UI events, is that it's surprisingly simple to get some broad standardized logging up and running which you won't have to worry about again when adding more views in the future.To easily log UI lifecycle events for any and all activities, simply provide a custom application class and in its onCreate() method, register for lifecycle callbacks:
@Override
public void onCreate() {
super.onCreate();
Log.i(LOG_APP, "Creating Application");
registerActivityLifecycleCallbacks(new ActivityLifecycleCallbacks() {
@Override
public void onActivityCreated(Activity activity, Bundle savedInstanceState) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " created");
}
@Override
public void onActivityStarted(Activity activity) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " started");
}
@Override
public void onActivityResumed(Activity activity) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " resumed");
}
@Override
public void onActivityPaused(Activity activity) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " paused");
}
@Override
public void onActivityStopped(Activity activity) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " stopped");
}
@Override
public void onActivitySaveInstanceState(Activity activity, Bundle outState) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " saved");
}
@Override
public void onActivityDestroyed(Activity activity) {
Log.i(LOG_UI, activity.getClass().getSimpleName() + " destroyed");
}
});
}
Oh and while you are in there, do yourself the favor and enable StrictMode for your debugging builds so that you bad dynamic behaviors of your app are logged.
if (BuildConfig.DEBUG) {
StrictMode.enableDefaults();
}
Modern apps are often revolving around just one activity but many fragments instead, so it's equally if not more important (due to their insane complex lifecycle) to be able to log fragment events. It can be done in a similar way, by overriding onAttachFragment() in a base class for your activities:
@Override
public void onAttachFragment(Fragment fragment){
Log.i(LOG_UI, "Fragment " + fragment.getClass().getSimpleName() + " attached to " + this.getClass().getSimpleName() );
}
Now you have an easy way to follow the UI flow of your application without which should help interpret the context of surrounding log messages. I find these major UI events to be important enough to deserve an "info" level classification. In fact, I also add various other UI/INFO level logging lines for menus etc, as in the following:
@Override
public boolean onNavigationItemSelected(MenuItem menuItem) {
Log.i(LOG_UI, "Option '" + menuItem.toString() + "' selected");
}
Logging templates
Android Studio is based on one of the most powerful IDE's available in modern programming so it also comes with handy templates. The logging templates available out of the box are context aware and will save you much time once you get used to them.
Simply enter the template characters and expand with the tab key. The templates "logm", "logr" and "logi" remains my favorites.
Don't log in production!
Logging is for development purposes - there are plenty of other tools for analytics and crash-reporting, so respect these separation of concerns and avoid compiling logging into your app. Only error, warning and info logs are acted upon at runtime, but verbose and debug levels are still compiled in. Regardless, there simply is no reason to keep any kind of logging for a production app - it's just unnecessary noise. I like to use ProGuard to strip the logging, which is a simple matter of adding the following to your ProGuard file:
-assumenosideeffects class android.util.Log {
public static boolean isLoggable(java.lang.String, int);
public static int e(...);
public static int w(...);
public static int i(...);
public static int d(...);
public static int v(...);
}
Note that if you are using other logging frameworks or custom wrappers, you may also want to target these explicitly to remove the bad weed "at the root" so to speak.
In conclusion
The IDE and associated toolbox is our friend, and we do best to get to know it well since much time and frustration can be saved on that account. Hopefully there's a trick or two in the above you take away from this blog post, but let me just end with showing a matrix I use conceptually when narrowing down a problem in an app based on the proposed logging levels and application aspects above.
The first matrix demonstrates filter settings when just wanting to following along and learn how the UI is put together when i.e. getting to know a new application. The second matrix is how you would think (and thus configure the logging) when wanting to screen an app quickly after a test suite has run, whether something exceptional happened anywhere. The last example shows how one would configure the filter when looking for issues in some app logic doing network communication.
Comments