FrameTokenMessageQueue Debugging of Flaky Tests

FrameTokenMessageQueue is setup to kill misbehaving Renderer processes,
when frame submission happens out of order. This has typically been a
side effect of other more serious bugs, and used to help identify the
cause.

However FullscreenInteractiveBrowserTest.NotifyFullscreenAcquired has
been flaking with this failure.

In order to get a better idea of what is the cause I'm looking to add
extra stateful info, along with two earlier DCHECKs.

I'm also re-enabling the test in order to get reproductions, as I
haven't been able to reproduce locally.

TBR=ellyjones@chromium.org
TEST=FullscreenInteractiveBrowserTest.NotifyFullscreenAcquired

Bug: 1087744
Change-Id: I470c33e3ca1c76abd810d551bf02dcfc9a0eaa51
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2239677Reviewed-by: Jonathan Ross <jonross@chromium.org>
Reviewed-by: kylechar <kylechar@chromium.org>
Commit-Queue: Jonathan Ross <jonross@chromium.org>
Cr-Commit-Position: refs/heads/master@{#777458}

chrome/browser/ui/exclusive_access/fullscreen_interactive_browsertest.cc

@@ -68,14 +68,10 @@ class FullscreenInteractiveBrowserTest : public InProcessBrowserTest {
   DISALLOW_COPY_AND_ASSIGN(FullscreenInteractiveBrowserTest);
 };
 
-// https://crbug.com/1087875: Flaky on Linux and Mac.
-#if defined(OS_MACOSX) || defined(OS_LINUX)
-#define MAYBE_NotifyFullscreenAcquired DISABLED_NotifyFullscreenAcquired
-#else
-#define MAYBE_NotifyFullscreenAcquired NotifyFullscreenAcquired
-#endif
+// TODO(jonross): Investigate the flakiness on Linux and Mac. Sheriff if this
+// fails update (https://crbug.com/1087875).
 IN_PROC_BROWSER_TEST_F(FullscreenInteractiveBrowserTest,
-                       MAYBE_NotifyFullscreenAcquired) {
+                       NotifyFullscreenAcquired) {
   content::WebContents* web_contents =
       browser()->tab_strip_model()->GetActiveWebContents();
 

content/browser/renderer_host/frame_token_message_queue.cc

@@ -35,6 +35,14 @@ void FrameTokenMessageQueue::DidProcessFrame(uint32_t frame_token) {
                                    base::NumberToString(frame_token));
     base::debug::DumpWithoutCrashing();
 
+    // TODO(jonross): Remove this once root cause of flaking tests is found.
+    // (crbug.com/1087744)
+    DCHECK(false) << "FrameTokenMessageQueue invalid order of acknowledged "
+                     "token. Current: "
+                  << frame_token
+                  << " Last Received: " << last_received_frame_token_
+                  << " Last Before Reset: " << last_received_frame_token_reset_
+                  << " queue size " << callback_map_.size();
     client_->OnInvalidFrameToken(frame_token);
     return;
   }
@@ -59,6 +67,11 @@ void FrameTokenMessageQueue::EnqueueOrRunFrameTokenCallback(
     base::OnceClosure callback) {
   // Zero token is invalid.
   if (!frame_token) {
+    // TODO(jonross): Remove this once root cause of flaking tests is found.
+    // (crbug.com/1087744)
+    DCHECK(false) << "FrameTokenMessageQueue invalid enqueued frame token. "
+                     "Last Received: "
+                  << last_received_frame_token_;
     client_->OnInvalidFrameToken(frame_token);
     return;
   }
@@ -84,6 +97,7 @@ void FrameTokenMessageQueue::OnFrameSwapMessagesReceived(
 }
 
 void FrameTokenMessageQueue::Reset() {
+  last_received_frame_token_reset_ = last_received_frame_token_;
   last_received_frame_token_ = 0;
   callback_map_.clear();
 }

content/browser/renderer_host/frame_token_message_queue.h

@@ -93,6 +93,12 @@ class CONTENT_EXPORT FrameTokenMessageQueue {
   // Sorted by frame token.
   std::multimap<uint32_t, base::OnceClosure> callback_map_;
 
+  // TODO(jonross): Remove this once root cause of flaking tests is found.
+  // (crbug.com/1087744)
+  // The frame token last seen when Reset() is called. To determine if we are
+  // getting delayed frame acknowledgements after a reset.
+  uint32_t last_received_frame_token_reset_ = 0u;
+
   DISALLOW_COPY_AND_ASSIGN(FrameTokenMessageQueue);
 };
 

content/browser/renderer_host/frame_token_message_queue_unittest.cc

@@ -476,9 +476,11 @@ TEST_F(FrameTokenMessageQueueTest, DifferentFrameTokensEnqueuedNonIPC) {
   EXPECT_TRUE(second_enqueuer.frame_token_callback_called());
 }
 
+// TODO(jonross): Re-enable this once the DCHECKs have been removed.
+// (crbug.com/1087744)
 // An empty frame token is considered invalid, so this tests that attempting to
 // enqueue for that is rejected.
-TEST_F(FrameTokenMessageQueueTest, EmptyTokenForIPCMessageIsRejected) {
+TEST_F(FrameTokenMessageQueueTest, DISABLED_EmptyTokenForIPCMessageIsRejected) {
   FrameTokenMessageQueue* queue = frame_token_message_queue();
   TestFrameTokenMessageQueueClient* client = test_client();
   ASSERT_EQ(0u, queue->size());
@@ -526,9 +528,12 @@ TEST_F(FrameTokenMessageQueueTest, EarlierTokenForIPCMessageIsNotRejected) {
   EXPECT_EQ(0, client->on_process_swap_message_count());
 }
 
+// TODO(jonross): Re-enable this once the DCHECKs have been removed.
+// (crbug.com/1087744)
 // Tests that if DidProcessFrame is called with an invalid token, that it is
 // rejected, and that no callbacks are processed.
-TEST_F(FrameTokenMessageQueueTest, InvalidDidProcessFrameTokenNotProcessed) {
+TEST_F(FrameTokenMessageQueueTest,
+       DISABLED_InvalidDidProcessFrameTokenNotProcessed) {
   FrameTokenMessageQueue* queue = frame_token_message_queue();
   TestFrameTokenMessageQueueClient* client = test_client();
   TestNonIPCMessageEnqueuer* enqueuer = test_non_ipc_enqueuer();
@@ -561,9 +566,12 @@ TEST_F(FrameTokenMessageQueueTest, InvalidDidProcessFrameTokenNotProcessed) {
   EXPECT_FALSE(enqueuer->frame_token_callback_called());
 }
 
+// TODO(jonross): Re-enable this once the DCHECKs have been removed.
+// (crbug.com/1087744)
 // Test that if DidProcessFrame is called with an earlier frame token, that it
 // is rejected, and that no callbacks are processed.
-TEST_F(FrameTokenMessageQueueTest, EarlierTokenForDidProcessFrameRejected) {
+TEST_F(FrameTokenMessageQueueTest,
+       DISABLED_EarlierTokenForDidProcessFrameRejected) {
   FrameTokenMessageQueue* queue = frame_token_message_queue();
   TestFrameTokenMessageQueueClient* client = test_client();
   TestNonIPCMessageEnqueuer* enqueuer = test_non_ipc_enqueuer();