Monday, February 3, 2014

Programmatically filtering your application's logs from Logcat output

Note: this post discusses filtering Logcat output on devices running Android prior to version 4.1. Starting from Android 4.1 applications are allowed to read only their own logs.

Logcat isn't much convenient when it comes to filtering your application logs. In fact, if you look at the logcat documentation, you will find that you can filter logcat output only by priority and/or tag fields:
A filter expression follows this format tag:priority ..., where tag indicates the tag of interest and priority indicates the minimum level of priority to report for that tag. Messages for that tag at or above the specified priority are written to the log. You can supply any number of tag:priority specifications in a single filter expression. The series of specifications is whitespace-delimited.
The android.util.Log class is your interface for printing your application logs to the Logcat system. Common print statement looks like this:
Log.e(TAG, "something bad happened");
Invoked method specifies the priority of the log record - in this example e stands for error, and TAG specifies well.. the tag.
 I commonly set the class name as a TAG using this statement:
private static final String TAG = ClassName.class.getCanonicalName();
Resolving the class name at run-time allows me to stay flexible and be adjusted to all the obfuscations made by Proguard processing.

But here's a problem: given a project with a hundred classes, how would you filter Logcat's output to print just your application's logs?
Additionally, what if you're using third-party libraries and would like to filter those logs as long as they run in context of your application?

I can think of three solutions to this problem:
  1. Specify a tag:priority pair for every single class in your project as a parameters to Logcat tool.
  2. Use application name as a TAG through all of your project's classes, and specify application_name:priority pair as a parameter to Logcat tool.
  3. Get all the Logcat's output and manually filter the logs.
The first option is obviously impractical - you're not going to spend rest of your life tapping all those class names. Second option is possible - but you loose the ability to specify more granular per-class filters. For both of these solutions you will have to find which tags your third-party libraries use and add them as a parameters to Logcat tool.
The third option can be a reasonable choice. However, it has its own drawbacks - the process ID may change once in a while (i.e. when you restart your application).

And if that's not enough, all three solutions contain inherent limitation: Logcat collects the logs in a series of circular buffers, which are usually limited to a few hundreds of killobytes. On my device, for example the buffer is limited to 256kb:
shell@android:/ $ logcat -g
logcat -g
/dev/log/main: ring buffer is 256Kb (255Kb consumed), max entry is 5120b, max payload is 4076b
/dev/log/system: ring buffer is 256Kb (255Kb consumed), max entry is 5120b, maxpayload is 4076b
If you don't want to miss any important events, then on your application startup you have to create a dedicated thread that in its turn will execute a logcat process, dump its output and filter it using one of the strategies I mentioned above.

Let's see how we can accomplish the third strategy - manually filter the logs by PID. From Logcat documentation:
Log messages contain a number of metadata fields, in addition to the tag and priority. You can modify the output format for messages so that they display a specific metadata field. To do so, you use the -v option and specify one of the supported output formats listed below.
...
threadtime — Display the date, invocation time, priority, tag, and the PID and TID of the thread issuing the message.
Log messages are clearly include the process ID field, so why Logcat doesn't expose the ability to filter by this field as well? I don't know the reasons behind this decision, but if you do - please shed some light by posting in the comments section. I would really love to understand it.

The implementation executes logcat command with -v threadtime parameters. Each line will include (among others) the process ID. I'm manually filtering the logcat output by the desired PID, and if matched I'm calling the LogFileWriter.write method that persists my application's log entry to a file. BufferedReader will always wait for additional logs to arrive and will never exit.
Remember that this method should be called from a separate thread, and will be responsible for redirecting Logcat logs of your application to a file.

package info.osom.logs;

import android.util.Log;

import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStreamReader;

public final class LogRetriever {

    private static final String TAG = LogRetriever.class.getCanonicalName();
    private static final String processId = Integer.toString(android.os.Process.myPid());

    public static void start(){
        try {
            String[] command = new String[] { "logcat", "-v", "threadtime" };

            Process process = Runtime.getRuntime().exec(command);

            BufferedReader bufferedReader = 
              new BufferedReader(new InputStreamReader(process.getInputStream()));

            String line;
            while ((line = bufferedReader.readLine()) != null){
                if(line.contains(processId)) {
                    LogFileWriter.write(line);
                }
            }
        }
        catch (IOException ex) {
            Log.e(TAG, "start failed", ex);
        }
    }
}

To summarize:
  1. The Logcat buffer limit was eliminated by using a dedicated thread.
  2. The filtering problem solved by manually filtering Logcat's output.

Things to inspect: manually filtering all the Logcat's output can be costly in terms of CPU resources consumed by a dedicated thread. I will do a benchmark to test the implications of this solution, and if they will be essential enough - I will use the second strategy, which puts the burden of filtering on Logcat process.

4 comments:

  1. String[] command = new String[] { "logcat", "-d", "threadtime" };
    This command only writes my app's log not device log.
    How can I get device complete log? Could you help me?

    ReplyDelete
    Replies
    1. You can't. See the note at the top of the post:
      "Starting from Android 4.1 applications are allowed to read only their own logs."

      Delete
  2. Can you please Share your "LogFileWriter" function?

    the function returns "log" what is that? a file?

    ReplyDelete
    Replies
    1. LogFileWriter#write should write the line to the file, you can search for such implementation over the Internet (I'm not including it because it is not the focus of the post).
      Changed the signature of a function - thanks for letting me know.

      Delete