From a17a10cddd10158eb5ab679b773528e3197bd47b Mon Sep 17 00:00:00 2001 From: vadimt Date: Fri, 19 Jun 2020 15:00:00 -0700 Subject: [PATCH] Changing event check implementation from logcat to TestProtocol Bug: 153670015 Change-Id: Id9fc759bd5be68758ef9cf0abbba3cd6fa452796 --- .../testing/DebugTestInformationHandler.java | 31 ++++ .../launcher3/testing/TestLogging.java | 12 ++ .../launcher3/testing/TestProtocol.java | 3 + .../tapl/LauncherInstrumentation.java | 34 ++-- .../launcher3/tapl/LogEventChecker.java | 162 ++++-------------- 5 files changed, 101 insertions(+), 141 deletions(-) diff --git a/ext_tests/src/com/android/launcher3/testing/DebugTestInformationHandler.java b/ext_tests/src/com/android/launcher3/testing/DebugTestInformationHandler.java index b84c7aa8e8..ad21106759 100644 --- a/ext_tests/src/com/android/launcher3/testing/DebugTestInformationHandler.java +++ b/ext_tests/src/com/android/launcher3/testing/DebugTestInformationHandler.java @@ -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 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 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); } diff --git a/src/com/android/launcher3/testing/TestLogging.java b/src/com/android/launcher3/testing/TestLogging.java index d522d81665..51e081972f 100644 --- a/src/com/android/launcher3/testing/TestLogging.java +++ b/src/com/android/launcher3/testing/TestLogging.java @@ -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 sEventConsumer; + private static void recordEventSlow(String sequence, String event) { Log.d(TestProtocol.TAPL_EVENTS_TAG, sequence + " / " + event); + final BiConsumer 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 consumer) { + sEventConsumer = consumer; + } } diff --git a/src/com/android/launcher3/testing/TestProtocol.java b/src/com/android/launcher3/testing/TestProtocol.java index 519b1b993f..49da7b3d8d 100644 --- a/src/com/android/launcher3/testing/TestProtocol.java +++ b/src/com/android/launcher3/testing/TestProtocol.java @@ -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"; diff --git a/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java b/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java index 9f4d9cea43..f634ce1951 100644 --- a/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java +++ b/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java @@ -165,9 +165,7 @@ public final class LauncherInstrumentation { private Consumer 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) { diff --git a/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java b/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java index 79d20ace68..4440b82976 100644 --- a/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java +++ b/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java @@ -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 + ": (?[a-zA-Z]+) / (?.*)"); - - 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 mExpectedEvents = new ListMap<>(); - private final ListMap 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 finishSync(long waitForExpectedCountMs) { + final long startTime = SystemClock.uptimeMillis(); + // Event strings with '/' separating the sequence and the event. + ArrayList 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 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 actualEvents = finishSync(waitForExpectedCountMs); final StringBuilder sb = new StringBuilder(); boolean hasMismatches = false; for (Map.Entry> expectedEvents : mExpectedEvents.entrySet()) { String sequence = expectedEvents.getKey(); - List actual = new ArrayList<>(mEvents.getNonNull(sequence)); - Log.d(SKIP_EVENTS_TAG, "Verifying events"); + List 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); } }