Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit cfb9e617 authored by Pablo Gamito's avatar Pablo Gamito
Browse files

Snapshot mutable ProtoLog arguments before sending them to the background thread 

Before this CL, the args where passed as they were to the background thread. This means that if they were modified after the call to the log function, then there might be a race condition and even crashes due to concurrent accesses.

This CL fixes that by copying the values by calling toString() on every object before passing them to the background thread.

Test: atest TracingTests
Bug: 420430923
Flag: EXEMPT bug fix
Change-Id: Ide20527b4b1406ffb0979fb35aab861a98260297
parent d09238d4

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");