OSDN Git Service

Attempt to de-flake tests.
authorAlan Stokes <alanstokes@google.com>
Mon, 4 Feb 2019 15:32:12 +0000 (15:32 +0000)
committerAlan Stokes <alanstokes@google.com>
Mon, 18 Feb 2019 16:59:56 +0000 (16:59 +0000)
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

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

index 1cf960a..99d1f5f 100644 (file)
@@ -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);
-
-        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);
+        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());
+            }
+        }.runTest();
     }
 
     @Test
     public void testGeneratesEvents_nativeLibrary_escapedName() 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);
-
-        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);
+        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.
+                String privateCopyName = "second copy " + tryNumber + ".so";
+                File privateCopyFile = privateFile(privateCopyName);
+                mExpectedNameHash = hashOf(privateCopyName);
+                mExpectedContentHash = copyAndHashResource(
+                        libraryPath("DexLoggerNativeTestLibrary.so"), privateCopyFile);
+
+                System.load(privateCopyFile.toString());
+            }
+        }.runTest();
     }
 
     @Test
     public void testGeneratesEvents_nativeExecutable() throws Exception {
-        File privateCopyFile = privateFile("test_executable");
-        String expectedNameHash =
-                "3FBEC3F925A132D18F347F11AE9A5BB8DE1238828F8B4E064AA86EB68BD46DCF";
-        String expectedContentHash =
-                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);
+        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);
+            }
+        }.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);
     }