Android logging put to bed.

I've been developing an android application recently, and I have had to scrabble around more than I should have in order to get logging working correctly so here's what I've learned.

How to get logging working; The basics.

Android has a Log class that you can use to make log entries. You can find that here;

https://developer.android.com/reference/android/util/Log.html

Here's an example of a log entry made from an Activity

#import android.util.Log;

class MyActivity{

    private static final String TAG = "MyActivity";

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        Log.v(TAG, "savedInstanceState contains " + savedInstanceState.size() + " mappings");
        ......
    }
}

The Log.v call makes a 'verbose' log entry. Log levels (in increasing order of 'importance' are;
    ERROR, WARN, INFO, DEBUG, VERBOSE
These entries are made with Log.e, Log.w, Log.i, Log.d & Log.v.

So far so good! So, you've littered your code with debug and verbose log entries, pushed your app to an emulator or attached device and you're running logcat (https://developer.android.com/tools/help/logcat.html). 

Woah! Hang on! Where are those verbose and debug log entries from your app? They're no where to be seen, and the reason is that you need to set some system properties on your phone or emulator to control the log levels generated by your application. You can do this in one of two ways;

1. Use adb shell to set the property on the phone - this will persist until the phone or emulator is shutdown or turned off.
   
   adb shell setprop log.tag.<TAG> <LOG LEVEL>
   
   So in our example we'd run;
   
   adb shell setprop log.tag.MyActivity VERBOSE
2. If your phone is rooted you can push a local.prop file to it containing the log level properties.
   
   local.prop file;
   
   log.tag.MyActivity=VERBOSE
   
   Push it to your phone/emulator using;
   
   adb push <source> <target>
   
   In our example;
   
   adb push ./local.prop /data/local.prop
   
   Note that you need the file name of the target too.
   
   There is one more undocumented step you need to make here to get this method working. After much digging around and scratching of head I found a comment by digital ronin on stack overflow that suggested that local.prop is ignored on later versions of android if it is world or group writeable. So you need to then go on to change the permissions of your local prop file.
   
   adb chmod 664 /data/local.prop
   
   You will now need to restart your phone or emulator as the local.prop file is only read on start up.
   
   adb reboot

So now when we run our app and connect via logcat we should see our verbose output. However, we need to apply a reasonable logcat filter so that we don't drown in system debug log messages. I start mine with filters via a script like this;


startlogcat.sh


#!/bin/bash
if [ $# -ne 1 ]; then
    echo "Please pass in the emulator name. Get this using adb -device"
    exit 1
fi

echo "Starting logcat for emulator $1."

adb -s $1 logcat MainActivity:D SendLocationAuthAct:V SmsReceiver:V PhoneLocation:V MainActivity:V *:W


This gives me verbose output for some of my modules, and only warnings and above for everything else (e.g. the dalvikvm for example).

My preferred approach to logging.

So now we have the basics working how about the finer details? How should we actually use logging? In the android log javadoc page there is a word of warning regarding the overheads associated with logging. In our previous example;

#import android.util.Log;

class MyActivity{

    private static final String TAG = "MyActivity";

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        Log.v(TAG, "savedInstanceState contains " + savedInstanceState.size() + " mappings");
        ......
    }
}

We can see that regardless of whether the verbose log entry will be seen or not we incur the overhead of building the log string. Under the hood StringBuilder is being used to convert

"savedInstanceState contains " + savedInstanceState.size() + " mappings"

into a single string. We can prevent this using a call to determine if the log level we're logging at is enabled.

if(Log.isLoggable(TAG, Log.VERBOSE)){
     Log.v(TAG, "savedInstanceState contains " + savedInstanceState.size() + " mappings");
}
Which is much better from an efficiency point of view. However, our log entries are getting a little ugly now. Surely there's a better way?

I've long been a fan of slf4j and it's approach to logging so I've built myself a facade for the android log that allows me to write log entries like this;

#include com.boho.android.logr;
class MyActivity{

    private final Logr log = new Logr("MyActivity");

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        log.verbose("savedInstanceState contains {} mappings", savedInstanceState.size());
        ......
    }
}


This is much better! Inside the Logr class the variable substitution is done and the string is built up, but only if verbose logging is enabled;

public class Logr{

    private final String tag;
    private final Pattern p;

    public Logr(String logTag){
        tag = logTag;
        p = Pattern.compile("\\{\\}");
    }

    public void verbose(String msg, Object arg){
        if(Log.isLoggable(tag, AndroidLogIf.VERBOSE)){
            Log.v(tag, getLogStr(msg, arg));
        }
    }



    public void getLogStr(String msg, String arg0){
        .... argument substitution using regex
    }
} 

So, there we have it. Pretty and efficient android log entries. Enjoy!