Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Fix Slogf to behave like Slog

Browse Source 
Log, Slog, and Slogf without format arguments all log VERBOSE and above
by default.  In contrast, Slogf with format arguments only logs INFO and
above by default.  That's very surprising, and it's causing messages to
disappear from the log after "trivial" conversions to Slogf.

This is caused by Slogf assuming that Log.isLoggable() works in the
expected way.  Unfortunately, Log.isLoggable() has always been advisory
in Android, not enforced.  By default it only returns true for INFO and
above, but it's always been up to the users of the logging methods to
check it, if they want to.  system_server generally does not check it,
or only uses it for boolean knobs at the class level that selected log
messages are conditional on.  system_server also lots quite a bit at
DEBUG level; people would probably be unhappy if it started enforcing
Log.isLoggable() and all DEBUG messages disappeared from the logs.

The end result is that while making logging methods return early if
!Log.isLoggable() at first seems like a perfectly reasonable thing to
do, in the context of system_server it actually results in unexpected
behavior, so it shouldn't be done.  It's up to the callers to decide
what they want to log.

Bug: 182476140
Bug: 268526331
Test: atest FrameworksMockingServicesTests:SlogfTest
Change-Id: If8d2ffe5bda51add08e2c952871e0c646ebb2474
This commit is contained in:
Eric Biggers
2023-02-10 17:27:48 +00:00
parent 6e4312545b
commit 84fbdc97b0
3 changed files with 30 additions and 272 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
services/core/java/com/android/server/cpu/CpuMonitorService.java
View File

@@ -38,7 +38,7 @@ import java.util.concurrent.Executor;
/** Service to monitor CPU availability and usage. */
public final class CpuMonitorService extends SystemService {
static final String TAG = CpuMonitorService.class.getSimpleName();
static final boolean DEBUG = Slogf.isLoggable(TAG, Log.DEBUG);
static final boolean DEBUG = Log.isLoggable(TAG, Log.DEBUG);
// TODO(b/242722241): Make this a resource overlay property.
// Maintain 3 monitoring intervals:
// * One to poll very frequently when mCpuAvailabilityCallbackInfoByCallbacks are available and

145
services/core/java/com/android/server/utils/Slogf.java
View File

@@ -30,11 +30,13 @@ import java.util.Locale;
/**
* Extends {@link Slog} by providing overloaded methods that take string formatting.
*
* <p><strong>Note: </strong>the overloaded methods won't create the formatted message if the
* respective logging level is disabled for the tag, but the compiler will still create an
* intermediate array of the objects for the {@code vargars}, which could affect garbage collection.
* So, if you're calling these method in a critical path, make sure to explicitly check for the
* level before calling them.
* <p><strong>Note: </strong>Like the other logging classes, e.g. {@link Log} and {@link Slog}, the
* methods in this class log unconditionally regardless of {@link Log#isLoggable(String, int)}.
* Therefore, these methods exist just for the convenience of handling formatting. (Even if they
* did check {@link Log#isLoggable(String, int)} before formatting and logging, calling a varargs
* method in Java still involves an array allocation.) If you need to avoid the overhead of logging
* on a performance-critical path, either don't use logging in that place, or make the logging
* conditional on a static boolean defaulting to false.
*/
public final class Slogf {
@@ -56,11 +58,6 @@ public final class Slogf {
throw new UnsupportedOperationException("provides only static methods");
}
/** Same as {@link Log#isLoggable(String, int)}. */
public static boolean isLoggable(String tag, int level) {
return Log.isLoggable(tag, level);
}
/** Same as {@link Slog#v(String, String)}. */
public static int v(String tag, String msg) {
return Slog.v(tag, msg);
@@ -146,166 +143,62 @@ public final class Slogf {
return Slog.println(priority, tag, msg);
}
/**
* Logs a {@link Log.VERBOSE} message.
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#VERBOSE} logging
* is enabled for the given {@code tag}, but the compiler will still create an intermediate
* array of the objects for the {@code vargars}, which could affect garbage collection. So, if
* you're calling this method in a critical path, make sure to explicitly do the check before
* calling it.
*/
/** Logs a {@link Log.VERBOSE} message. */
public static void v(String tag, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.VERBOSE)) return;
v(tag, getMessage(format, args));
}
/**
* Logs a {@link Log.VEBOSE} message with a throwable
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#VERBOSE} logging
* is enabled for the given {@code tag}, but the compiler will still create an intermediate
* array of the objects for the {@code vargars}, which could affect garbage collection. So, if
* you're calling this method in a critical path, make sure to explicitly do the check before
* calling it.
*/
/** Logs a {@link Log.VERBOSE} message with a throwable. */
public static void v(String tag, Throwable throwable, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.VERBOSE)) return;
v(tag, getMessage(format, args), throwable);
}
/**
* Logs a {@link Log.DEBUG} message.
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#DEBUG} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.DEBUG} message. */
public static void d(String tag, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.DEBUG)) return;
d(tag, getMessage(format, args));
}
/**
* Logs a {@link Log.DEBUG} message with a throwable
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#DEBUG} logging
* is enabled for the given {@code tag}, but the compiler will still create an intermediate
* array of the objects for the {@code vargars}, which could affect garbage collection. So, if
* you're calling this method in a critical path, make sure to explicitly do the check before
* calling it.
*/
/** Logs a {@link Log.DEBUG} message with a throwable. */
public static void d(String tag, Throwable throwable, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.DEBUG)) return;
d(tag, getMessage(format, args), throwable);
}
/**
* Logs a {@link Log.INFO} message.
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#INFO} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.INFO} message. */
public static void i(String tag, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.INFO)) return;
i(tag, getMessage(format, args));
}
/**
* Logs a {@link Log.INFO} message with a throwable
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#INFO} logging
* is enabled for the given {@code tag}, but the compiler will still create an intermediate
* array of the objects for the {@code vargars}, which could affect garbage collection. So, if
* you're calling this method in a critical path, make sure to explicitly do the check before
* calling it.
*/
/** Logs a {@link Log.INFO} message with a throwable. */
public static void i(String tag, Throwable throwable, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.INFO)) return;
i(tag, getMessage(format, args), throwable);
}
/**
* Logs a {@link Log.WARN} message.
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#WARN} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.WARN} message. */
public static void w(String tag, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.WARN)) return;
w(tag, getMessage(format, args));
}
/**
* Logs a {@link Log.WARN} message with a throwable
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#WARN} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.WARN} message with a throwable. */
public static void w(String tag, Throwable throwable, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.WARN)) return;
w(tag, getMessage(format, args), throwable);
}
/**
* Logs a {@link Log.ERROR} message.
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#ERROR} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.ERROR} message. */
public static void e(String tag, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.ERROR)) return;
e(tag, getMessage(format, args));
}
/**
* Logs a {@link Log.ERROR} message with a throwable
*
* <p><strong>Note: </strong>the message will only be formatted if {@link Log#ERROR} logging is
* enabled for the given {@code tag}, but the compiler will still create an intermediate array
* of the objects for the {@code vargars}, which could affect garbage collection. So, if you're
* calling this method in a critical path, make sure to explicitly do the check before calling
* it.
*/
/** Logs a {@link Log.ERROR} message with a throwable. */
public static void e(String tag, Throwable throwable, String format, @Nullable Object... args) {
if (!isLoggable(tag, Log.ERROR)) return;
e(tag, getMessage(format, args), throwable);
}
/**
* Logs a {@code wtf} message.
*/
/** Logs a {@code wtf} message. */
public static void wtf(String tag, String format, @Nullable Object... args) {
wtf(tag, getMessage(format, args));
}
/**
* Logs a {@code wtf} message with a throwable.
*/
/** Logs a {@code wtf} message with a throwable. */
public static void wtf(String tag, Throwable throwable, String format,
@Nullable Object... args) {
wtf(tag, getMessage(format, args), throwable);

155
services/tests/mockingservicestests/src/com/android/server/utils/SlogfTest.java
View File

@@ -16,16 +16,9 @@
package com.android.server.utils;
import static com.android.dx.mockito.inline.extended.ExtendedMockito.doReturn;
import static com.android.dx.mockito.inline.extended.ExtendedMockito.mockitoSession;
import static com.android.dx.mockito.inline.extended.ExtendedMockito.verify;
import static com.google.common.truth.Truth.assertThat;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.never;
import android.util.Log;
import android.util.Slog;
@@ -51,7 +44,6 @@ public final class SlogfTest {
mSession = mockitoSession()
.initMocks(this)
.mockStatic(Slog.class)
.spyStatic(Slogf.class) // for isLoggable only
.strictness(Strictness.LENIENT)
.startMocking();
}
@@ -65,11 +57,6 @@ public final class SlogfTest {
}
}
@Test
public void testIsLoggable() {
assertThat(Slogf.isLoggable(TAG, Log.VERBOSE)).isEqualTo(Log.isLoggable(TAG, Log.VERBOSE));
}
@Test
public void testV_msg() {
Slogf.v(TAG, "msg");
@@ -85,41 +72,19 @@ public final class SlogfTest {
}
@Test
public void testV_msgFormatted_enabled() {
enableLogging(Log.VERBOSE);
public void testV_msgFormatted() {
Slogf.v(TAG, "msg in a %s", "bottle");
verify(()-> Slog.v(TAG, "msg in a bottle"));
}
@Test
public void testV_msgFormatted_disabled() {
disableLogging(Log.VERBOSE);
Slogf.v(TAG, "msg in a %s", "bottle");
verify(()-> Slog.v(eq(TAG), any()), never());
}
@Test
public void testV_msgFormattedWithThrowable_enabled() {
enableLogging(Log.VERBOSE);
public void testV_msgFormattedWithThrowable() {
Slogf.v(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.v(TAG, "msg in a bottle", mThrowable));
}
@Test
public void testV_msgFormattedWithException_disabled() {
disableLogging(Log.VERBOSE);
Slogf.v(TAG, "msg in a %s", "bottle");
verify(()-> Slog.v(eq(TAG), any(String.class), any(Throwable.class)), never());
}
@Test
public void testD_msg() {
Slogf.d(TAG, "msg");
@@ -135,41 +100,19 @@ public final class SlogfTest {
}
@Test
public void testD_msgFormatted_enabled() {
enableLogging(Log.DEBUG);
public void testD_msgFormatted() {
Slogf.d(TAG, "msg in a %s", "bottle");
verify(()-> Slog.d(TAG, "msg in a bottle"));
}
@Test
public void testD_msgFormatted_disabled() {
disableLogging(Log.DEBUG);
Slogf.d(TAG, "msg in a %s", "bottle");
verify(()-> Slog.d(eq(TAG), any()), never());
}
@Test
public void testD_msgFormattedWithThrowable_enabled() {
enableLogging(Log.DEBUG);
public void testD_msgFormattedWithThrowable() {
Slogf.d(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.d(TAG, "msg in a bottle", mThrowable));
}
@Test
public void testD_msgFormattedWithException_disabled() {
disableLogging(Log.DEBUG);
Slogf.d(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.d(eq(TAG), any(String.class), any(Throwable.class)), never());
}
@Test
public void testI_msg() {
Slogf.i(TAG, "msg");
@@ -185,41 +128,19 @@ public final class SlogfTest {
}
@Test
public void testI_msgFormatted_enabled() {
enableLogging(Log.INFO);
public void testI_msgFormatted() {
Slogf.i(TAG, "msg in a %s", "bottle");
verify(()-> Slog.i(TAG, "msg in a bottle"));
}
@Test
public void testI_msgFormatted_disabled() {
disableLogging(Log.INFO);
Slogf.i(TAG, "msg in a %s", "bottle");
verify(()-> Slog.i(eq(TAG), any()), never());
}
@Test
public void testI_msgFormattedWithThrowable_enabled() {
enableLogging(Log.INFO);
public void testI_msgFormattedWithThrowable() {
Slogf.i(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.i(TAG, "msg in a bottle", mThrowable));
}
@Test
public void testI_msgFormattedWithException_disabled() {
disableLogging(Log.INFO);
Slogf.i(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.i(eq(TAG), any(String.class), any(Throwable.class)), never());
}
@Test
public void testW_msg() {
Slogf.w(TAG, "msg");
@@ -242,41 +163,19 @@ public final class SlogfTest {
}
@Test
public void testW_msgFormatted_enabled() {
enableLogging(Log.WARN);
public void testW_msgFormatted() {
Slogf.w(TAG, "msg in a %s", "bottle");
verify(()-> Slog.w(TAG, "msg in a bottle"));
}
@Test
public void testW_msgFormatted_disabled() {
disableLogging(Log.WARN);
Slogf.w(TAG, "msg in a %s", "bottle");
verify(()-> Slog.w(eq(TAG), any(String.class)), never());
}
@Test
public void testW_msgFormattedWithThrowable_enabled() {
enableLogging(Log.WARN);
public void testW_msgFormattedWithThrowable() {
Slogf.w(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.w(TAG, "msg in a bottle", mThrowable));
}
@Test
public void testW_msgFormattedWithException_disabled() {
disableLogging(Log.WARN);
Slogf.w(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.w(eq(TAG), any(String.class), any(Throwable.class)), never());
}
@Test
public void testE_msg() {
Slogf.e(TAG, "msg");
@@ -292,41 +191,19 @@ public final class SlogfTest {
}
@Test
public void testE_msgFormatted_enabled() {
enableLogging(Log.ERROR);
public void testE_msgFormatted() {
Slogf.e(TAG, "msg in a %s", "bottle");
verify(()-> Slog.e(TAG, "msg in a bottle"));
}
@Test
public void testE_msgFormatted_disabled() {
disableLogging(Log.ERROR);
Slogf.e(TAG, "msg in a %s", "bottle");
verify(()-> Slog.e(eq(TAG), any()), never());
}
@Test
public void testE_msgFormattedWithThrowable_enabled() {
enableLogging(Log.ERROR);
public void testE_msgFormattedWithThrowable() {
Slogf.e(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.e(TAG, "msg in a bottle", mThrowable));
}
@Test
public void testE_msgFormattedWithException_disabled() {
disableLogging(Log.ERROR);
Slogf.e(TAG, mThrowable, "msg in a %s", "bottle");
verify(()-> Slog.e(eq(TAG), any(String.class), any(Throwable.class)), never());
}
@Test
public void testWtf_msg() {
Slogf.wtf(TAG, "msg");
@@ -382,16 +259,4 @@ public final class SlogfTest {
verify(()-> Slog.wtf(TAG, "msg in a bottle", mThrowable));
}
private void enableLogging(@Log.Level int level) {
setIsLogging(level, true);
}
private void disableLogging(@Log.Level int level) {
setIsLogging(level, false);
}
private void setIsLogging(@Log.Level int level, boolean value) {
doReturn(value).when(() -> Slogf.isLoggable(TAG, level));
}
}