Chromium Code Reviews| Index: docs/android_logging.md |
| diff --git a/docs/android_logging.md b/docs/android_logging.md |
| new file mode 100644 |
| index 0000000000000000000000000000000000000000..3068dc5409da074d9d53d34e8f9273b95c18b277 |
| --- /dev/null |
| +++ b/docs/android_logging.md |
| @@ -0,0 +1,203 @@ |
| +# Logging # |
|
Bernhard Bauer
2015/09/02 10:40:15
I wonder why this doesn't show up as a move...
dgn
2015/09/02 10:57:50
I did a bunch of changes to make it 80 char lines,
dgn
2015/09/02 11:03:10
shows as move with `git cl upload --similarity 10`
|
| + |
| +[TOC] |
| + |
| + |
| +## Overview |
| + |
| +Logging used to be done using Android's [android.util.Log] |
| +(http://developer.android.com/reference/android/util/Log.html). |
| + |
| +A wrapper on that is now available: org.chromium.base.Log. It is designed to |
| +write logs as belonging to logical groups going beyond single classes, and to |
| +make it easy to switch logging on or off for individual groups. |
| + |
| +Usage: |
| + |
| +```java |
| +private static final String TAG = "cr.YourModuleTag"; |
| +... |
| +Log.i(TAG, "Logged INFO message."); |
| +Log.d(TAG, "Some DEBUG info: %s", data); |
| +``` |
| + |
| +Output: |
| + |
| +``` |
| +I/cr.YourModuleTag: ( 999): Logged INFO message |
| +D/cr.YourModuleTag: ( 999): [MyClass.java:42] Some DEBUG info: data.toString |
| +``` |
| + |
| +Here, **TAG** will be a feature or package name, "MediaRemote" or "NFC" for |
| +example. In most cases, the class name is not needed. |
| + |
| +### Verbose and Debug logs have special handling ### |
| + |
| +* `Log.v` and `Log.d` Calls made using `org.chromium.base.Log` are stripped |
| + out of production binaries using Proguard. There is no way to get those logs |
| + in release builds. |
| + |
| +* The file name and line number will be prepended to the log message. |
| + For higher priority logs, those are not added for performance concerns. |
| + |
| +### An exception trace is printed when the exception is the last parameter ### |
| + |
| +As with `java.util.Log`, putting a throwable as last parameter will dump the |
| +corresponding stack trace: |
| + |
| +```java |
| +Log.i(TAG, "An error happened: %s", e) |
| +``` |
| + |
| +``` |
| +I/cr.YourModuleTag: ( 999): An error happened: This is the exception's message |
| +I/cr.YourModuleTag: ( 999): java.lang.Exception: This is the exception's message |
| +I/cr.YourModuleTag: ( 999): at foo.bar.MyClass.test(MyClass.java:42) |
| +I/cr.YourModuleTag: ( 999): ... |
| +``` |
| + |
| +Having the exception as last parameter doesn't prevent it from being used for |
| +string formatting. |
| + |
| +## Logging Best Practices |
| + |
| +### Rule #1: Never log PII (Personal Identification Information): |
| + |
| +This is a huge concern, because other applications can access the log and |
| +extract a lot of data from your own by doing so. Even if JellyBean restricted |
| +this, people are going to run your application on rooted devices and allow some |
| +apps to access it. Also anyone with USB access to the device can use ADB to get |
| +the full logcat and get the same data right now. |
| + |
| +If you really need to print something , print a series of Xs instead |
| +(e.g. "XXXXXX"), or print a truncated hash of the PII instead. Truncation is |
| +required to make it harder for an attacker to recover the full data through |
| +rainbow tables and similar methods. |
| + |
| +Similarly, avoid dumping API keys, cookies, etc... |
| + |
| +### Rule #2: Do not build debug logs in production code: |
| + |
| +The log methods are removed in release builds using Proguard. Because log |
| +messages might not be written, the cost of creating them should also be avoided. |
| +This can be done using three complementary ways: |
| + |
| +#### Use string formatting instead of concatenations |
| + |
| +```java |
| +// BAD |
| +Log.d(TAG, "I " + preference + " writing logs."); |
| + |
| +// BETTER |
| +Log.d(TAG, "I %s writing logs.", preference); |
| +``` |
| + |
| +Proguard removes the method call itself, but doesn't do anything about the |
| +arguments. The method's arguments will still be computed and provided as |
| +input. The first call above will always lead to the creation of a |
| +`StringBuilder` and a few concatenations, while the second just passes the |
| +arguments and won't need that. |
| + |
| +#### Guard expensive calls |
| + |
| +Sometimes the values to log aren't readily available and need to be computed |
| +specially. This should be avoided when logging is disabled. |
| + |
| +```java |
| +static private final boolean DEBUG = false; // debug toggle. |
| +... |
| +if (DEBUG) { |
| + Log.i(TAG, createThatExpensiveLogMessage(activity)) |
| +} |
| +``` |
| + |
| +Because the variable is a `static final` that can be evaluated at compile |
| +time, the Java compiler will optimize out all guarded calls from the |
| +generated `.class` file. Changing it however requires editing each of the |
| +files for which debug should be enabled and recompiling. |
| + |
| +#### Annotate debug functions with the `@RemovableInRelease` annotation. |
| + |
| +That annotation tells Proguard to assume that a given function has no side |
| +effects, and is called only for its returned value. If this value is unused, |
| +the call will be removed. If the function is not called at all, it will also |
| +be removed. Since Proguard is already used to strip debug and verbose calls |
| +out of release builds, this annotation allows it to have a deeper action by |
| +removing also function calls used to generate the log call's arguments. |
| + |
| +```java |
| +/* If that function is only used in Log.d calls, proguard should |
| + * completely remove it from the release builds. */ |
| +@RemovableInRelease |
| +private static String getSomeDebugLogString(Thing[] things) { |
| + StringBuilder sb = new StringBuilder( |
| + "Reporting " + thing.length + " things: "); |
| + for (Thing thing : things) { |
| + sb.append('\n').append(thing.id).append(' ').append(report.foo); |
| + } |
| + return sb.toString(); |
| +} |
| + |
| +public void bar() { |
| + ... |
| + Log.d(TAG, getSomeDebugLogString(things)); /* The line is removed in |
| + * release builds. */ |
| +} |
| +``` |
| + |
| +Again, this is useful only if the input to that function are variables |
| +already available in the scope. The idea is to move computations, |
| +concatenations, etc. to a place where that can be removed when not needed, |
| +without invading the main function's logic. It can then have a similar |
| +effect as guarding with a static final property that would be enabled in |
| +Debug and disabled in Release. |
| + |
| +### Rule #3: Favor small log messages |
| + |
| +This is still related to the global fixed-sized kernel buffer used to keep all |
| +logs. Try to make your log information as terse as possible. This reduces the |
| +risk of pushing interesting log data out of the buffer when something really |
| +nasty happens. It's really better to have a single-line log message, than |
| +several ones. I.e. don't use: |
| + |
| +```java |
| +Log.GROUP.d(TAG, "field1 = %s", value1); |
| +Log.GROUP.d(TAG, "field2 = %s", value2); |
| +Log.GROUP.d(TAG, "field3 = %s", value3); |
| +``` |
| + |
| +Instead, write this as: |
| + |
| +```java |
| +Log.d(TAG, "field1 = %s, field2 = %s, field3 = %s", value1, value2, value3); |
| +``` |
| + |
| +That doesn't seem to be much different if you count overall character counts, |
| +but each independent log entry also implies a small, but non-trivial header, in |
| +the kernel log buffer. And since every byte count, you can also try something |
| +even shorter, as in: |
| + |
| +```java |
| +Log.d(TAG, "fields [%s,%s,%s]", value1, value2, value3); |
| +``` |
| + |
| +## Filtering logs |
| + |
| +Logcat allows filtering by specifying tags and the associated level: |
| + |
| +```shell |
| +adb logcat [TAG_EXPR:LEVEL]... |
| +adb logcat cr.YourModuleTag:D *:S |
| +``` |
| + |
| +This shows only logs having a level higher or equal to DEBUG for |
| +`cr.YourModuleTag`, and SILENT (nothing is logged at this level or higher, so it |
| +silences the tags) for everything else. You can persist a filter by setting an |
| +environment variable: |
| + |
| +```shell |
| +export ANDROID_LOG_TAGS="cr.YourModuleTag:D *:S" |
| +``` |
| + |
| +For more, see the [related page on developer.android.com] |
| +(http://developer.android.com/tools/debugging/debugging-log.html#filteringOutput) |