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

Commit 206a69d4 authored by Alan Stokes's avatar Alan Stokes
Browse files

Attempt to de-flake tests. 

Some of these tests rely on audit logs being generated and then
visible when we try to read them. Occasionally this doesn't work -
probably because of throttling or the asynchronous, background nature
of logging. When it happens the tests fail.

To avoid this, re-run the susceptible tests multiple times rather than
failing on the first go, with increasingly long delays between
triggering and reading the logs on each run.

Bug: 123507824
Test: atest -p services/core/java/com/android/server/pm/dex
Change-Id: I62db997c912b2d153ecaea34011529c4c58207c7
parent e4f26ef2

tests/DexLoggerIntegrationTests/src/com/android/server/pm/dex/DexLoggerIntegrationTests.java

+103 −59
Original line number Diff line number Diff line
@@ -65,6 +65,8 @@ import java.util.concurrent.TimeUnit; 
@RunWith(JUnit4.class)

public final class DexLoggerIntegrationTests {



    private static final String SHA_256 = "SHA-256";



    // Event log tag used for SNET related events

    private static final int SNET_TAG = 0x534e4554;
@@ -76,6 +78,13 @@ public final class DexLoggerIntegrationTests { 
    private static final int IDLE_LOGGING_JOB_ID = 2030028;

    private static final int AUDIT_WATCHING_JOB_ID = 203142925;



    // For tests that rely on parsing audit logs, how often to retry. (There are many reasons why

    // we might not see the audit logs, including throttling and delays in log generation, so to

    // avoid flakiness we run these tests multiple times, allowing progressively longer between

    // code loading and checking the logs on each try.)

    private static final int AUDIT_LOG_RETRIES = 10;

    private static final int RETRY_DELAY_MS = 2_000;



    private static Context sContext;

    private static int sMyUid;
@@ -144,78 +153,65 @@ public final class DexLoggerIntegrationTests { 


    @Test

    public void testGeneratesEvents_nativeLibrary() throws Exception {

        File privateCopyFile = privateFile("copied.so");

        String expectedNameHash =

                "996223BAD4B4FE75C57A3DEC61DB9C0B38E0A7AD479FC95F33494F4BC55A0F0E";

        String expectedContentHash =

                copyAndHashResource(libraryPath("DexLoggerNativeTestLibrary.so"), privateCopyFile);

        new TestNativeCodeWithRetries() {

            @Override

            protected void loadNativeCode(int tryNumber) throws Exception {

                // We need to use a different file name for each retry, because once a file is

                // loaded, re-loading it has no effect.

                String privateCopyName = "copied" + tryNumber + ".so";

                File privateCopyFile = privateFile(privateCopyName);

                mExpectedNameHash = hashOf(privateCopyName);

                mExpectedContentHash = copyAndHashResource(

                        libraryPath("DexLoggerNativeTestLibrary.so"), privateCopyFile);



                System.load(privateCopyFile.toString());



        // Run the job to scan generated audit log entries

        runDynamicCodeLoggingJob(AUDIT_WATCHING_JOB_ID);



        // And then make sure we log events about it

        long previousEventNanos = mostRecentEventTimeNanos();

        runDynamicCodeLoggingJob(IDLE_LOGGING_JOB_ID);



        assertDclLoggedSince(previousEventNanos, DCL_NATIVE_SUBTAG,

                expectedNameHash, expectedContentHash);

            }

        }.runTest();

    }



    @Test

    public void testGeneratesEvents_nativeLibrary_escapedName() throws Exception {

        new TestNativeCodeWithRetries() {

            @Override

            protected void loadNativeCode(int tryNumber) throws Exception {

                // A file name with a space will be escaped in the audit log; verify we un-escape it

                // correctly.

        File privateCopyFile = privateFile("second copy.so");

        String expectedNameHash =

                "8C39990C560B4F36F83E208E279F678746FE23A790E4C50F92686584EA2041CA";

        String expectedContentHash =

                copyAndHashResource(libraryPath("DexLoggerNativeTestLibrary.so"), privateCopyFile);

                String privateCopyName = "second copy " + tryNumber + ".so";

                File privateCopyFile = privateFile(privateCopyName);

                mExpectedNameHash = hashOf(privateCopyName);

                mExpectedContentHash = copyAndHashResource(

                        libraryPath("DexLoggerNativeTestLibrary.so"), privateCopyFile);



                System.load(privateCopyFile.toString());



        // Run the job to scan generated audit log entries

        runDynamicCodeLoggingJob(AUDIT_WATCHING_JOB_ID);



        // And then make sure we log events about it

        long previousEventNanos = mostRecentEventTimeNanos();

        runDynamicCodeLoggingJob(IDLE_LOGGING_JOB_ID);



        assertDclLoggedSince(previousEventNanos, DCL_NATIVE_SUBTAG,

                expectedNameHash, expectedContentHash);

            }

        }.runTest();

    }



    @Test

    public void testGeneratesEvents_nativeExecutable() throws Exception {

        File privateCopyFile = privateFile("test_executable");

        String expectedNameHash =

                "3FBEC3F925A132D18F347F11AE9A5BB8DE1238828F8B4E064AA86EB68BD46DCF";

        String expectedContentHash =

                copyAndHashResource("/DexLoggerNativeExecutable", privateCopyFile);

        new TestNativeCodeWithRetries() {

            @Override

            protected void loadNativeCode(int tryNumber) throws Exception {

                String privateCopyName = "test_executable" + tryNumber;

                File privateCopyFile = privateFile(privateCopyName);

                mExpectedNameHash = hashOf(privateCopyName);

                mExpectedContentHash = copyAndHashResource(

                        "/DexLoggerNativeExecutable", privateCopyFile);

                assertThat(privateCopyFile.setExecutable(true)).isTrue();



                Process process = Runtime.getRuntime().exec(privateCopyFile.toString());

                int exitCode = process.waitFor();

                assertThat(exitCode).isEqualTo(0);



        // Run the job to scan generated audit log entries

        runDynamicCodeLoggingJob(AUDIT_WATCHING_JOB_ID);



        // And then make sure we log events about it

        long previousEventNanos = mostRecentEventTimeNanos();

        runDynamicCodeLoggingJob(IDLE_LOGGING_JOB_ID);



        assertDclLoggedSince(previousEventNanos, DCL_NATIVE_SUBTAG,

                expectedNameHash, expectedContentHash);

            }

        }.runTest();

    }



    @Test

    public void testGeneratesEvents_spoofed_validFile() throws Exception {

        File privateCopyFile = privateFile("spoofed");



        String expectedContentHash =

                copyAndHashResource("/DexLoggerNativeExecutable", privateCopyFile);

        String expectedContentHash = copyAndHashResource(

                "/DexLoggerNativeExecutable", privateCopyFile);



        EventLog.writeEvent(EventLog.getTagCode("auditd"),

                "type=1400 avc: granted { execute_no_trans } "
@@ -304,6 +300,40 @@ public final class DexLoggerIntegrationTests { 
        assertNoDclLoggedSince(previousEventNanos, DCL_NATIVE_SUBTAG, expectedNameHash);

    }



    // Abstract out the logic for running a native code loading test multiple times if needed and

    // leaving time for audit messages to reach the log.

    private abstract class TestNativeCodeWithRetries {

        String mExpectedContentHash;

        String mExpectedNameHash;



        abstract void loadNativeCode(int tryNumber) throws Exception;



        final void runTest() throws Exception {

            List<String> messages = null;



            for (int i = 0; i < AUDIT_LOG_RETRIES; i++) {

                loadNativeCode(i);



                SystemClock.sleep(i * RETRY_DELAY_MS);



                // Run the job to scan generated audit log entries

                runDynamicCodeLoggingJob(AUDIT_WATCHING_JOB_ID);



                // And then make sure we log events about it

                long previousEventNanos = mostRecentEventTimeNanos();

                runDynamicCodeLoggingJob(IDLE_LOGGING_JOB_ID);



                messages = findMatchingEvents(

                        previousEventNanos, DCL_NATIVE_SUBTAG, mExpectedNameHash);

                if (!messages.isEmpty()) {

                    break;

                }

            }



            assertHasDclLog(messages, mExpectedContentHash);

        }

    }



    private static File privateFile(String name) {

        return new File(sContext.getDir("dcl", Context.MODE_PRIVATE), name);

    }
@@ -315,7 +345,7 @@ public final class DexLoggerIntegrationTests { 
    }



    private static String copyAndHashResource(String resourcePath, File copyTo) throws Exception {

        MessageDigest hasher = MessageDigest.getInstance("SHA-256");

        MessageDigest hasher = MessageDigest.getInstance(SHA_256);



        // Copy the jar from our Java resources to a private data directory

        Class<?> thisClass = DexLoggerIntegrationTests.class;
@@ -334,6 +364,16 @@ public final class DexLoggerIntegrationTests { 


        // Compute the SHA-256 of the file content so we can check that it is the same as the value

        // we see logged.

        return toHexString(hasher);

    }



    private String hashOf(String input) throws Exception {

        MessageDigest hasher = MessageDigest.getInstance(SHA_256);

        hasher.update(input.getBytes());

        return toHexString(hasher);

    }



    private static String toHexString(MessageDigest hasher) {

        Formatter formatter = new Formatter();

        for (byte b : hasher.digest()) {

            formatter.format("%02X", b);
@@ -388,6 +428,10 @@ public final class DexLoggerIntegrationTests { 
        List<String> messages =

                findMatchingEvents(previousEventNanos, expectedSubTag, expectedNameHash);



        assertHasDclLog(messages, expectedContentHash);

    }



    private static void assertHasDclLog(List<String> messages, String expectedContentHash) {

        assertWithMessage("Expected exactly one matching log entry").that(messages).hasSize(1);

        assertThat(messages.get(0)).endsWith(expectedContentHash);

    }