Introducing Log.logStackTrace() (122754d2) · Commits · e / os / android_frameworks_base

core/java/android/os/UserManager.java

+5 −3

Original line number	Diff line number	Diff line
		@@ -6990,8 +6990,9 @@ public class UserManager {
		if (!DEBUG_LOG_DEPRECATION) {
		return;
		}
		Log.v(DEPRECATION_LOG_TAG, "deprecated call on pkg " + mContext.getPackageName()
		+ " (from user " + mUserId + "):", new Exception());
		Log.logStackTrace(Log.LOG_ID_MAIN, Log.VERBOSE, DEPRECATION_LOG_TAG,
		"deprecated call on pkg " + mContext.getPackageName() + " (from user " + mUserId
		+ "):", /* skippedInitialLines= */ 2);
		}

		/**
		@@ -7005,7 +7006,8 @@ public class UserManager {
		if (!DEBUG_LOG_DEPRECATION) {
		return;
		}
		Log.v(DEPRECATION_LOG_TAG, "deprecated call:", new Exception());
		Log.logStackTrace(Log.LOG_ID_MAIN, Log.VERBOSE, DEPRECATION_LOG_TAG,
		"deprecated call:", /* skippedInitialLines= */ 2);
		}

		/* Cache key for anything that assumes that userIds cannot be re-used without rebooting. */

core/java/android/util/Log.java

+70 −0

Original line number	Diff line number	Diff line
		@@ -23,9 +23,11 @@ import android.annotation.SystemApi;
		import android.compat.annotation.UnsupportedAppUsage;
		import android.os.DeadSystemException;

		import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.os.RuntimeInit;
		import com.android.internal.util.FastPrintWriter;
		import com.android.internal.util.LineBreakBufferedWriter;
		import com.android.internal.util.Preconditions;

		import dalvik.annotation.optimization.FastNative;

		@@ -35,6 +37,7 @@ import java.io.Writer;
		import java.lang.annotation.Retention;
		import java.lang.annotation.RetentionPolicy;
		import java.net.UnknownHostException;
		import java.util.Objects;

		/**
		* API for sending log output.
		@@ -504,6 +507,73 @@ public final class Log {
		return logWriter.getWritten();
		}

		/**
		* Logs the stack trace of the method calling it, ignoring the first
		* {@code skippedInitialLines} (which will be typically {@code 1}, which is the
		* {@code logStackTrace()} itself), except when the calls are
		* nested.
		*
		* <p> For example, {@code UserManager.logDeprecation()} is meant to log callers of that method,
		* so {@code skippedInitialLines} is {@code 2} in that case.
		*
		* @hide
		*/
		public static int logStackTrace(int bufID, int priority, String tag, String msg,
		int skippedInitialLines) {
		// TODO(b/432819184): logic below was copied from printlns(); ideally we should refactor
		// these 2 methods to reuse the code, but printlns() is not unit tests (in fact, it also
		// doesn't close lbbw)
		ImmediateLogWriter logWriter = new ImmediateLogWriter(bufID, priority, tag);
		int bufferSize = PreloadHolder.LOGGER_ENTRY_MAX_PAYLOAD // Base.
		- 2 // Two terminators.
		- (tag != null ? tag.length() : 0) // Tag length.
		- 32; // Some slack.
		bufferSize = Math.max(bufferSize, 100);

		try (LineBreakBufferedWriter lbbw = new LineBreakBufferedWriter(logWriter, bufferSize)) {
		logStackTrace(lbbw, bufID, priority, msg, skippedInitialLines);
		}
		return logWriter.getWritten();
		}

		/** @hide */
		@VisibleForTesting
		public static void logStackTrace(PrintWriter writer, int bufID, int priority, String msg,
		int skippedInitialLines) {
		Objects.requireNonNull(msg, "msg cannot be null");
		Preconditions.checkArgumentNonnegative(skippedInitialLines,
		"skippedInitialLines must be non-negative");

		// First write the message...
		writer.println(msg);

		// ...then the elements
		StackTraceElement[] elements = Thread.currentThread().getStackTrace();
		// First elements come from ART, so we need to skip them until we find this method's
		boolean foundlogStackTraceElement = false;
		int skipped = 0; // actual number of skipped lines
		for (int i = 0; i < elements.length; i++) {
		StackTraceElement element = elements[i];
		if (!foundlogStackTraceElement) {
		if (element.getMethodName().equals("logStackTrace")) {
		// In theory we should check for the class name as well, but pragmatically
		// speaking, just checking the method is enough (as it's unlikely that ART would
		// have a method with that name)
		foundlogStackTraceElement = true;
		}
		continue;
		}
		if (skipped < skippedInitialLines) {
		skipped++;
		continue;
		}

		writer.printf("\t%s\n", element);
		}

		writer.flush();
		}

		/**
		* PreloadHelper class. Caches the LOGGER_ENTRY_MAX_PAYLOAD value to avoid
		* a JNI call during logging.

core/tests/coretests/src/android/util/LogTest.java

+90 −6

Original line number	Diff line number	Diff line
		@@ -16,30 +16,45 @@

		package android.util;

		import static android.util.Log.logStackTrace;

		import static com.google.common.truth.Truth.assertWithMessage;

		import static org.junit.Assert.assertThrows;

		import android.os.SystemProperties;
		import android.test.PerformanceTestCase;

		import androidx.test.ext.junit.runners.AndroidJUnit4;
		import androidx.test.filters.Suppress;

		import com.google.common.truth.Expect;

		import junit.framework.TestCase;

		import org.junit.Assert;
		import org.junit.Ignore;
		import org.junit.Rule;
		import org.junit.Test;
		import org.junit.runner.RunWith;

		//This is an empty TestCase.
		@Suppress
		import java.io.PrintWriter;
		import java.io.StringWriter;

		@RunWith(AndroidJUnit4.class)
		public class LogTest {
		public final class LogTest {
		private static final String PROPERTY_TAG = "log.tag.LogTest";
		private static final String LOG_TAG = "LogTest";

		private static final String MSG = "in a bottle";

		@Rule
		public final Expect expect = Expect.create();

		@Test
		@Ignore // wtf() call would crash the test - WTF?!?!?
		public void testWtf() {
		Log.wtf(LOG_TAG, "Message");
		Log.wtf(LOG_TAG, "Message", new Throwable("Throwable"));
		Log.wtf(LOG_TAG, MSG);
		Log.wtf(LOG_TAG, MSG, new Throwable("Throwable"));
		Log.wtf(LOG_TAG, new Throwable("Throwable"));
		}

		@@ -138,6 +153,75 @@ public class LogTest {
		Assert.assertFalse(Log.isLoggable(LOG_TAG, Log.ASSERT));
		}

		@Test
		public void testLogStackTrace_invalidArgs() throws Exception {
		try (StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw)) {
		assertThrows(NullPointerException.class, () -> logStackTrace(pw, Log.LOG_ID_MAIN,
		Log.VERBOSE, /* msg= / null, / skippedInitialLines= */ 0));
		assertThrows(IllegalArgumentException.class, () -> logStackTrace(pw, Log.LOG_ID_MAIN,
		Log.VERBOSE, MSG, /* skippedInitialLines= */ -1));
		}
		}

		@Test
		public void testLogStackTrace_noSkippedLine() throws Exception {
		try (StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw)) {
		logStackTrace(pw, Log.LOG_ID_MAIN, Log.VERBOSE, MSG, /* skippedInitialLines= */ 0);

		String[] loggedLines = getLoggedLines(sw);
		assertWithMessage("number of logged lines").that(loggedLines.length).isAtLeast(2);
		expect.withMessage("first line").that(loggedLines[0]).isEqualTo(MSG);
		expect.withMessage("second line").that(loggedLines[1])
		.contains("testLogStackTrace_noSkippedLine");
		}
		}

		@Test
		public void testLogStackTrace_oneSkippedLine() throws Exception {
		try (StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw)) {
		oneLevelLog(pw, MSG, /* skippedInitialLines= */ 1);

		String[] loggedLines = getLoggedLines(sw);
		assertWithMessage("number of logged lines").that(loggedLines.length).isAtLeast(2);
		expect.withMessage("first line").that(loggedLines[0]).isEqualTo(MSG);
		expect.withMessage("second line").that(loggedLines[1])
		.contains("testLogStackTrace_oneSkippedLine");
		}
		}

		@Test
		public void testLogStackTrace_twoSkippedLines() throws Exception {
		try (StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw)) {
		twoLevelsLog(pw, MSG, /* skippedInitialLines= */ 2);

		String[] loggedLines = getLoggedLines(sw);
		assertWithMessage("number of logged lines").that(loggedLines.length).isAtLeast(2);
		expect.withMessage("first line").that(loggedLines[0]).isEqualTo(MSG);
		expect.withMessage("second line").that(loggedLines[1])
		.contains("testLogStackTrace_twoSkippedLines");
		}
		}

		private String[] getLoggedLines(StringWriter writer) {
		String loggedMessage = writer.toString();
		Log.v(LOG_TAG, "Logged message: \n" + loggedMessage);
		assertWithMessage("logged message").that(loggedMessage).isNotEmpty();

		String[] loggedLines = loggedMessage.split("\n");
		assertWithMessage("logged message as array").that(loggedLines).isNotNull();
		return loggedLines;
		}

		/** This method calls a method that calls {@code logStackTrace(msg, skippedInitialLines)}. */
		private static void twoLevelsLog(PrintWriter writer, String msg, int skippedInitialLines) {
		oneLevelLog(writer, msg, skippedInitialLines);
		}

		/** This method calls {@code logStackTrace(msg, skippedLines)} directly. */
		private static void oneLevelLog(PrintWriter writer, String msg, int skippedInitialLines) {
		logStackTrace(writer, Log.LOG_ID_MAIN, Log.VERBOSE, msg, skippedInitialLines);
		}

		public static class PerformanceTest extends TestCase implements PerformanceTestCase {
		private static final int ITERATIONS = 1000;