docs/android_logging.md

   1 # Logging #
   2
   3 [TOC]
   4
   5
   6 ## Overview
   7
   8 Logging used to be done using Android's [android.util.Log]
   9 (http://developer.android.com/reference/android/util/Log.html).
  10
  11 A wrapper on that is now available: org.chromium.base.Log. It is designed to
  12 write logs as belonging to logical groups going beyond single classes, and to
  13 make it easy to switch logging on or off for individual groups.
  14
  15 Usage:
  16
  17 ```java
  18 private static final String TAG = "YourModuleTag";
  19 ...
  20 Log.i(TAG, "Logged INFO message.");
  21 Log.d(TAG, "Some DEBUG info: %s", data);
  22 ```
  23
  24 Output:
  25
  26 ```
  27 I/cr_YourModuleTag: ( 999): Logged INFO message
  28 D/cr_YourModuleTag: ( 999): [MyClass.java:42] Some DEBUG info: data.toString
  29 ```
  30
  31 Here, **TAG** will be a feature or package name, "MediaRemote" or "NFC" for
  32 example. In most cases, the class name is not needed. It will be prepended by
  33 the "cr_" prefix to make obvious which logs are coming from Chrome.
  34
  35 ### Verbose and Debug logs have special handling ###
  36
  37 *   `Log.v` and `Log.d` Calls made using `org.chromium.base.Log` are stripped
  38     out of production binaries using Proguard. There is no way to get those logs
  39     in release builds.
  40
  41 *   The file name and line number will be prepended to the log message.
  42     For higher priority logs, those are not added for performance concerns.
  43
  44 ### An exception trace is printed when the exception is the last parameter ###
  45
  46 As with `java.util.Log`, putting a throwable as last parameter will dump the
  47 corresponding stack trace:
  48
  49 ```java
  50 Log.i(TAG, "An error happened: %s", e)
  51 ```
  52
  53 ```
  54 I/cr_YourModuleTag: ( 999): An error happened: This is the exception's message
  55 I/cr_YourModuleTag: ( 999): java.lang.Exception: This is the exception's message
  56 I/cr_YourModuleTag: ( 999):     at foo.bar.MyClass.test(MyClass.java:42)
  57 I/cr_YourModuleTag: ( 999):     ...
  58 ```
  59
  60 Having the exception as last parameter doesn't prevent it from being used for
  61 string formatting.
  62
  63 ## Logging Best Practices
  64
  65 ### Rule #1: Never log PII (Personal Identification Information):
  66
  67 This is a huge concern, because other applications can access the log and
  68 extract a lot of data from your own by doing so. Even if JellyBean restricted
  69 this, people are going to run your application on rooted devices and allow some
  70 apps to access it. Also anyone with USB access to the device can use ADB to get
  71 the full logcat and get the same data right now.
  72
  73 If you really need to print something , print a series of Xs instead
  74 (e.g. "XXXXXX"), or print a truncated hash of the PII instead. Truncation is
  75 required to make it harder for an attacker to recover the full data through
  76 rainbow tables and similar methods.
  77
  78 Similarly, avoid dumping API keys, cookies, etc...
  79
  80 ### Rule #2: Do not build debug logs in production code:
  81
  82 The log methods are removed in release builds using Proguard. Because log
  83 messages might not be written, the cost of creating them should also be avoided.
  84 This can be done using three complementary ways:
  85
  86 #### Use string formatting instead of concatenations
  87
  88 ```java
  89 // BAD
  90 Log.d(TAG, "I " + preference + " writing logs.");
  91
  92 // BETTER
  93 Log.d(TAG, "I %s writing logs.", preference);
  94 ```
  95
  96 Proguard removes the method call itself, but doesn't do anything about the
  97 arguments. The method's arguments will still be computed and provided as
  98 input. The first call above will always lead to the creation of a
  99 `StringBuilder` and a few concatenations, while the second just passes the
 100 arguments and won't need that.
 101
 102 #### Guard expensive calls
 103
 104 Sometimes the values to log aren't readily available and need to be computed
 105 specially. This should be avoided when logging is disabled.
 106
 107 ```java
 108 static private final boolean DEBUG = false;  // debug toggle.
 109 ...
 110 if (DEBUG) {
 111   Log.i(TAG, createThatExpensiveLogMessage(activity))
 112 }
 113 ```
 114
 115 Because the variable is a `static final` that can be evaluated at compile
 116 time, the Java compiler will optimize out all guarded calls from the
 117 generated `.class` file. Changing it however requires editing each of the
 118 files for which debug should be enabled and recompiling.
 119
 120 #### Annotate debug functions with the `@RemovableInRelease` annotation.
 121
 122 That annotation tells Proguard to assume that a given function has no side
 123 effects, and is called only for its returned value. If this value is unused,
 124 the call will be removed. If the function is not called at all, it will also
 125 be removed. Since Proguard is already used to strip debug and verbose calls
 126 out of release builds, this annotation allows it to have a deeper action by
 127 removing also function calls used to generate the log call's arguments.
 128
 129 ```java
 130 /* If that function is only used in Log.d calls, proguard should
 131  * completely remove it from the release builds. */
 132 @RemovableInRelease
 133 private static String getSomeDebugLogString(Thing[] things) {
 134   StringBuilder sb = new StringBuilder(
 135       "Reporting " + thing.length + " things: ");
 136   for (Thing thing : things) {
 137     sb.append('\n').append(thing.id).append(' ').append(report.foo);
 138   }
 139   return sb.toString();
 140 }
 141
 142 public void bar() {
 143   ...
 144   Log.d(TAG, getSomeDebugLogString(things)); /* The line is removed in
 145                                               *  release builds. */
 146 }
 147 ```
 148
 149 Again, this is useful only if the input to that function are variables
 150 already available in the scope. The idea is to move computations,
 151 concatenations, etc. to a place where that can be removed when not needed,
 152 without invading the main function's logic. It can then have a similar
 153 effect as guarding with a static final property that would be enabled in
 154 Debug and disabled in Release.
 155
 156 ### Rule #3: Favor small log messages
 157
 158 This is still related to the global fixed-sized kernel buffer used to keep all
 159 logs. Try to make your log information as terse as possible. This reduces the
 160 risk of pushing interesting log data out of the buffer when something really
 161 nasty happens. It's really better to have a single-line log message, than
 162 several ones. I.e. don't use:
 163
 164 ```java
 165 Log.GROUP.d(TAG, "field1 = %s", value1);
 166 Log.GROUP.d(TAG, "field2 = %s", value2);
 167 Log.GROUP.d(TAG, "field3 = %s", value3);
 168 ```
 169
 170 Instead, write this as:
 171
 172 ```java
 173 Log.d(TAG, "field1 = %s, field2 = %s, field3 = %s", value1, value2, value3);
 174 ```
 175
 176 That doesn't seem to be much different if you count overall character counts,
 177 but each independent log entry also implies a small, but non-trivial header, in
 178 the kernel log buffer. And since every byte count, you can also try something
 179 even shorter, as in:
 180
 181 ```java
 182 Log.d(TAG, "fields [%s,%s,%s]", value1, value2, value3);
 183 ```
 184
 185 ## Filtering logs
 186
 187 Logcat allows filtering by specifying tags and the associated level:
 188
 189 ```shell
 190 adb logcat [TAG_EXPR:LEVEL]...
 191 adb logcat cr_YourModuleTag:D *:S
 192 ```
 193
 194 This shows only logs having a level higher or equal to DEBUG for
 195 `cr_YourModuleTag`, and SILENT (nothing is logged at this level or higher, so it
 196 silences the tags) for everything else. You can persist a filter by setting an
 197 environment variable:
 198
 199 ```shell
 200 export ANDROID_LOG_TAGS="cr_YourModuleTag:D *:S"
 201 ```
 202
 203 For more, see the [related page on developer.android.com]
 204 (http://developer.android.com/tools/debugging/debugging-log.html#filteringOutput)