Using Log.v, LogCat and Filters when debugging an Android Application

When debugging an Android Application one of the most useful tools is Log.v. This is a means of sending debug messages to the log file, which can be read in real-time with LogCat. I will illustrate this using a real bug in the Android Notepad tutorial.

If you have been following this blog you will now have a version of Notepad (NotepadV4) that makes it easy to add edit and delete Notes. If you run it in the emulator, chose the DDMS perspective in Java and select the emulator then you will see LogCat showing the log messages from Android.


Try editing a number of notes within the Notepad application. After editing 4 the following error messages appeared in LogCat. I have maxmised the LogCat Window as the error messages are quite long.


The crucial error messages are:

06-07 14:54:31.530: ERROR/Database(221): java.lang.IllegalStateException: /data/data/my.android.demo.notepad4/databases/data SQLiteDatabase created and never closed

and

06-07 14:54:31.530: ERROR/Database(221): at my.android.demo.notepad4.NotesDbAdapter.open(NotesDbAdapter.java:102)

To debug this lets write a log message each time we open a database, and each time we close it. To start with import android.util.Log and define a constant to use as a tag for the log item in each class that opens a database.

import android.util.Log;

public static final String LOG_TAG = "Notepadv4";

Initially I tried to have the tag equal to the name of the compilation unit so I could immediately see where the database was being opened. Unfortunately there does not appear to be any way of including an OR clause or wild card in a LogCat filter so I had to abandon this approach and use the application name as the tag for all log messages I was writing.

Now start by doing a find for .open within Notepadv4.java. You will get a hit on line 50. Now use Eclipse’s search facility to find all occurrences of the method.



You will find 2, the first in NotepadV4 which opens the database when the activity is first started, and the second which opens the database each time the class NoteEdit()is invoked. Add a line above each method:

Log.v(LOG_TAG, "opening database… ");

If you repeat the process for .close you will not get any hits, which reveals the source of the problem. Presumably the author thought that the database would be closed automatically when the finish() method was called – but this does not appear to be the case. finish() will cause the onPause, onStop and onDestroy methods to be invoked, so add the following onDestroy method to the NoteEdit Class.

@Override
protected void onDestroy(){
super.onDestroy();
Log.v(LOG_TAG,"closing database...");
mDbHelper.close();
}

Again using LogCat to see the log messages from the emulator - amongst all the log messages you can see the log message from the database being opened as NotepadV4 is invoked. It is in black and has severity V, and the Notepadv4 logtag.



We want to filter out our Log messages from all the others, so create a filter by clicking on the green + symbol on the upper right of the LogCat window.


Then as we run NotepadV4 the filter allows us to see the messages confirming that the database is being opened and closed appropriately.



Note that the filter removes the log messages from the log window rather than duplicating them. If you do not see any log messages you haven't given the LogCat Window the appropriate focus by clicking on the emulator in the left hand window of the DDMS perspective.