Updating logcat reading logic
Start a thread to read logcat synchronusly instead
of back-tracking at the end of the test
Also:
* Reusing the same logcat process for all checks. This eliminates
reading the log from its start for every gesture. We don’t kill that
process at the end, and don’t stop the thread. I’ve verified that
“am instrument” doesn’t hang, and the logcat process gets automatically
killed after the test process exits.
* Not using mStarted latch, as there is no need to wait until the reader
reaches the start mark.
Bug: 149422395
Change-Id: Ide4ed19ad8d099c41918f38c2b073b8b2e143b69
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;
+ }
+ }
+}