Changing event check implementation from logcat to TestProtocol

Bug: 153670015
Change-Id: Id9fc759bd5be68758ef9cf0abbba3cd6fa452796
This commit is contained in:
vadimt 2020-06-19 15:00:00 -07:00
parent 6dac493218
commit a17a10cddd
5 changed files with 101 additions and 141 deletions

View File

@ -28,6 +28,8 @@ import android.view.View;
import androidx.annotation.Keep;
import java.util.ArrayList;
import java.util.Collection;
import java.util.LinkedList;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
@ -37,6 +39,7 @@ import java.util.concurrent.TimeUnit;
*/
public class DebugTestInformationHandler extends TestInformationHandler {
private static LinkedList sLeaks;
private static Collection<String> sEvents;
public DebugTestInformationHandler(Context context) {
init(context);
@ -134,6 +137,34 @@ public class DebugTestInformationHandler extends TestInformationHandler {
return response;
}
case TestProtocol.REQUEST_START_EVENT_LOGGING: {
sEvents = new ArrayList<>();
TestLogging.setEventConsumer(
(sequence, event) -> {
final Collection<String> events = sEvents;
if (events != null) {
synchronized (events) {
events.add(sequence + '/' + event);
}
}
});
return response;
}
case TestProtocol.REQUEST_STOP_EVENT_LOGGING: {
TestLogging.setEventConsumer(null);
sEvents = null;
return response;
}
case TestProtocol.REQUEST_GET_TEST_EVENTS: {
synchronized (sEvents) {
response.putStringArrayList(
TestProtocol.TEST_INFO_RESPONSE_FIELD, new ArrayList<>(sEvents));
}
return response;
}
default:
return super.call(method);
}

View File

@ -21,9 +21,17 @@ import android.view.MotionEvent;
import com.android.launcher3.Utilities;
import java.util.function.BiConsumer;
public final class TestLogging {
private static BiConsumer<String, String> sEventConsumer;
private static void recordEventSlow(String sequence, String event) {
Log.d(TestProtocol.TAPL_EVENTS_TAG, sequence + " / " + event);
final BiConsumer<String, String> eventConsumer = sEventConsumer;
if (eventConsumer != null) {
eventConsumer.accept(sequence, event);
}
}
public static void recordEvent(String sequence, String event) {
@ -43,4 +51,8 @@ public final class TestLogging {
recordEventSlow(sequence, message + ": " + event);
}
}
static void setEventConsumer(BiConsumer<String, String> consumer) {
sEventConsumer = consumer;
}
}

View File

@ -88,6 +88,9 @@ public final class TestProtocol {
public static final String REQUEST_NATIVE_LEAK = "native-leak";
public static final String REQUEST_VIEW_LEAK = "view-leak";
public static final String REQUEST_RECENT_TASKS_LIST = "recent-tasks-list";
public static final String REQUEST_START_EVENT_LOGGING = "start-event-logging";
public static final String REQUEST_GET_TEST_EVENTS = "get-test-events";
public static final String REQUEST_STOP_EVENT_LOGGING = "stop-event-logging";
public static boolean sDebugTracing = false;
public static final String REQUEST_ENABLE_DEBUG_TRACING = "enable-debug-tracing";

View File

@ -165,9 +165,7 @@ public final class LauncherInstrumentation {
private Consumer<ContainerType> mOnSettledStateAction;
private static LogEventChecker sEventChecker;
// True if there is an gesture in progress that needs event verification.
private static boolean sCheckingEvents;
private LogEventChecker mEventChecker;
private boolean mCheckEventsForSuccessfulGestures = false;
private Runnable mOnLauncherCrashed;
@ -437,15 +435,16 @@ public final class LauncherInstrumentation {
}
private String formatErrorWithEvents(String message, boolean checkEvents) {
if (sCheckingEvents) {
sCheckingEvents = false;
if (mEventChecker != null) {
final LogEventChecker eventChecker = mEventChecker;
mEventChecker = null;
if (checkEvents) {
final String eventMismatch = sEventChecker.verify(0, false);
final String eventMismatch = eventChecker.verify(0, false);
if (eventMismatch != null) {
message = message + ", having produced " + eventMismatch;
}
} else {
sEventChecker.finishNoWait();
eventChecker.finishNoWait();
}
}
@ -1337,12 +1336,11 @@ public final class LauncherInstrumentation {
}
public Closable eventsCheck() {
Assert.assertTrue("Nested event checking", !sCheckingEvents);
Assert.assertTrue("Nested event checking", mEventChecker == null);
disableSensorRotation();
final Integer initialPid = getPid();
if (sEventChecker == null) sEventChecker = new LogEventChecker();
sEventChecker.start();
sCheckingEvents = true;
final LogEventChecker eventChecker = new LogEventChecker(this);
if (eventChecker.start()) mEventChecker = eventChecker;
return () -> {
if (initialPid != null && initialPid.intValue() != getPid()) {
@ -1353,10 +1351,10 @@ public final class LauncherInstrumentation {
formatErrorWithEvents("Launcher crashed", false)));
}
if (sCheckingEvents) {
sCheckingEvents = false;
if (mEventChecker != null) {
mEventChecker = null;
if (mCheckEventsForSuccessfulGestures) {
final String message = sEventChecker.verify(WAIT_TIME_MS, true);
final String message = eventChecker.verify(WAIT_TIME_MS, true);
if (message != null) {
dumpDiagnostics();
checkForAnomaly();
@ -1364,7 +1362,7 @@ public final class LauncherInstrumentation {
"http://go/tapl : successful gesture produced " + message));
}
} else {
sEventChecker.finishNoWait();
eventChecker.finishNoWait();
}
}
};
@ -1375,7 +1373,11 @@ public final class LauncherInstrumentation {
}
void expectEvent(String sequence, Pattern expected) {
if (sCheckingEvents) sEventChecker.expectPattern(sequence, expected);
if (mEventChecker != null) {
mEventChecker.expectPattern(sequence, expected);
} else {
Log.d(TAG, "Expecting: " + sequence + " / " + expected);
}
}
Rect getVisibleBounds(UiObject2 object) {

View File

@ -15,169 +15,81 @@
*/
package com.android.launcher3.tapl;
import static java.util.concurrent.TimeUnit.MILLISECONDS;
import android.util.Log;
import android.os.SystemClock;
import com.android.launcher3.testing.TestProtocol;
import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStreamReader;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.UUID;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.Semaphore;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
/**
* Utility class to read log on a background thread.
* Utility class to verify expected events.
*/
public class LogEventChecker {
private static final Pattern EVENT_LOG_ENTRY = Pattern.compile(
".*" + TestProtocol.TAPL_EVENTS_TAG + ": (?<sequence>[a-zA-Z]+) / (?<event>.*)");
private static final String START_PREFIX = "START_READER ";
private static final String FINISH_PREFIX = "FINISH_READER ";
private static final String SKIP_EVENTS_TAG = "b/153670015";
private volatile CountDownLatch mFinished;
private final LauncherInstrumentation mLauncher;
// Map from an event sequence name to an ordered list of expected events in that sequence.
private final ListMap<Pattern> mExpectedEvents = new ListMap<>();
private final ListMap<String> mEvents = new ListMap<>();
private final Semaphore mEventsCounter = new Semaphore(0);
private volatile String mStartCommand;
private volatile String mFinishCommand;
LogEventChecker() {
final Thread thread = new Thread(this::onRun, "log-reader-thread");
thread.setPriority(Thread.NORM_PRIORITY);
thread.start();
LogEventChecker(LauncherInstrumentation launcher) {
mLauncher = launcher;
}
void start() {
if (mFinished != null) {
try {
mFinished.await();
} catch (InterruptedException e) {
throw new RuntimeException(e);
} finally {
mFinished = null;
}
}
mEvents.clear();
Log.d(SKIP_EVENTS_TAG, "Cleared events");
boolean start() {
mExpectedEvents.clear();
mEventsCounter.drainPermits();
final String id = UUID.randomUUID().toString();
mStartCommand = START_PREFIX + id;
mFinishCommand = FINISH_PREFIX + id;
Log.d(SKIP_EVENTS_TAG, "Expected finish command: " + mFinishCommand);
Log.d(TestProtocol.TAPL_EVENTS_TAG, mStartCommand);
}
private void onRun() {
while (true) readEvents();
}
private void readEvents() {
try {
// Note that we use Runtime.exec to start the log reading process instead of running
// it via UIAutomation, so that we can directly access the "Process" object and
// ensure that the instrumentation is not stuck forever.
final String cmd = "logcat -s " + TestProtocol.TAPL_EVENTS_TAG;
final Process logcatProcess = Runtime.getRuntime().exec(cmd);
try (BufferedReader reader = new BufferedReader(new InputStreamReader(
logcatProcess.getInputStream()))) {
while (true) {
// Skip everything before the next start command.
for (; ; ) {
final String event = reader.readLine();
if (event == null) {
Log.d(SKIP_EVENTS_TAG, "Read a null line while waiting for start");
return;
}
if (event.contains(mStartCommand)) {
Log.d(SKIP_EVENTS_TAG, "Read start: " + event);
break;
}
}
// Store all actual events until the finish command.
for (; ; ) {
final String event = reader.readLine();
if (event == null) {
Log.d(SKIP_EVENTS_TAG, "Read a null line after waiting for start");
mEventsCounter.drainPermits();
mEvents.clear();
return;
}
if (event.contains(mFinishCommand)) {
mFinished.countDown();
Log.d(SKIP_EVENTS_TAG, "Read finish: " + event);
break;
} else {
final Matcher matcher = EVENT_LOG_ENTRY.matcher(event);
if (matcher.find()) {
mEvents.add(matcher.group("sequence"), matcher.group("event"));
Log.d(SKIP_EVENTS_TAG, "Read event: " + event);
mEventsCounter.release();
} else {
Log.d(SKIP_EVENTS_TAG, "Read something unexpected: " + event);
}
}
}
}
} finally {
logcatProcess.destroyForcibly();
}
} catch (IOException e) {
throw new RuntimeException(e);
}
return mLauncher.getTestInfo(TestProtocol.REQUEST_START_EVENT_LOGGING) != null;
}
void expectPattern(String sequence, Pattern pattern) {
mExpectedEvents.add(sequence, pattern);
}
private void finishSync(long waitForExpectedCountMs) {
try {
// Wait until Launcher generates the expected number of events.
int expectedCount = mExpectedEvents.entrySet()
// Waits for the expected number of events and returns them.
private ListMap<String> finishSync(long waitForExpectedCountMs) {
final long startTime = SystemClock.uptimeMillis();
// Event strings with '/' separating the sequence and the event.
ArrayList<String> rawEvents;
while (true) {
rawEvents = mLauncher.getTestInfo(TestProtocol.REQUEST_GET_TEST_EVENTS)
.getStringArrayList(TestProtocol.TEST_INFO_RESPONSE_FIELD);
final int expectedCount = mExpectedEvents.entrySet()
.stream().mapToInt(e -> e.getValue().size()).sum();
mEventsCounter.tryAcquire(expectedCount, waitForExpectedCountMs, MILLISECONDS);
finishNoWait();
mFinished.await();
mFinished = null;
} catch (InterruptedException e) {
throw new RuntimeException(e);
if (rawEvents.size() >= expectedCount
|| SystemClock.uptimeMillis() > startTime + waitForExpectedCountMs) {
break;
}
SystemClock.sleep(100);
}
finishNoWait();
// Parse raw events into a map.
final ListMap<String> eventSequences = new ListMap<>();
for (String rawEvent : rawEvents) {
final String[] split = rawEvent.split("/");
eventSequences.add(split[0], split[1]);
}
return eventSequences;
}
void finishNoWait() {
mFinished = new CountDownLatch(1);
Log.d(TestProtocol.TAPL_EVENTS_TAG, mFinishCommand);
mLauncher.getTestInfo(TestProtocol.REQUEST_STOP_EVENT_LOGGING);
}
String verify(long waitForExpectedCountMs, boolean successfulGesture) {
finishSync(waitForExpectedCountMs);
final ListMap<String> actualEvents = finishSync(waitForExpectedCountMs);
final StringBuilder sb = new StringBuilder();
boolean hasMismatches = false;
for (Map.Entry<String, List<Pattern>> expectedEvents : mExpectedEvents.entrySet()) {
String sequence = expectedEvents.getKey();
List<String> actual = new ArrayList<>(mEvents.getNonNull(sequence));
Log.d(SKIP_EVENTS_TAG, "Verifying events");
List<String> actual = new ArrayList<>(actualEvents.getNonNull(sequence));
final int mismatchPosition = getMismatchPosition(expectedEvents.getValue(), actual);
hasMismatches = hasMismatches
|| mismatchPosition != -1 && !ignoreMistatch(successfulGesture, sequence);
@ -189,7 +101,7 @@ public class LogEventChecker {
mismatchPosition);
}
// Check for unexpected event sequences in the actual data.
for (String actualNamedSequence : mEvents.keySet()) {
for (String actualNamedSequence : actualEvents.keySet()) {
if (!mExpectedEvents.containsKey(actualNamedSequence)) {
hasMismatches = hasMismatches
|| !ignoreMistatch(successfulGesture, actualNamedSequence);
@ -197,7 +109,7 @@ public class LogEventChecker {
sb,
actualNamedSequence,
new ArrayList<>(),
mEvents.get(actualNamedSequence),
actualEvents.get(actualNamedSequence),
0);
}
}