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