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