Updating logcat reading logic (2f41808e) · Commits · e / os / BlissLauncher3

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

+25 −208

Original line number	Diff line number	Diff line
		@@ -69,22 +69,16 @@ import org.junit.Assert;
		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 @@ public final class LauncherInstrumentation {
		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 @@ public final class LauncherInstrumentation {

		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,11 +419,13 @@ public final class LauncherInstrumentation {
		log("Hierarchy dump for: " + message);
		dumpViewHierarchy();

		final String eventMismatch = getEventMismatchMessage(false);

		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 @@ public final class LauncherInstrumentation {
		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 (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));
		}
		};
		}

		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);
		}
		} else {
		sEventChecker.finishNoWait();
		}

		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)");
		void expectEvent(String sequence, Pattern expected) {
		if (sCheckingEvents) sEventChecker.expectPattern(sequence, expected);
		}
		}
		No newline at end of file

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

0 → 100644

+233 −0

Original line number	Diff line number	Diff line
		/*
		* 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;
		}
		}
		}