Merge "Updating logcat reading logic" into ub-launcher3-master
diff --git a/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java b/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java
index c5fbd7c..b3b887d 100644
--- a/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java
+++ b/tests/tapl/com/android/launcher3/tapl/LauncherInstrumentation.java
@@ -69,22 +69,16 @@
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.lang.ref.WeakReference;
-import java.text.ParseException;
-import java.text.SimpleDateFormat;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
-import java.util.Date;
import java.util.Deque;
-import java.util.HashMap;
import java.util.LinkedList;
import java.util.List;
-import java.util.Map;
import java.util.concurrent.TimeoutException;
import java.util.function.Consumer;
import java.util.function.Function;
import java.util.function.Supplier;
-import java.util.regex.Matcher;
import java.util.regex.Pattern;
import java.util.stream.Collectors;
@@ -97,16 +91,8 @@
private static final String TAG = "Tapl";
private static final int ZERO_BUTTON_STEPS_FROM_BACKGROUND_TO_HOME = 20;
private static final int GESTURE_STEP_MS = 16;
- private static final SimpleDateFormat DATE_TIME_FORMAT =
- new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
private static long START_TIME = System.currentTimeMillis();
- static final Pattern EVENT_LOG_ENTRY = Pattern.compile(
- "(?<time>[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] "
- + "[0-9][0-9]:[0-9][0-9]:[0-9][0-9]\\.[0-9][0-9][0-9])"
- + ".*" + TestProtocol.TAPL_EVENTS_TAG + ": (?<sequence>[a-zA-Z]+) / "
- + "(?<event>.*)");
-
private static final Pattern EVENT_TOUCH_DOWN = getTouchEventPattern("ACTION_DOWN");
private static final Pattern EVENT_TOUCH_UP = getTouchEventPattern("ACTION_UP");
private static final Pattern EVENT_TOUCH_CANCEL = getTouchEventPattern("ACTION_CANCEL");
@@ -176,11 +162,10 @@
private Consumer<ContainerType> mOnSettledStateAction;
- // Map from an event sequence name to an ordered list of expected events in that sequence.
- // Not null when we are collecting expected events to compare with actual ones.
- private Map<String, List<Pattern>> mExpectedEvents;
+ private static LogEventChecker sEventChecker;
+ // True if there is an gesture in progress that needs event verification.
+ private static boolean sCheckingEvents;
- private Date mStartRecordingTime;
private boolean mCheckEventsForSuccessfulGestures = false;
private static Pattern getTouchEventPattern(String prefix, String action) {
@@ -434,10 +419,12 @@
log("Hierarchy dump for: " + message);
dumpViewHierarchy();
- final String eventMismatch = getEventMismatchMessage(false);
-
- if (eventMismatch != null) {
- message = message + ", having produced " + eventMismatch;
+ if (sCheckingEvents) {
+ sCheckingEvents = false;
+ final String eventMismatch = sEventChecker.verify(0);
+ if (eventMismatch != null) {
+ message = message + ", having produced " + eventMismatch;
+ }
}
Assert.fail(formatSystemHealthMessage(message));
@@ -1245,204 +1232,34 @@
return tasks;
}
- // Returns actual events retrieved from logcat. The return value's key set is the set of all
- // sequence names that actually had at least one event, and the values are lists of events in
- // the given sequence, in the order they were recorded.
- private Map<String, List<String>> getEvents() {
- final Map<String, List<String>> events = new HashMap<>();
- try {
- // Logcat may skip events after the specified time. Querying for events starting 1 min
- // earlier.
- final Date startTime = new Date(mStartRecordingTime.getTime() - 60000);
- final String logcatCommand = "logcat -d -v year --pid=" + getPid() + " -t "
- + DATE_TIME_FORMAT.format(startTime).replaceAll(" ", "")
- + " -s " + TestProtocol.TAPL_EVENTS_TAG;
- log("Events query command: " + logcatCommand);
- final String logcatEvents = mDevice.executeShellCommand(logcatCommand);
- final Matcher matcher = EVENT_LOG_ENTRY.matcher(logcatEvents);
- while (matcher.find()) {
- // Skip events before recording start time.
- if (DATE_TIME_FORMAT.parse(matcher.group("time"))
- .compareTo(mStartRecordingTime) < 0) {
- continue;
- }
-
- eventsListForSequence(matcher.group("sequence"), events).add(
- matcher.group("event"));
- }
- return events;
- } catch (IOException e) {
- throw new RuntimeException(e);
- } catch (ParseException e) {
- throw new AssertionError(e);
- }
- }
-
- // Returns an event list for a given sequence, adding it to the map as needed.
- private static <T> List<T> eventsListForSequence(
- String sequenceName, Map<String, List<T>> events) {
- List<T> eventSequence = events.get(sequenceName);
- if (eventSequence == null) {
- eventSequence = new ArrayList<>();
- events.put(sequenceName, eventSequence);
- }
- return eventSequence;
- }
-
- private void startRecordingEvents() {
- Assert.assertTrue("Already recording events", mExpectedEvents == null);
- mExpectedEvents = new HashMap<>();
- mStartRecordingTime = new Date();
- log("startRecordingEvents: " + DATE_TIME_FORMAT.format(mStartRecordingTime));
- }
-
- private void stopRecordingEvents() {
- mExpectedEvents = null;
- mStartRecordingTime = null;
- }
-
public Closable eventsCheck() {
+ Assert.assertTrue("Nested event checking", !sCheckingEvents);
if ("com.android.launcher3".equals(getLauncherPackageName())) {
// Not checking specific Launcher3 event sequences.
return () -> {
};
}
-
- // Entering events check block.
- startRecordingEvents();
+ sCheckingEvents = true;
+ if (sEventChecker == null) sEventChecker = new LogEventChecker();
+ sEventChecker.start();
return () -> {
- // Leaving events check block.
- if (mExpectedEvents == null) {
- return; // There was a failure. Noo need to report another one.
- }
-
- if (!mCheckEventsForSuccessfulGestures) {
- stopRecordingEvents();
- return;
- }
-
- final String message = getEventMismatchMessage(true);
- if (message != null) {
- Assert.fail(formatSystemHealthMessage(
- "http://go/tapl : successful gesture produced " + message));
+ if (sCheckingEvents) {
+ sCheckingEvents = false;
+ if (mCheckEventsForSuccessfulGestures) {
+ final String message = sEventChecker.verify(WAIT_TIME_MS);
+ if (message != null) {
+ Assert.fail(formatSystemHealthMessage(
+ "http://go/tapl : successful gesture produced " + message));
+ }
+ } else {
+ sEventChecker.finishNoWait();
+ }
}
};
}
void expectEvent(String sequence, Pattern expected) {
- if (mExpectedEvents != null) {
- eventsListForSequence(sequence, mExpectedEvents).add(expected);
- }
- }
-
- // Returns non-null error message if the actual events in logcat don't match expected events.
- // If we are not checking events, returns null.
- private String getEventMismatchMessage(boolean waitForExpectedCount) {
- if (mExpectedEvents == null) return null;
-
- try {
- Map<String, List<String>> actual = getEvents();
-
- if (waitForExpectedCount) {
- // Wait until Launcher generates the expected number of events.
- final long endTime = SystemClock.uptimeMillis() + WAIT_TIME_MS;
- while (SystemClock.uptimeMillis() < endTime
- && !receivedEnoughEvents(actual)) {
- SystemClock.sleep(100);
- actual = getEvents();
- }
- }
-
- return getEventMismatchErrorMessage(actual);
- } finally {
- stopRecordingEvents();
- }
- }
-
- // Returns whether there is a sufficient number of events in the logcat to match the expected
- // events.
- private boolean receivedEnoughEvents(Map<String, List<String>> actual) {
- for (Map.Entry<String, List<Pattern>> expectedNamedSequence : mExpectedEvents.entrySet()) {
- final List<String> actualEventSequence = actual.get(expectedNamedSequence.getKey());
- if (actualEventSequence == null
- || actualEventSequence.size() < expectedNamedSequence.getValue().size()) {
- return false;
- }
- }
- return true;
- }
-
- // If the list of actual events matches the list of expected events, returns -1, otherwise
- // the position of the mismatch.
- private static int getMismatchPosition(List<Pattern> expected, List<String> actual) {
- for (int i = 0; i < expected.size(); ++i) {
- if (i >= actual.size()
- || !expected.get(i).matcher(actual.get(i)).find()) {
- return i;
- }
- }
-
- if (actual.size() > expected.size()) return expected.size();
-
- return -1;
- }
-
- // Returns non-null error message if the actual events passed as a param don't match expected
- // events.
- private String getEventMismatchErrorMessage(Map<String, List<String>> actualEvents) {
- final StringBuilder sb = new StringBuilder();
-
- // Check that all expected even sequences match the actual data.
- for (Map.Entry<String, List<Pattern>> expectedNamedSequence : mExpectedEvents.entrySet()) {
- List<String> actualEventSequence = actualEvents.get(expectedNamedSequence.getKey());
- if (actualEventSequence == null) actualEventSequence = new ArrayList<>();
- final int mismatchPosition = getMismatchPosition(
- expectedNamedSequence.getValue(), actualEventSequence);
- if (mismatchPosition != -1) {
- formatSequenceWithMismatch(
- sb,
- expectedNamedSequence.getKey(),
- expectedNamedSequence.getValue(),
- actualEventSequence,
- mismatchPosition);
- }
- }
-
- // Check for unexpected event sequences in the actual data.
- for (Map.Entry<String, List<String>> actualNamedSequence : actualEvents.entrySet()) {
- if (!mExpectedEvents.containsKey(actualNamedSequence.getKey())) {
- formatSequenceWithMismatch(
- sb,
- actualNamedSequence.getKey(),
- new ArrayList<>(),
- actualNamedSequence.getValue(),
- 0);
- }
- }
-
- return sb.length() != 0 ? "mismatching events: " + sb.toString() : null;
- }
-
- private static void formatSequenceWithMismatch(
- StringBuilder sb,
- String sequenceName,
- List<Pattern> expected,
- List<String> actualEvents,
- int mismatchPosition) {
- sb.append("\n>> Sequence " + sequenceName);
- sb.append("\n Expected:");
- formatEventListWithMismatch(sb, expected, mismatchPosition);
- sb.append("\n Actual:");
- formatEventListWithMismatch(sb, actualEvents, mismatchPosition);
- }
-
- private static void formatEventListWithMismatch(StringBuilder sb, List events, int position) {
- for (int i = 0; i < events.size(); ++i) {
- sb.append("\n | ");
- sb.append(i == position ? "---> " : " ");
- sb.append(events.get(i).toString());
- }
- if (position == events.size()) sb.append("\n | ---> (end)");
+ if (sCheckingEvents) sEventChecker.expectPattern(sequence, expected);
}
}
\ No newline at end of file
diff --git a/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java b/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java
new file mode 100644
index 0000000..0fc88ee
--- /dev/null
+++ b/tests/tapl/com/android/launcher3/tapl/LogEventChecker.java
@@ -0,0 +1,233 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.android.launcher3.tapl;
+
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+
+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.
+ */
+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 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<>();
+ 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();
+ }
+
+ void start() {
+ if (mFinished != null) {
+ try {
+ mFinished.await();
+ } catch (InterruptedException e) {
+ throw new RuntimeException(e);
+ }
+ mFinished = null;
+ }
+ mEvents.clear();
+ mExpectedEvents.clear();
+ mEventsCounter.drainPermits();
+ final String id = UUID.randomUUID().toString();
+ mStartCommand = START_PREFIX + id;
+ mFinishCommand = FINISH_PREFIX + id;
+ Log.d(TestProtocol.TAPL_EVENTS_TAG, mStartCommand);
+ }
+
+ private void onRun() {
+ 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;
+
+ try (BufferedReader reader = new BufferedReader(new InputStreamReader(
+ Runtime.getRuntime().exec(cmd).getInputStream()))) {
+ for (;;) {
+ // Skip everything before the next start command.
+ for (;;) {
+ final String event = reader.readLine();
+ if (event.contains(TestProtocol.TAPL_EVENTS_TAG)
+ && event.contains(mStartCommand)) {
+ break;
+ }
+ }
+
+ // Store all actual events until the finish command.
+ for (;;) {
+ final String event = reader.readLine();
+ if (event.contains(TestProtocol.TAPL_EVENTS_TAG)) {
+ if (event.contains(mFinishCommand)) {
+ mFinished.countDown();
+ break;
+ } else {
+ final Matcher matcher = EVENT_LOG_ENTRY.matcher(event);
+ if (matcher.find()) {
+ mEvents.add(matcher.group("sequence"), matcher.group("event"));
+ mEventsCounter.release();
+ }
+ }
+ }
+ }
+ }
+ }
+ } catch (IOException e) {
+ throw new RuntimeException(e);
+ }
+ }
+
+ 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()
+ .stream().mapToInt(e -> e.getValue().size()).sum();
+ mEventsCounter.tryAcquire(expectedCount, waitForExpectedCountMs, MILLISECONDS);
+ finishNoWait();
+ mFinished.await();
+ mFinished = null;
+ } catch (InterruptedException e) {
+ throw new RuntimeException(e);
+ }
+ }
+
+ void finishNoWait() {
+ mFinished = new CountDownLatch(1);
+ Log.d(TestProtocol.TAPL_EVENTS_TAG, mFinishCommand);
+ }
+
+ String verify(long waitForExpectedCountMs) {
+ finishSync(waitForExpectedCountMs);
+
+ final StringBuilder sb = new StringBuilder();
+ for (Map.Entry<String, List<Pattern>> expectedEvents : mExpectedEvents.entrySet()) {
+ String sequence = expectedEvents.getKey();
+
+ List<String> actual = new ArrayList<>(mEvents.getNonNull(sequence));
+ final int mismatchPosition = getMismatchPosition(expectedEvents.getValue(), actual);
+ if (mismatchPosition != -1) {
+ formatSequenceWithMismatch(
+ sb,
+ sequence,
+ expectedEvents.getValue(),
+ actual,
+ mismatchPosition);
+ }
+ }
+ // Check for unexpected event sequences in the actual data.
+ for (String actualNamedSequence : mEvents.keySet()) {
+ if (!mExpectedEvents.containsKey(actualNamedSequence)) {
+ formatSequenceWithMismatch(
+ sb,
+ actualNamedSequence,
+ new ArrayList<>(),
+ mEvents.get(actualNamedSequence),
+ 0);
+ }
+ }
+
+ return sb.length() != 0 ? "mismatching events: " + sb.toString() : null;
+ }
+
+ // If the list of actual events matches the list of expected events, returns -1, otherwise
+ // the position of the mismatch.
+ private static int getMismatchPosition(List<Pattern> expected, List<String> actual) {
+ for (int i = 0; i < expected.size(); ++i) {
+ if (i >= actual.size()
+ || !expected.get(i).matcher(actual.get(i)).find()) {
+ return i;
+ }
+ }
+
+ if (actual.size() > expected.size()) return expected.size();
+
+ return -1;
+ }
+
+ private static void formatSequenceWithMismatch(
+ StringBuilder sb,
+ String sequenceName,
+ List<Pattern> expected,
+ List<String> actualEvents,
+ int mismatchPosition) {
+ sb.append("\n>> Sequence " + sequenceName);
+ sb.append("\n Expected:");
+ formatEventListWithMismatch(sb, expected, mismatchPosition);
+ sb.append("\n Actual:");
+ formatEventListWithMismatch(sb, actualEvents, mismatchPosition);
+ }
+
+ private static void formatEventListWithMismatch(StringBuilder sb, List events, int position) {
+ for (int i = 0; i < events.size(); ++i) {
+ sb.append("\n | ");
+ sb.append(i == position ? "---> " : " ");
+ sb.append(events.get(i).toString());
+ }
+ if (position == events.size()) sb.append("\n | ---> (end)");
+ }
+
+ private static class ListMap<T> extends HashMap<String, List<T>> {
+
+ void add(String key, T value) {
+ getNonNull(key).add(value);
+ }
+
+ List<T> getNonNull(String key) {
+ List<T> list = get(key);
+ if (list == null) {
+ list = new ArrayList<>();
+ put(key, list);
+ }
+ return list;
+ }
+ }
+}