Fixed LogcatOnFailureCollector and made it iteration-aware.

Bug: 130441146
Test: atest CollectorDeviceLibTest:LogcatOnFailureCollectorTest
(updated)
Change-Id: I9c2ca57666397983d8b05292e5351af6cb4b325f
(cherry picked from commit 44408c3e65d2527d13579a09074760ac1169b79e)

2 files changed, 281 insertions, 33 deletions

diff --git a/libraries/device-collectors/src/main/java/android/device/collectors/LogcatOnFailureCollector.java b/libraries/device-collectors/src/main/java/android/device/collectors/LogcatOnFailureCollector.java
index 61a30a58b..aaa9944dd 100644
--- a/libraries/device-collectors/src/main/java/android/device/collectors/LogcatOnFailureCollector.java
+++ b/libraries/device-collectors/src/main/java/android/device/collectors/LogcatOnFailureCollector.java
@@ -17,7 +17,6 @@ package android.device.collectors;
 
 import android.device.collectors.annotations.OptionClass;
 import android.os.Bundle;
-import android.os.ParcelFileDescriptor;
 import android.util.Log;
 
 import androidx.annotation.VisibleForTesting;
@@ -27,13 +26,12 @@ import org.junit.runner.notification.Failure;
 
 import java.io.File;
 import java.io.IOException;
-import java.io.InputStream;
-import java.io.FileOutputStream;
-import java.io.OutputStream;
 import java.util.Date;
-import java.text.DateFormat;
+import java.util.HashMap;
 import java.text.SimpleDateFormat;
 
+import java.util.Arrays;
+
 /**
  * A {@link BaseMetricListener} that captures logcat after each test case failure.
  *
@@ -43,6 +41,10 @@ import java.text.SimpleDateFormat;
  */
 @OptionClass(alias = "logcat-failure-collector")
 public class LogcatOnFailureCollector extends BaseMetricListener {
+    @VisibleForTesting
+    static final SimpleDateFormat DATE_FORMATTER = new SimpleDateFormat("MM-dd HH:mm:ss.SSS");
+
+    @VisibleForTesting static final String METRIC_SEP = "-";
 
     public static final String DEFAULT_DIR = "run_listeners/logcats";
     private static final int BUFFER_SIZE = 16 * 1024;
@@ -50,6 +52,9 @@ public class LogcatOnFailureCollector extends BaseMetricListener {
     private File mDestDir;
     private String mStartTime = null;
 
+    // Map to keep track of test iterations for multiple test iterations.
+    private HashMap<Description, Integer> mTestIterations = new HashMap<>();
+
     public LogcatOnFailureCollector() {
         super();
     }
@@ -66,12 +71,19 @@ public class LogcatOnFailureCollector extends BaseMetricListener {
     @Override
     public void onTestRunStart(DataRecord runData, Description description) {
         mDestDir = createAndEmptyDirectory(DEFAULT_DIR);
+        // Capture the start time in case onTestStart() is never called due to failure during
+        // @BeforeClass.
+        mStartTime = getCurrentDate();
     }
 
     @Override
     public void onTestStart(DataRecord testData, Description description) {
-        // Capture the start time for logcat purpose
+        // Capture the start time for logcat purpose.
+        // Overwrites any start time set prior to the test.
         mStartTime = getCurrentDate();
+        // Keep track of test iterations.
+        mTestIterations.computeIfPresent(description, (desc, iteration) -> iteration + 1);
+        mTestIterations.computeIfAbsent(description, desc -> 1);
     }
 
     @Override
@@ -80,34 +92,42 @@ public class LogcatOnFailureCollector extends BaseMetricListener {
         if (mDestDir == null) {
             return;
         }
-        String command = String.format("logcat -T \"%s\"", mStartTime);
-        try (InputStream is = getLogcat(command);) {
-            final String fileName = String.format("%s.%s.txt", description.getClassName(),
-                                description.getMethodName());
-            // TODO: Refactor in a fileUtil like tradefed one
+        try {
+            int iteration = mTestIterations.get(description);
+            final String fileName =
+                    String.format(
+                            "%s.%s%s.txt",
+                            description.getClassName(),
+                            description.getMethodName(),
+                            iteration == 1 ? "" : (METRIC_SEP + String.valueOf(iteration)));
             File logcat = new File(mDestDir, fileName);
-            OutputStream out = new FileOutputStream(logcat);
-            byte[] buf = new byte[BUFFER_SIZE];
-            int length;
-            while ((length = is.read(buf)) >= 0) {
-                out.write(buf, 0, length);
-            }
+            getLogcatSince(mStartTime, logcat);
             testData.addFileMetric(String.format("%s_%s", getTag(), logcat.getName()), logcat);
-        } catch (IOException e) {
-            Log.e(getTag(), "Error executing: " + command, e);
+        } catch (IOException | InterruptedException e) {
+            Log.e(getTag(), "Error trying to retrieve logcat.", e);
         }
     }
 
+    /** @hide */
     @VisibleForTesting
-    protected InputStream getLogcat(String command) {
-        return new ParcelFileDescriptor.AutoCloseInputStream(
-                getInstrumentation().getUiAutomation().executeShellCommand(command));
+    protected void getLogcatSince(String startTime, File saveTo)
+            throws IOException, InterruptedException {
+        // ProcessBuilder is used here in favor of UiAutomation.executeShellCommand() because the
+        // logcat command requires the timestamp to be quoted which in Java requires
+        // Runtime.exec(String[]) or ProcessBuilder to work properly, and UiAutomation does not
+        // support this for now.
+        ProcessBuilder pb = new ProcessBuilder(Arrays.asList("logcat", "-t", startTime));
+        pb.redirectOutput(saveTo);
+        Process proc = pb.start();
+        // Make the process blocking to ensure consistent behavior.
+        proc.waitFor();
     }
 
-    private String getCurrentDate() {
-        Date date = new Date();
-        String strDateFormat = "MM-DD hh:mm:ss.mmm";
-        DateFormat dateFormat = new SimpleDateFormat(strDateFormat);
-        return dateFormat.format(date);
+    /** @hide */
+    @VisibleForTesting
+    protected String getCurrentDate() {
+        // Get time using system (wall clock) time since this is the time that logcat is based on.
+        Date date = new Date(System.currentTimeMillis());
+        return DATE_FORMATTER.format(date);
     }
 }
diff --git a/libraries/device-collectors/src/test/java/android/device/collectors/LogcatOnFailureCollectorTest.java b/libraries/device-collectors/src/test/java/android/device/collectors/LogcatOnFailureCollectorTest.java
index 91d3647a1..30069834b 100644
--- a/libraries/device-collectors/src/test/java/android/device/collectors/LogcatOnFailureCollectorTest.java
+++ b/libraries/device-collectors/src/test/java/android/device/collectors/LogcatOnFailureCollectorTest.java
@@ -19,6 +19,8 @@ import android.app.Instrumentation;
 import android.device.collectors.util.SendToInstrumentation;
 import android.os.Bundle;
 import android.os.Environment;
+import android.os.SystemClock;
+import android.util.Log;
 
 import androidx.test.runner.AndroidJUnit4;
 
@@ -32,16 +34,19 @@ import org.junit.runner.RunWith;
 import org.mockito.ArgumentCaptor;
 import org.mockito.Mockito;
 
-import java.io.ByteArrayInputStream;
+import java.io.BufferedReader;
 import java.io.File;
+import java.io.FileReader;
+import java.text.ParsePosition;
+import java.text.SimpleDateFormat;
+import java.util.Calendar;
 import java.util.List;
 
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
 import static org.junit.Assert.assertTrue;
 
-/**
- * Run with {@link LogcatOnFailureCollector}.
- */
+/** Unit tests for {@link LogcatOnFailureCollector}. */
 @RunWith(AndroidJUnit4.class)
 public final class LogcatOnFailureCollectorTest {
 
@@ -49,6 +54,16 @@ public final class LogcatOnFailureCollectorTest {
     private static final Description RUN_DESCRIPTION = Description.createSuiteDescription("run");
     private static final Description TEST_DESCRIPTION =
             Description.createTestDescription("run", "test");
+    // A template for a logcat line for the purpose of this test. The three parameters are type (
+    // info, warning, etc.), log tag and message.
+    private static final String LOGCAT_REGEX_TEMPLATE =
+            "^\\d{2}-\\d{2}\\s+\\d{2}:\\d{2}:\\d{2}\\.\\d{3}[\\s\\d]+%s\\s+%s\\s*:\\s+%s$";
+
+    // A version of the date formatter used in the actual collector with the year added in, as the
+    // logcat itself does not include year by default, and it is better not to enable it there
+    // as it will just end up being visual noise for the user.
+    private static final SimpleDateFormat DATE_FORMATTER =
+            new SimpleDateFormat("yyyy " + LogcatOnFailureCollector.DATE_FORMATTER.toPattern());
 
     private File mLogDir;
     private LogcatOnFailureCollector mCollector;
@@ -71,14 +86,15 @@ public final class LogcatOnFailureCollectorTest {
         LogcatOnFailureCollector listener = Mockito.spy(mCollector);
         listener.setInstrumentation(mMockInstrumentation);
         Mockito.doReturn(mLogDir).when(listener).createAndEmptyDirectory(Mockito.anyString());
-        Mockito.doReturn(new ByteArrayInputStream("".getBytes()))
-                .when(listener).getLogcat(Mockito.anyString());
         return listener;
     }
 
     @Test
     public void testLogcatOnFailure_nofailure() throws Exception {
         LogcatOnFailureCollector listener = initListener();
+        Mockito.doNothing()
+                .when(listener)
+                .getLogcatSince(Mockito.any(String.class), Mockito.any(File.class));
         // Test run start behavior
         listener.testRunStarted(RUN_DESCRIPTION);
 
@@ -98,6 +114,9 @@ public final class LogcatOnFailureCollectorTest {
     @Test
     public void testLogcatOnFailure() throws Exception {
         LogcatOnFailureCollector listener = initListener();
+        Mockito.doNothing()
+                .when(listener)
+                .getLogcatSince(Mockito.any(String.class), Mockito.any(File.class));
         // Test run start behavior
         listener.testRunStarted(RUN_DESCRIPTION);
 
@@ -126,4 +145,213 @@ public final class LogcatOnFailureCollectorTest {
             assertTrue(key.contains("run.test.txt"));
         }
     }
+
+    /** Test that the collector can actually retrieve logcat. */
+    @Test
+    public void testRetrievingLogcat() throws Exception {
+        LogcatOnFailureCollector listener = initListener();
+        // Test run start behavior
+        listener.testRunStarted(RUN_DESCRIPTION);
+
+        Description testDescription = Description.createTestDescription("run", "test_logcat");
+        // Test test start behavior
+        listener.testStarted(testDescription);
+        // Log three lines after a short delay.
+        SystemClock.sleep(10);
+        String logTag = this.getClass().getSimpleName() + "_testRetrievingLogcat";
+        Log.i(logTag, "Message 1");
+        Log.w(logTag, "Message 2");
+        Log.e(logTag, "Message 3");
+        SystemClock.sleep(10);
+        Failure f = new Failure(testDescription, new RuntimeException("I failed."));
+        listener.testFailure(f);
+        listener.testFinished(testDescription);
+        listener.testRunFinished(new Result());
+        // AJUR runner is then gonna call instrumentationRunFinished
+        Bundle resultBundle = new Bundle();
+        listener.instrumentationRunFinished(System.out, resultBundle, new Result());
+        assertEquals(0, resultBundle.size());
+
+        ArgumentCaptor<Bundle> capture = ArgumentCaptor.forClass(Bundle.class);
+        Mockito.verify(mMockInstrumentation)
+                .sendStatus(
+                        Mockito.eq(SendToInstrumentation.INST_STATUS_IN_PROGRESS),
+                        capture.capture());
+        List<Bundle> capturedBundle = capture.getAllValues();
+        assertEquals(1, capturedBundle.size());
+        Bundle check = capturedBundle.get(0);
+        // Ensure we received the file
+        assertEquals(1, check.size());
+        String logPath = null;
+        for (String key : check.keySet()) {
+            if (key.contains("run.test_logcat")) {
+                logPath = check.getString(key);
+            }
+        }
+        assertTrue(logPath != null);
+
+        String message1Regex = String.format(LOGCAT_REGEX_TEMPLATE, "I", logTag, "Message 1");
+        String message2Regex = String.format(LOGCAT_REGEX_TEMPLATE, "W", logTag, "Message 2");
+        String message3Regex = String.format(LOGCAT_REGEX_TEMPLATE, "E", logTag, "Message 3");
+        // Read the metric file and check that the lines logged in this test are present.
+        boolean hasMessage1 = false;
+        boolean hasMessage2 = false;
+        boolean hasMessage3 = false;
+        try (BufferedReader reader = new BufferedReader(new FileReader(new File(logPath)))) {
+            for (String line = reader.readLine(); line != null; line = reader.readLine()) {
+                if (line.matches(message1Regex)) {
+                    hasMessage1 = true;
+                }
+                if (line.matches(message2Regex)) {
+                    hasMessage2 = true;
+                }
+                if (line.matches(message3Regex)) {
+                    hasMessage3 = true;
+                }
+            }
+            assertTrue(hasMessage1);
+            assertTrue(hasMessage2);
+            assertTrue(hasMessage3);
+        }
+    }
+
+    /** Test that the logcat retrieved are within the time bounds of the test. */
+    @Test
+    public void testLogcatTimespan() throws Exception {
+        LogcatOnFailureCollector listener = initListener();
+
+        listener.testRunStarted(RUN_DESCRIPTION);
+        // Store the start time of the test. The logcat should begin after this time.
+        long startTimeMillis = System.currentTimeMillis();
+        Description testDescription = Description.createTestDescription("run", "test_logcat_time");
+        // Test test start behavior
+        listener.testStarted(testDescription);
+        // Log three lines after a short delay.
+        SystemClock.sleep(10);
+        String logTag = this.getClass().getSimpleName() + "_testRetrievingLogcat";
+        Log.i(logTag, "Message");
+        Log.i(logTag, "Another message");
+        SystemClock.sleep(10);
+        listener.testFailure(new Failure(testDescription, new RuntimeException("I failed.")));
+        listener.testFinished(testDescription);
+        // Store the end time of the test. The logcat should end before this time.
+        long endTimeMillis = System.currentTimeMillis();
+        listener.testRunFinished(new Result());
+
+        // AJUR runner is then gonna call instrumentationRunFinished
+        Bundle resultBundle = new Bundle();
+        listener.instrumentationRunFinished(System.out, resultBundle, new Result());
+        assertEquals(0, resultBundle.size());
+
+        ArgumentCaptor<Bundle> capture = ArgumentCaptor.forClass(Bundle.class);
+        Mockito.verify(mMockInstrumentation)
+                .sendStatus(
+                        Mockito.eq(SendToInstrumentation.INST_STATUS_IN_PROGRESS),
+                        capture.capture());
+        List<Bundle> capturedBundle = capture.getAllValues();
+        assertEquals(1, capturedBundle.size());
+        Bundle check = capturedBundle.get(0);
+        // Ensure we received the file
+        assertEquals(1, check.size());
+        String logPath = null;
+        for (String key : check.keySet()) {
+            if (key.contains("run.test_logcat")) {
+                logPath = check.getString(key);
+            }
+        }
+        assertTrue(logPath != null);
+
+        // A regex to match any logcat line for the purpose of this test.
+        String logcatLineRegex = String.format(LOGCAT_REGEX_TEMPLATE, "[A-Z]", ".*", ".*");
+        String year = String.format("%04d", Calendar.getInstance().get(Calendar.YEAR));
+        String startTime = null;
+        String endTime = null;
+        try (BufferedReader reader = new BufferedReader(new FileReader(new File(logPath)))) {
+            String firstLine = null;
+            String lastLine = null;
+            for (String line = reader.readLine(); line != null; line = reader.readLine()) {
+                // Skip the "--- beginning of..." lines.
+                if (line.matches("^-+\\s+beginning of.*$")) {
+                    continue;
+                }
+                if (firstLine == null) {
+                    firstLine = line;
+                }
+                lastLine = line;
+            }
+            // These lines should be present.
+            assertNotNull(firstLine);
+            assertNotNull(lastLine);
+            // These lines should be logcat lines.
+            assertTrue(firstLine.matches(logcatLineRegex));
+            assertTrue(lastLine.matches(logcatLineRegex));
+            // Parse the timestamp at the start of the logcat lines. They should fall within the
+            // start and end time recorded in the test.
+            // Note that it is necessary to prepend the year to the logcat lines or the dates will
+            // end up in 1970.
+            long firstTimestamp =
+                    DATE_FORMATTER.parse(year + " " + firstLine, new ParsePosition(0)).getTime();
+            long lastTimestamp =
+                    DATE_FORMATTER.parse(year + " " + lastLine, new ParsePosition(0)).getTime();
+            assertTrue(firstTimestamp >= startTimeMillis);
+            assertTrue(lastTimestamp <= endTimeMillis);
+            assertTrue(firstTimestamp <= lastTimestamp);
+        }
+    }
+
+    /** Test that the logcat collection supports multiple iterations. */
+    @Test
+    public void testMultipleIterations() throws Exception {
+        LogcatOnFailureCollector listener = initListener();
+        Mockito.doNothing()
+                .when(listener)
+                .getLogcatSince(Mockito.any(String.class), Mockito.any(File.class));
+        Failure f = new Failure(TEST_DESCRIPTION, new RuntimeException("I failed."));
+
+        listener.testRunStarted(RUN_DESCRIPTION);
+
+        // Schedule 3 identical tests.
+        // Fail the first one.
+        listener.testStarted(TEST_DESCRIPTION);
+        listener.testFailure(f);
+        listener.testFinished(TEST_DESCRIPTION);
+        // Let the second one pass.
+        listener.testStarted(TEST_DESCRIPTION);
+        listener.testFinished(TEST_DESCRIPTION);
+        // Fail the third one.
+        listener.testStarted(TEST_DESCRIPTION);
+        listener.testFailure(f);
+        listener.testFinished(TEST_DESCRIPTION);
+
+        listener.testRunFinished(new Result());
+        // AJUR runner is then gonna call instrumentationRunFinished
+        Bundle resultBundle = new Bundle();
+        listener.instrumentationRunFinished(System.out, resultBundle, new Result());
+        assertEquals(0, resultBundle.size());
+
+        ArgumentCaptor<Bundle> capture = ArgumentCaptor.forClass(Bundle.class);
+        Mockito.verify(mMockInstrumentation, Mockito.times(2))
+                .sendStatus(
+                        Mockito.eq(SendToInstrumentation.INST_STATUS_IN_PROGRESS),
+                        capture.capture());
+        List<Bundle> capturedBundles = capture.getAllValues();
+        // 2 bundles as we have two tests that failed (and thus has metrics).
+        assertEquals(2, capturedBundles.size());
+
+        // The first bundle should have the first logcat file, for the first iteration.
+        Bundle check1 = capturedBundles.get(0);
+        assertEquals(1, check1.size());
+        for (String key : check1.keySet()) {
+            // The first iteration should not have an iteration number.
+            assertTrue(key.contains("run.test.txt"));
+        }
+
+        // The second bundle should have the second logcat file, for the third iteration.
+        Bundle check2 = capturedBundles.get(1);
+        assertEquals(1, check2.size());
+        for (String key : check2.keySet()) {
+            // The third iteration should have an iteration number, 3.
+            assertTrue(key.contains("run.test-3.txt"));
+        }
+    }
 }