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