/* * Copyright (C) 2018 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.util; import static com.android.launcher3.util.RaceConditionTracker.ENTER_POSTFIX; import static com.android.launcher3.util.RaceConditionTracker.EXIT_POSTFIX; import static org.junit.Assert.assertTrue; import static org.junit.Assert.fail; import android.os.Handler; import android.os.HandlerThread; import android.util.Log; import java.util.ArrayList; import java.util.Arrays; import java.util.Collection; import java.util.HashMap; import java.util.HashSet; import java.util.List; import java.util.Map; import java.util.Set; import java.util.concurrent.Semaphore; import java.util.concurrent.TimeUnit; /** * Event processor for reliably reproducing multithreaded apps race conditions in tests. * * The app notifies us about “events” that happen in its threads. The race condition test runs the * test action multiple times (aka iterations), trying to generate all possible permutations of * these events. It keeps a set of all seen event sequences and steers the execution towards * executing events in previously unseen order. It does it by postponing execution of threads that * would lead to an already seen sequence. * * If an event A occurs before event B in the sequence, this is how execution order looks like: * Events: ... A ... B ... * Events and instructions, guaranteed order: * (instructions executed prior to A) A ... B (instructions executed after B) * * Each iteration has 3 parts (phases). * Phase 1. Picking a previously seen event subsequence that we believe can have previously unseen * continuations. Reproducing this sequence by pausing threads that would lead to other sequences. * Phase 2. Trying to generate previously unseen continuation of the sequence from Phase 1. We need * one new event after that sequence. All threads leading to seen continuations will be postponed * for some short period of time. The phase ends once the new event is registered, or after the * period of time ends (in which case we declare that the sequence can’t have new continuations). * Phase 3. Releasing all threads and letting the test iteration run till its end. * * The iterations end when all seen paths have been declared “uncontinuable”. * * When we register event XXX:enter, we hold all other events until we register XXX:exit. */ public class RaceConditionReproducer implements RaceConditionTracker.EventProcessor { private static final String TAG = "RaceConditionReproducer"; private static final long SHORT_TIMEOUT_MS = 2000; private static final long LONG_TIMEOUT_MS = 60000; // Handler used to resume postponed events. private static final Handler POSTPONED_EVENT_RESUME_HANDLER = createEventResumeHandler(); private static Handler createEventResumeHandler() { final HandlerThread thread = new HandlerThread("RaceConditionEventResumer"); thread.start(); return new Handler(thread.getLooper()); } /** * Event in a particular sequence of events. A node in the prefix tree of all seen event * sequences. */ private class EventNode { // Events that were seen just after this event. private final Map mNextEvents = new HashMap<>(); // Whether we believe that further iterations will not be able to add more events to // mNextEvents. private boolean mStoppedAddingChildren = true; private void debugDump(StringBuilder sb, int indent, String name) { for (int i = 0; i < indent; ++i) sb.append('.'); sb.append(!mStoppedAddingChildren ? "+" : "-"); sb.append(" : "); sb.append(name); if (mLastRegisteredEvent == this) sb.append(" <"); sb.append('\n'); for (String key : mNextEvents.keySet()) { mNextEvents.get(key).debugDump(sb, indent + 2, key); } } /** Number of leaves in the subtree with this node as a root. */ private int numberOfLeafNodes() { if (mNextEvents.isEmpty()) return 1; int leaves = 0; for (String event : mNextEvents.keySet()) { leaves += mNextEvents.get(event).numberOfLeafNodes(); } return leaves; } /** * Whether we believe that further iterations will not be able add nodes to the subtree with * this node as a root. */ private boolean stoppedAddingChildrenToTree() { if (!mStoppedAddingChildren) return false; for (String event : mNextEvents.keySet()) { if (!mNextEvents.get(event).stoppedAddingChildrenToTree()) return false; } return true; } /** * In the subtree with this node as a root, tries finding a node where we may have a * chance to add new children. * If succeeds, returns true and fills 'path' with the sequence of events to that node; * otherwise returns false. */ private boolean populatePathToGrowthPoint(List path) { for (String event : mNextEvents.keySet()) { if (mNextEvents.get(event).populatePathToGrowthPoint(path)) { path.add(0, event); return true; } } if (!mStoppedAddingChildren) { // Mark that we have finished adding children. It will remain true if no new // children are added, or will be set to false upon adding a new child. mStoppedAddingChildren = true; return true; } return false; } } // Starting point of all event sequences; the root of the prefix tree representation all // sequences generated by test iterations. A test iteration can add nodes int it. private EventNode mRoot = new EventNode(); // During a test iteration, the last event that was registered. private EventNode mLastRegisteredEvent; // Length of the current sequence of registered events for the current test iteration. private int mRegisteredEventCount = 0; // During the first part of a test iteration, we go to a specific node under mRoot by // 'playing back' mSequenceToFollow. During this part, all events that don't belong to this // sequence get postponed. private List mSequenceToFollow = new ArrayList<>(); // Collection of events that got postponed, with corresponding wait objects used to let them go. private Map mPostponedEvents = new HashMap<>(); // Callback to run by POSTPONED_EVENT_RESUME_HANDLER, used to let go of all currently // postponed events. private Runnable mResumeAllEventsCallback; // String representation of the sequence of events registered so far for the current test // iteration. After registering any event, we output it to the log. The last output before // the test failure can be later played back to reliable reproduce the exact sequence of // events that broke the test. // Format: EV1|EV2|...\EVN private StringBuilder mCurrentSequence; // When not null, we are in a repro mode. We run only one test iteration, and are trying to // reproduce the event sequence represented by this string. The format is same as for // mCurrentSequence. private final String mReproString; /* Constructor for a normal test. */ public RaceConditionReproducer() { mReproString = null; } /** * Constructor for reliably reproducing a race condition failure. The developer should find in * the log the latest "Repro sequence:" record and locally modify the test by passing that * string to the constructor. Running the test will have only one iteration that will reliably * "play back" that sequence. */ public RaceConditionReproducer(String reproString) { mReproString = reproString; } public RaceConditionReproducer(String... reproSequence) { this(String.join("|", reproSequence)); } public synchronized String getCurrentSequenceString() { return mCurrentSequence.toString(); } /** * Starts a new test iteration. Events reported via RaceConditionTracker.onEvent before this * call will be ignored. */ public synchronized void startIteration() { mLastRegisteredEvent = mRoot; mRegisteredEventCount = 0; mCurrentSequence = new StringBuilder(); Log.d(TAG, "Repro sequence: " + mCurrentSequence); mSequenceToFollow = mReproString != null ? parseReproString(mReproString) : generateSequenceToFollowLocked(); Log.e(TAG, "---- Start of iteration; state:\n" + dumpStateLocked()); checkIfCompletedSequenceToFollowLocked(); RaceConditionTracker.setEventProcessor(this); } /** * Ends a new test iteration. Events reported via RaceConditionTracker.onEvent after this call * will be ignored. * Returns whether we need more iterations. */ public synchronized boolean finishIteration() { RaceConditionTracker.setEventProcessor(null); runResumeAllEventsCallbackLocked(); assertTrue("Non-empty postponed events", mPostponedEvents.isEmpty()); assertTrue("Last registered event is :enter", lastEventAsEnter() == null); // No events came after mLastRegisteredEvent. It doesn't make sense to come to it again // because we won't see new continuations. mLastRegisteredEvent.mStoppedAddingChildren = true; Log.e(TAG, "---- End of iteration; state:\n" + dumpStateLocked()); if (mReproString != null) { assertTrue("Repro mode: failed to reproduce the sequence", mCurrentSequence.toString().startsWith(mReproString)); } // If we are in a repro mode, we need only one iteration. Otherwise, continue if the tree // has prospective growth points. return mReproString == null && !mRoot.stoppedAddingChildrenToTree(); } private static List parseReproString(String reproString) { return Arrays.asList(reproString.split("\\|")); } /** * Called when the app issues an event. */ @Override public void onEvent(String event) { final Semaphore waitObject = tryRegisterEvent(event); if (waitObject != null) { waitUntilCanRegister(event, waitObject); } } /** * Returns whether the last event was not an XXX:enter, or this event is a matching XXX:exit. */ private boolean canRegisterEventNowLocked(String event) { final String lastEventAsEnter = lastEventAsEnter(); final String thisEventAsExit = eventAsExit(event); if (lastEventAsEnter != null) { if (!lastEventAsEnter.equals(thisEventAsExit)) { assertTrue("YYY:exit after XXX:enter", thisEventAsExit == null); // Last event was :enter, but this event is not :exit. return false; } } else { // Previous event was not :enter. assertTrue(":exit after a non-enter event", thisEventAsExit == null); } return true; } /** * Registers an event issued by the app and returns null or decides that the event must be * postponed, and returns an object to wait on. */ private synchronized Semaphore tryRegisterEvent(String event) { Log.d(TAG, "Event issued by the app: " + event); if (!canRegisterEventNowLocked(event)) { return createWaitObjectForPostponedEventLocked(event); } if (mRegisteredEventCount < mSequenceToFollow.size()) { // We are in the first part of the iteration. We only register events that follow the // mSequenceToFollow and postponing all other events. if (event.equals(mSequenceToFollow.get(mRegisteredEventCount))) { // The event is the next one expected in the sequence. Register it. registerEventLocked(event); // If there are postponed events that could continue the sequence, register them. while (mRegisteredEventCount < mSequenceToFollow.size() && mPostponedEvents.containsKey( mSequenceToFollow.get(mRegisteredEventCount))) { registerPostponedEventLocked(mSequenceToFollow.get(mRegisteredEventCount)); } // Perhaps we just completed the required sequence... checkIfCompletedSequenceToFollowLocked(); } else { // The event is not the next one in the sequence. Postpone it. return createWaitObjectForPostponedEventLocked(event); } } else if (mRegisteredEventCount == mSequenceToFollow.size()) { // The second phase of the iteration. We have just registered the whole // mSequenceToFollow, and want to add previously not seen continuations for the last // node in the sequence aka 'growth point'. if (!mLastRegisteredEvent.mNextEvents.containsKey(event) || mReproString != null) { // The event was never seen as a continuation for the current node. // Or we are in repro mode, in which case we are not in business of generating // new sequences after we've played back the required sequence. // Register it immediately. registerEventLocked(event); } else { // The event was seen as a continuation for the current node. Postpone it, hoping // that a new event will come from other threads. return createWaitObjectForPostponedEventLocked(event); } } else { // The third phase of the iteration. We are past the growth point and register // everything that comes. registerEventLocked(event); // Register events that may have been postponed while waiting for an :exit event // during the third phase. We don't do this if just registered event is :enter. if (eventAsEnter(event) == null && mRegisteredEventCount > mSequenceToFollow.size()) { registerPostponedEventsLocked(new HashSet<>(mPostponedEvents.keySet())); } } return null; } /** Called when there are chances that we just have registered the whole mSequenceToFollow. */ private void checkIfCompletedSequenceToFollowLocked() { if (mRegisteredEventCount == mSequenceToFollow.size()) { // We just entered the second phase of the iteration. We have just registered the // whole mSequenceToFollow, and want to add previously not seen continuations for the // last node in the sequence aka 'growth point'. All seen continuations will be // postponed for SHORT_TIMEOUT_MS. At the end of this time period, we'll let them go. scheduleResumeAllEventsLocked(); // Among the events that were postponed during the first stage, there may be an event // that wasn't seen after the current. If so, register it immediately because this // creates a new sequence. final Set keys = new HashSet<>(mPostponedEvents.keySet()); keys.removeAll(mLastRegisteredEvent.mNextEvents.keySet()); if (!keys.isEmpty()) { registerPostponedEventLocked(keys.iterator().next()); } } } private Semaphore createWaitObjectForPostponedEventLocked(String event) { final Semaphore waitObject = new Semaphore(0); assertTrue("Event already postponed: " + event, !mPostponedEvents.containsKey(event)); mPostponedEvents.put(event, waitObject); return waitObject; } private void waitUntilCanRegister(String event, Semaphore waitObject) { try { assertTrue("Never registered event: " + event, waitObject.tryAcquire(LONG_TIMEOUT_MS, TimeUnit.MILLISECONDS)); } catch (InterruptedException e) { fail("Wait was interrupted"); } } /** Schedules resuming all postponed events after SHORT_TIMEOUT_MS */ private void scheduleResumeAllEventsLocked() { assertTrue(mResumeAllEventsCallback == null); mResumeAllEventsCallback = this::allEventsResumeCallback; POSTPONED_EVENT_RESUME_HANDLER.postDelayed(mResumeAllEventsCallback, SHORT_TIMEOUT_MS); } private synchronized void allEventsResumeCallback() { assertTrue("In callback, but callback is not set", mResumeAllEventsCallback != null); mResumeAllEventsCallback = null; registerPostponedEventsLocked(new HashSet<>(mPostponedEvents.keySet())); } private void registerPostponedEventsLocked(Collection events) { for (String event : events) { registerPostponedEventLocked(event); if (eventAsEnter(event) != null) { // Once :enter is registered, switch to waiting for :exit to come. Won't register // other postponed events. break; } } } private void registerPostponedEventLocked(String event) { mPostponedEvents.remove(event).release(); registerEventLocked(event); } /** * If the last registered event was XXX:enter, returns XXX, otherwise, null. */ private String lastEventAsEnter() { return eventAsEnter(mCurrentSequence.substring(mCurrentSequence.lastIndexOf("|") + 1)); } /** * If the event is XXX:postfix, returns XXX, otherwise, null. */ private static String prefixFromPostfixedEvent(String event, String postfix) { final int columnPos = event.indexOf(':'); if (columnPos != -1 && postfix.equals(event.substring(columnPos + 1))) { return event.substring(0, columnPos); } return null; } /** * If the event is XXX:enter, returns XXX, otherwise, null. */ private static String eventAsEnter(String event) { return prefixFromPostfixedEvent(event, ENTER_POSTFIX); } /** * If the event is XXX:exit, returns XXX, otherwise, null. */ private static String eventAsExit(String event) { return prefixFromPostfixedEvent(event, EXIT_POSTFIX); } private void registerEventLocked(String event) { assertTrue(canRegisterEventNowLocked(event)); Log.d(TAG, "Actually registering event: " + event); EventNode next = mLastRegisteredEvent.mNextEvents.get(event); if (next == null) { // This event wasn't seen after mLastRegisteredEvent. next = new EventNode(); mLastRegisteredEvent.mNextEvents.put(event, next); // The fact that we've added a new event after the previous one means that the // previous event is still a growth point, unless this event is :exit, which means // that the previous event is :enter. mLastRegisteredEvent.mStoppedAddingChildren = eventAsExit(event) != null; } mLastRegisteredEvent = next; mRegisteredEventCount++; if (mCurrentSequence.length() > 0) mCurrentSequence.append("|"); mCurrentSequence.append(event); Log.d(TAG, "Repro sequence: " + mCurrentSequence); } private void runResumeAllEventsCallbackLocked() { if (mResumeAllEventsCallback != null) { POSTPONED_EVENT_RESUME_HANDLER.removeCallbacks(mResumeAllEventsCallback); mResumeAllEventsCallback.run(); } } private CharSequence dumpStateLocked() { StringBuilder sb = new StringBuilder(); sb.append("Sequence to follow: "); for (String event : mSequenceToFollow) sb.append(" " + event); sb.append(".\n"); sb.append("Registered event count: " + mRegisteredEventCount); sb.append("\nPostponed events: "); for (String event : mPostponedEvents.keySet()) sb.append(" " + event); sb.append("."); sb.append("\nNodes: \n"); mRoot.debugDump(sb, 0, ""); return sb; } public int numberOfLeafNodes() { return mRoot.numberOfLeafNodes(); } private List generateSequenceToFollowLocked() { ArrayList sequence = new ArrayList<>(); mRoot.populatePathToGrowthPoint(sequence); return sequence; } }