Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(14)

Side by Side Diff: base/android/java/src/org/chromium/base/README_logging.md

Issue 1323943004: [Android] Remove runtime log level checks (Closed) Base URL: https://chromium.googlesource.com/chromium/src.git@master
Patch Set: Remove @Deprecated on isLoggable Created 5 years, 3 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
« no previous file with comments | « base/android/java/src/org/chromium/base/Log.java ('k') | no next file » | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
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 )
OLDNEW
« no previous file with comments | « base/android/java/src/org/chromium/base/Log.java ('k') | no next file » | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698