Merge "Changing event check implementation from logcat to TestProtocol" into ub-launcher3-rvc-dev

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<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);
         }

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<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;
+    }
 }

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";

tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java

@@ -165,9 +165,7 @@ public final class LauncherInstrumentation {
 
     private Consumer<ContainerType> mOnSettledStateAction;
 
-    private static LogEventChecker sEventChecker;
+    private LogEventChecker mEventChecker;
-    // True if there is an gesture in progress that needs event verification.
-    private static boolean sCheckingEvents;
 
     private boolean mCheckEventsForSuccessfulGestures = false;
     private Runnable mOnLauncherCrashed;
@@ -437,15 +435,16 @@ public final class LauncherInstrumentation {
     }
 
     private String formatErrorWithEvents(String message, boolean checkEvents) {
-        if (sCheckingEvents) {
+        if (mEventChecker != null) {
-            sCheckingEvents = false;
+            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();
+        final LogEventChecker eventChecker = new LogEventChecker(this);
-        sEventChecker.start();
+        if (eventChecker.start()) mEventChecker = eventChecker;
-        sCheckingEvents = true;
 
         return () -> {
             if (initialPid != null && initialPid.intValue() != getPid()) {
@@ -1353,10 +1351,10 @@ public final class LauncherInstrumentation {
                                 formatErrorWithEvents("Launcher crashed", false)));
             }
 
-            if (sCheckingEvents) {
+            if (mEventChecker != null) {
-                sCheckingEvents = false;
+                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) {

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.os.SystemClock;
-
-import android.util.Log;
 
 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(
+    private final LauncherInstrumentation mLauncher;
-            ".*" + 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;
 
     // 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<>();
+    LogEventChecker(LauncherInstrumentation launcher) {
-    private final Semaphore mEventsCounter = new Semaphore(0);
+        mLauncher = launcher;
-
-    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();
     }
 
-    void start() {
+    boolean 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");
         mExpectedEvents.clear();
-        mEventsCounter.drainPermits();
+        return mLauncher.getTestInfo(TestProtocol.REQUEST_START_EVENT_LOGGING) != null;
-        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);
-        }
     }
 
     void expectPattern(String sequence, Pattern pattern) {
         mExpectedEvents.add(sequence, pattern);
     }
 
-    private void finishSync(long waitForExpectedCountMs) {
+    // Waits for the expected number of events and returns them.
-        try {
+    private ListMap<String> finishSync(long waitForExpectedCountMs) {
-            // Wait until Launcher generates the expected number of events.
+        final long startTime = SystemClock.uptimeMillis();
-            int expectedCount = mExpectedEvents.entrySet()
+        // 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);
+            if (rawEvents.size() >= expectedCount
-            finishNoWait();
+                    || SystemClock.uptimeMillis() > startTime + waitForExpectedCountMs) {
-            mFinished.await();
+                break;
-            mFinished = null;
-        } catch (InterruptedException e) {
-            throw new RuntimeException(e);
             }
+            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);
+        mLauncher.getTestInfo(TestProtocol.REQUEST_STOP_EVENT_LOGGING);
-        Log.d(TestProtocol.TAPL_EVENTS_TAG, mFinishCommand);
     }
 
     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));
+            List<String> actual = new ArrayList<>(actualEvents.getNonNull(sequence));
-            Log.d(SKIP_EVENTS_TAG, "Verifying events");
             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);
             }
         }