Merge "Snapshot mutable ProtoLog arguments before sending them to the background thread" into main (9278d47a) · Commits · e / os / android_frameworks_base

core/java/com/android/internal/protolog/PerfettoProtoLogImpl.java

+17 −2

Original line number	Diff line number	Diff line
		@@ -508,10 +508,16 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		} else {
		stacktrace = null;
		}

		// This is to avoid passing args that are mutable to the background thread, which might
		// cause issues with concurrent access to the same object.
		if (args != null) {
		snapshotMutableArgsToStringInPlace(args);
		}

		mBackgroundHandler.post(() -> {
		try {
		logToProto(logLevel, group, message, args, tsNanos,
		stacktrace);
		logToProto(logLevel, group, message, args, tsNanos, stacktrace);
		} catch (RuntimeException e) {
		// An error occurred during the logging process itself.
		// Log this error along with information about the original log call.
		@@ -542,6 +548,15 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		}
		}

		private void snapshotMutableArgsToStringInPlace(@NonNull Object[] args) {
		for (int i = 0; i < args.length; i++) {
		Object arg = args[i];
		if (arg != null && !(arg instanceof Number) && !(arg instanceof Boolean)) {
		args[i] = arg.toString();
		}
		}
		}

		@Override
		public void onTracingFlush() {
		Log.d(LOG_TAG, "Executing onTracingFlush");

tests/Tracing/src/com/android/internal/protolog/ProcessedPerfettoProtoLogImplTest.java

+55 −0

Original line number	Diff line number	Diff line
		@@ -33,6 +33,7 @@ import static org.mockito.Mockito.when;

		import static java.io.File.createTempFile;

		import android.os.Handler;
		import android.os.SystemClock;
		import android.platform.test.annotations.Presubmit;
		import android.tools.ScenarioBuilder;
		@@ -1163,6 +1164,60 @@ public class ProcessedPerfettoProtoLogImplTest {
		}
		}

		@Test
		public void snapshotsMutableArgumentsOnCallingThread() throws Exception {
		// This test ensures that the mutable argument is snapshotted on the calling thread,
		// and not on the background thread, otherwise it might be modified concurrently and this
		// might lead to a crash.

		PerfettoTraceMonitor traceMonitor = PerfettoTraceMonitor.newBuilder()
		.enableProtoLog(true, List.of(), TEST_PROTOLOG_DATASOURCE_NAME)
		.build();

		final String initialValue = "InitialValue";
		final String modifiedValue = "ModifiedValueAfterLogCall";
		final StringBuilder mutableArg = new StringBuilder(initialValue);
		final String logMessageFormat = "Test with mutable arg: %s";

		final Handler backgroundHandler = sProtoLog.mBackgroundHandler;

		// Task to pause the background thread.
		final CountDownLatch backgroundThreadPausedLatch = new CountDownLatch(1);
		backgroundHandler.post(() -> {
		try {
		backgroundThreadPausedLatch.await();
		} catch (InterruptedException e) {
		Thread.currentThread().interrupt();
		Truth.assertWithMessage(
		"Background thread interrupted while waiting on pause latch.")
		.fail();
		}
		});

		try {
		traceMonitor.start();
		assertTrue("ProtoLog tracing should be enabled", sProtoLog.isProtoEnabled());

		sProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP,
		logMessageFormat, mutableArg);

		mutableArg.replace(0, mutableArg.length(), modifiedValue);

		// Unpause the background thread.
		backgroundThreadPausedLatch.countDown();
		} finally {
		traceMonitor.stop(mWriter);
		}

		final ResultReader resultReader = new ResultReader(mWriter.write(), mTraceConfig);
		final ProtoLogTrace protologTrace = resultReader.readProtoLogTrace();

		Truth.assertThat(protologTrace.messages).hasSize(1);
		final String expectedLoggedMessage = String.format(logMessageFormat, initialValue);
		Truth.assertThat(protologTrace.messages.getFirst().getMessage())
		.isEqualTo(expectedLoggedMessage);
		}

		private enum TestProtoLogGroup implements IProtoLogGroup {
		TEST_GROUP(true, true, false, "TEST_TAG");