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 |