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 |