| OLD | NEW |
| (Empty) |
| 1 ## Logging ## | |
| 2 | |
| 3 Logging used to be done using Android's [android.util.Log] | |
| 4 (http://developer.android.com/reference/android/util/Log.html). | |
| 5 | |
| 6 A wrapper on that is now available: org.chromium.base.Log. It is designed to wri
te logs as | |
| 7 belonging to logical groups going beyond single classes, and to make it easy to
switch logging on | |
| 8 or off for individual groups. | |
| 9 | |
| 10 Usage: | |
| 11 | |
| 12 private static final String TAG = "cr.YourModuleTag"; | |
| 13 ... | |
| 14 Log.i(TAG, "Logged INFO message."); | |
| 15 Log.d(TAG, "Some DEBUG info: %s", data); | |
| 16 | |
| 17 Output: | |
| 18 | |
| 19 I/cr.YourModuleTag: ( 999): Logged INFO message | |
| 20 D/cr.YourModuleTag: ( 999): [MyClass.java:42] Some DEBUG info: data's toStri
ng output | |
| 21 | |
| 22 Here, **TAG** will be a feature or package name, "MediaRemote" or "NFC" for exam
ple. In most | |
| 23 cases, the class name is not needed. | |
| 24 | |
| 25 **Caveat:** Property keys are limited to 23 characters. If the tag is too long,
`Log#isLoggable` | |
| 26 throws a RuntimeException. | |
| 27 | |
| 28 ### Verbose and Debug logs have special handling ### | |
| 29 | |
| 30 * `Log.v` and `Log.d` Calls made using `org.chromium.base.Log` are stripped | |
| 31 out of production binaries using Proguard. There is no way to get those logs | |
| 32 in release builds. | |
| 33 | |
| 34 * The file name and line number will be prepended to the log message. | |
| 35 For higher priority logs, those are not added for performance concerns. | |
| 36 | |
| 37 * By default, Verbose and Debug logs are not enabled, see guarding: | |
| 38 | |
| 39 ### Log calls are guarded: Tag groups can be enabled or disabled using ADB ### | |
| 40 | |
| 41 adb shell setprop log.tag.cr.YourModuleTag <LEVEL> | |
| 42 | |
| 43 Level here is either `VERBOSE`, `DEBUG`, `INFO`, `WARN`, `ERROR`, `ASSERT`, or `
SUPPRESS` | |
| 44 By default, the level for all tags is `INFO`. | |
| 45 | |
| 46 ### An exception trace is printed when the exception is the last parameter ### | |
| 47 | |
| 48 As with `java.util.Log`, putting a throwable as last parameter will dump the cor
responding stack | |
| 49 trace: | |
| 50 | |
| 51 Log.i(TAG, "An error happened: %s", e) | |
| 52 | |
| 53 I/cr.YourModuleTag: ( 999): An error happened: This is the exception's messa
ge | |
| 54 I/cr.YourModuleTag: ( 999): java.lang.Exception: This is the exception's mes
sage | |
| 55 I/cr.YourModuleTag: ( 999): at foo.bar.MyClass.test(MyClass.java:42) | |
| 56 I/cr.YourModuleTag: ( 999): ... | |
| 57 | |
| 58 Having the exception as last parameter doesn't prevent it from being used for st
ring formatting. | |
| 59 | |
| 60 ### Logging Best Practices | |
| 61 | |
| 62 #### Rule #1: Never log PII (Personal Identification Information): | |
| 63 | |
| 64 This is a huge concern, because other applications can access the log and extrac
t a lot of data | |
| 65 from your own by doing so. Even if JellyBean restricted this, people are going t
o run your | |
| 66 application on rooted devices and allow some apps to access it. Also anyone with
USB access to the | |
| 67 device can use ADB to get the full logcat and get the same data right now. | |
| 68 | |
| 69 If you really need to print something , print a series of Xs instead (e.g. "XXXX
XX"), or print a | |
| 70 truncated hash of the PII instead. Truncation is required to make it harder for
an attacker to | |
| 71 recover the full data through rainbow tables and similar methods. | |
| 72 | |
| 73 Similarly, avoid dumping API keys, cookies, etc... | |
| 74 | |
| 75 #### Rule #2: Do not write debug logs in production code: | |
| 76 | |
| 77 The kernel log buffer is global and of limited size. Any extra debug log you add
to your activity | |
| 78 or service makes it more difficult to diagnose problems on other parts of the sy
stem, because they | |
| 79 tend to push the interesting bit out of the buffer too soon. This is a recurring
problem on | |
| 80 Android, so avoid participating into it. | |
| 81 | |
| 82 Logs can be disabled using system properties. Because log messages might not be | |
| 83 written, the cost of creating them should also be avoided. This can be done usin
g three | |
| 84 complementary ways: | |
| 85 | |
| 86 - Use string formatting instead of concatenations | |
| 87 | |
| 88 // BAD | |
| 89 Log.d(TAG, "I " + preference + " writing logs."); | |
| 90 | |
| 91 // BETTER | |
| 92 Log.d(TAG, "I %s writing logs.", preference); | |
| 93 | |
| 94 If logging is disabled, the function's arguments will still have to be compu
ted and provided | |
| 95 as input. The first call above will always lead to the creation of a `String
Builder` and a few | |
| 96 concatenations, while the second just passes the arguments and won't need th
at. | |
| 97 | |
| 98 - Guard expensive calls | |
| 99 | |
| 100 Sometimes the values to log aren't readily available and need to be computed
specially. This | |
| 101 should be avoided when logging is disabled. | |
| 102 | |
| 103 Using `Log#isLoggable` will return whether logging for a specific tag is all
owed or not. It is | |
| 104 the call used inside the log functions and using allows to know when running
the expensive | |
| 105 functions is needed. | |
| 106 | |
| 107 if (Log.isLoggable(TAG, Log.DEBUG) { | |
| 108 Log.d(TAG, "Something happened: %s", dumpDom(tab)); | |
| 109 } | |
| 110 | |
| 111 For more info, See the [android framework documentation] | |
| 112 (http://developer.android.com/tools/debugging/debugging-log.html). | |
| 113 | |
| 114 Using a debug constant is a less flexible, but more perfomance oriented alte
rnative. | |
| 115 | |
| 116 static private final boolean DEBUG = false; // set to 'true' to enable
debug | |
| 117 ... | |
| 118 if (DEBUG) { | |
| 119 Log.i(TAG, createThatExpensiveLogMessage(activity)) | |
| 120 } | |
| 121 | |
| 122 Because the variable is a `static final` that can be evaluated at compile ti
me, the Java | |
| 123 compiler will optimize out all guarded calls from the generated `.class` fil
e. Changing it | |
| 124 however requires editing each of the files for which debug should be enabled
and recompiling, | |
| 125 while the previous method can enable or disable debugging for a whole featur
e without changing | |
| 126 any source file. | |
| 127 | |
| 128 - Annotate debug functions with the `@RemovableInRelease` annotation. | |
| 129 | |
| 130 That annotation tells Proguard to assume that a given function has no side e
ffects, and is | |
| 131 called only for its returned value. If this value is unused, the call will b
e removed. If the | |
| 132 function is not called at all, it will also be removed. Since Proguard is al
ready used to | |
| 133 strip debug and verbose calls out of release builds, this annotation allows
it to have a | |
| 134 deeper action by removing also function calls used to generate the log call'
s arguments. | |
| 135 | |
| 136 /* If that function is only used in Log.d calls, proguard should complet
ely remove it from | |
| 137 * the release builds. */ | |
| 138 @RemovableInRelease | |
| 139 private static String getSomeDebugLogString(Thing[] things) { | |
| 140 /* Still needs to be guarded to avoid impacting debug builds, or in ca
se it's used for | |
| 141 * some other log levels. But at least it is done only once, inside th
e function. */ | |
| 142 if (!Log.isLoggable(TAG, Log.DEBUG)) return null; | |
| 143 | |
| 144 StringBuilder sb = new StringBuilder("Reporting " + thing.length + " t
hings:"); | |
| 145 for (Thing thing : things) { | |
| 146 sb.append('\n').append(thing.id).append(' ').append(report.foo); | |
| 147 } | |
| 148 return sb.toString(); | |
| 149 } | |
| 150 | |
| 151 public void bar() { | |
| 152 ... | |
| 153 Log.d(TAG, getSomeDebugLogString(things)); /* In debug builds, the fun
ction does nothing | |
| 154 * is debug is disabled, an
d the entire line | |
| 155 * is removed in release bu
ilds. */ | |
| 156 } | |
| 157 | |
| 158 Again, this is useful only if the input to that function are variables alrea
dy available in | |
| 159 the scope. The idea is to move computations, concatenations, etc. to a place
where that can be | |
| 160 removed when not needed, without invading the main function's logic. | |
| 161 | |
| 162 #### Rule #3: Favor small log messages | |
| 163 | |
| 164 This is still related to the global fixed-sized kernel buffer used to keep all l
ogs. Try to make | |
| 165 your log information as terse as possible. This reduces the risk of pushing inte
resting log data | |
| 166 out of the buffer when something really nasty happens. It's really better to hav
e a single-line | |
| 167 log message, than several ones. I.e. don't use: | |
| 168 | |
| 169 Log.GROUP.d(TAG, "field1 = %s", value1); | |
| 170 Log.GROUP.d(TAG, "field2 = %s", value2); | |
| 171 Log.GROUP.d(TAG, "field3 = %s", value3); | |
| 172 | |
| 173 Instead, write this as: | |
| 174 | |
| 175 Log.d(TAG, "field1 = %s, field2 = %s, field3 = %s", value1, value2, value3); | |
| 176 | |
| 177 That doesn't seem to be much different if you count overall character counts, bu
t each independent | |
| 178 log entry also implies a small, but non-trivial header, in the kernel log buffer
. | |
| 179 And since every byte count, you can also try something even shorter, as in: | |
| 180 | |
| 181 Log.d(TAG, "fields [%s,%s,%s]", value1, value2, value3); | |
| OLD | NEW |