The Purr of the LogCat
The Purr of the LogCat
The logcat facility is an essential debugging tool in Android because it displays a continuous stream of system messages and user-generated diagnostics.
User-generated logcat messages can be displayed by embedding commands of the form
Log.i(TAG, "Lat="+loc.getLatitude()+" long="+loc.getLongitude());
in the Java files, where TAG is a user-defined string variable (e.g., static final String TAG = "debug";) that can be used to filter the output messages and everything after the comma is a string that will be output as a line to the logcat stream, tagged by the string TAG. (See the documentation of Log.) The i on Log.i indicates that this is an informational message, and is associated with how the messages are filtered in the LogCat display. Other options are Log.v (verbose), Log.d (debug), Log.w (warning), and Log.e (error). In the following figure
these options are displayed as I, V, D, W, and E in the second column of the LogCat window, and particular categories of messages can be selected by clicking the corresponding symbols near the upper right. For example, if the circled E is clicked, only the error messages are displayed in the LogCat window.
Note: use Log.i rather than Log.d because the latter may not be displayed in logcat if you are debugging an actual device rather than an emulator.
If the logging screen is not displayed or iconized at the bottom of Eclipse (see above figure), display it using Window > Show View > Other, and then select Android > LogCat. Once displayed it can be iconized using the iconize symbol (short horizontal line at top right of LogCat window) and recalled by clicking the LogCat symbol (the Android icon) at the lower right of Eclipse; see the above figure.
However, the logging in the LogCat window of Eclipse is often not very useful since (at least for Linux) the custom filters available on the Eclipse interface don't always work and there is a huge volume of material scrolled through a tiny window (though the window can be resized). It is much more efficient to send log output to the screen or to a file where it can be scrolled and searched. From a shell, to send the output to the screen:
adb -e logcat -v time
or to redirect it to a file
adb -e logcat -v time > temp.txt
The -e flag specifies all events in the only running emulator (a -d flag specifies all events in the only running hardware device) and the -v time flag puts a time stamp on each event. You can of course use the filtering commands available in your shell to massage this information further. For example, with Linux,
adb -e logcat -v time | tee temp.txt
to both send the stream to a file and display on the screen, or
adb -e logcat -v time | grep filterTag
to display on the screen only the lines containing the string "filterTag". The logcat command itself has various options set through flags, including filtering, though I find that they are not reliable, at least under Linux. To clear the logs:
adb -e logcat -c
You can also use the standard Java print statements System.out.println() and printf() (which specifies output formats using syntax defined in the Formatter class) to generate formatted output that will appear in the logcat stream with the default category I and default tag "System.out". For example, the following are valid Android output statements:
System.out.println("pi = "+Math.PI);
System.out.printf("pi to 5 decimal places = %8.5f%n", Math.PI);
System.out.printf(Locale.FRANCE,
"pi to 3 decimal places in French notation = %6.3f%n", Math.PI);
They produce the following logcat output:
01-05 13:04:12.804 I/System.out(17057): pi = 3.141592653589793
01-05 13:04:12.804 I/System.out(17057): pi to 5 decimal places = 3.14159
01-05 13:04:12.809 I/System.out(17057): pi to 3 decimal places in French notation = 3,142
The println() statement accepts a string, which can usually be a concatenation of a string and other mathematical types like the double specified by Math.PI. The printf() statement has as its arguments an optional Locale (which tailors the format to that appropriate for the specified Locale), a string defining the desired output format, and a list of variables. In the first printf() statement above, %8.5f specifies a decimal format of width 8 places with 5 of those places after the decimal and %n is the line return for the system (see Formatter for a complete list of formatting options). The second printf() statement above specifies Locale.FRANCE as the Locale, which causes the decimal output to be formatted at it would in France, with commas instead of periods.
To format decimal numbers you can also use a utility method such as the following one, which
accepts a double d and returns a double rounded to decimalPlace decimal places.
// Method to round a double to fixed number of decimal places.
private static double rounded(double d, int decimalPlace){
BigDecimal bd = new BigDecimal(Double.toString(d));
bd = bd.setScale(decimalPlace,BigDecimal.ROUND_HALF_UP);
return bd.doubleValue();
}
Then the statement
System.out.println("pi = "+rounded(Math.PI, 4));
sends
pi = 3.1416 to the logcat output.
The qualifier static means that the method doesn't use instance variables or methods (a static method can use only parameters, local variables, static constants, other static methods within the same class). A method generally should be declared static if it meets these conditions. The qualifer private means that this method is not accessible to other classes. Methods should generally be declared private if they will only be used in the present class. |
The following figure shows the dreaded and completely uninformative message associated with the crash of an app launched from Eclipse on an actual device (Motorola Backflip phone running Android 1.5).
This program has been tested and usually runs correctly, but the failure was triggered by a sequence of actions different from that for the usual use of the program.
If following this crash (or before) we issue in a shell
adb -d logcat -v time
(the -d flag assumes that this is the only physical device connected), we obtain the log associated with activity on the phone. Near the end of that output we find the following lines, with times given up to milliseconds
06-09 12:18:21.766 I/ActivityManager( 91): Displayed activity com.lightcone.maptutorial/.MapTutorial: 473 ms
06-09 12:18:21.846 I/GPStest ( 2546): GPS position changed: oldLat=35.956549 oldLong=-83.92517328 newLat=35.956549 newLong=-83.92517328
06-09 12:18:21.846 W/dalvikvm( 2546): threadid=3: thread exiting with uncaught exception (group=0x4000ff28)
06-09 12:18:21.856 E/AndroidRuntime( 2546): Uncaught handler: thread main exiting due to uncaught exception
06-09 12:18:21.856 E/AndroidRuntime( 2546): java.lang.NullPointerException
06-09 12:18:21.856 E/AndroidRuntime( 2546): at com.lightcone.maptutorial.MapTutorial.onLocationChanged(MapTutorial.java:596)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.location.LocationManager$ListenerTransport._handleMessage(LocationManager.java:184)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.location.LocationManager$ListenerTransport.access$000(LocationManager.java:117)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.location.LocationManager$ListenerTransport$1.handleMessage(LocationManager.java:133)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.os.Handler.dispatchMessage(Handler.java:99)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.os.Looper.loop(Looper.java:123)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at android.app.ActivityThread.main(ActivityThread.java:3977)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at java.lang.reflect.Method.invokeNative(Native Method)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at java.lang.reflect.Method.invoke(Method.java:521)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:782)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:540)
06-09 12:18:21.856 E/AndroidRuntime( 2546): at dalvik.system.NativeStart.main(Native Method)
This is much more informative! The first line indicates that the phone launched an activity MapTutorial and the second line is a user-generated diagnostic output indicating that 80 milliseconds later there was a GPS position-change event. This second line was generated by line 596 in the following block of code in the Java file MapTutorial.java
583 public void onLocationChanged(Location arg0) {
584 double oldLat = 0;
585 double oldLong = 0;
586 if(loc != null){
587 oldLat = loc.getLatitude();
588 oldLong = loc.getLongitude();
589 }
590 // If the location has changed, center the map on the new location
591 loc = locman.getLastKnownLocation(provider);
592 if(loc != null){
593 double lat = loc.getLatitude();
594 double lon = loc.getLongitude();
595 Log.i(TAG, "GPS position changed: oldLat="+oldLat+" oldLong="+oldLong+" newLat="+lat+" newLong="+lon);
596 route.putLocation(new GeoPoint((int)(loc.getLatitude()*1e6), (int)(loc.getLongitude()*1e6)));
597 centerOnLocation();
598
599 // GPS Satellite accuracy (meters)
600 if(loc.hasAccuracy()){
601 satAccuracy = loc.getAccuracy();
602 Log.i(TAG,"Accuracy="+satAccuracy+" meters");
603 route.putSatInfo(numberSats,satAccuracy);
604 }
605 }
606 }
The I/GPStest tag on the corresponding line in the logcat output is because it was generated by a user-inserted Log.i command (the I) in line 595, and the GPStest part is because earlier in this file we find the definition
27 String TAG = "GPStest";
Everything appears normal until this point, but in the next logcat line we see that immediately (less than 1 millisecond later) the Dalvik virtual machine issues a warning (tagged W/dalvikvm) that it is terminating execution of a thread because of an uncaught exception. In the following lines we see that the Android runtime promptly issues an error message (tagged E/AndroidRuntime) indicating a nullPointerException---we have tried to operate on something that does not exist---and follows with a series of lines indicating exactly where in the Java code the exception occurred: It is in line 596 of the Java file MapTutorial.java, which is within the method onLocationChanged (the lines after that in the logcat output trace in sequence how that method was invoked, when read in reverse order).
So this gives us a lot of information about what caused the error: we now know that it is precipitated by the line
596 route.putLocation(new GeoPoint((int)(loc.getLatitude()*1e6),
(int)(loc.getLongitude()*1e6)));
in the method onLocationChanged of the file MapTutorial.java, and our sleuthing suggests that it is associated in some way with detection of a GPS location change that triggers an action on something that does not exist at this point. Since the program was running normally before this crash, and performs correctly in most circumstances, it is further implied that this is not a general outcome of such an event but is because of a particular set of circumstances that occurred in this example.
The two user-defined objects associated with line 596 are loc, which is an Android Location object (instantiation of the class android.location.Location), and route, which is an instance of the user-defined RouteSegmentOverlay class. In line 591 we see that the value of loc has been set by invoking the getLastKnownLocation() method of locman, which is an instantiation of the Android class android.location.LocationManager. Consulting the documentation for the LocationManager class, we find that the variable loc can indeed be null because getLastKnownLocation() can return null (for example, if the location provider does not exist). But the programmer, savvy dude that he is, must have anticipated this because the offending statement 596 is enclosed in an if-statement that permits it to be executed only if loc is not null (see line 592); furthermore, that loc is not null is confirmed by the sensible diagnostic logcat output of line 595 for the latitude and longitude derived from the loc object. Thus, we are led to suspect the route object: a particular situation must have been encountered in which route was null when we tried to invoke its putLocation() method in line 596.
This was an actual bug in an actual program and the above diagnosis was confirmed by inserting a line
if(route == null) Log.i(TAG,"Problem: route is null");
before line 592 in the preceding code. The simple cure for this bug was to change line 592 to
592 if(loc != null && route != null){
Calling something before it is created is a likely indication of some faulty logic in organization of the code that should perhaps be corrected. However, testing of the above fix indicated that it was adequate since the statements to be executed are only relevant if the route object exists.
This, by the way, illustrates a type of bug that is common on Android-powered devices
such as smart phones if they are not programmed carefully because
|
Attempting to manipulate a null quantity will often generate an exception in short order. The standard guards against such errors are testing logically for null values before performing operations that are not valid on null objects, and the use of try-catch enclosures to catch and process exceptions gracefully if they do occur.