Merge "Fixed LogcatOnFailureCollector and made it iteration-aware."
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 61a30a5..aaa9944 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 @@
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 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 @@
*/
@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 @@
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 @@
@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 @@
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 91d3647..3006983 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.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.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 @@
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 @@
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 @@
@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 @@
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"));
+ }
+ }
}
