Bug 1409656 - Append log of ContentCacheInParent::RequestIMEToCommitComposition() in the latest 2 sets of composition events to app notes of crash report when ContentCacheInParent::OnEventNeedingAckHandled() meets unexpected state and crash itself r?m_kato draft
authorMasayuki Nakano <masayuki@d-toybox.com>
Thu, 19 Oct 2017 00:13:42 +0900
changeset 682720 79c7d746d4c98d46f4cdb6a0ca726f46a25d241b
parent 682644 48823390645d79db391dcaf64dab59e754b680a5
child 736400 df23a9fcc261bc69fc8386440591dc2a341668e9
push id85111
push usermasayuki@d-toybox.com
push dateWed, 18 Oct 2017 16:53:38 +0000
reviewersm_kato
bugs1409656, 1408086
milestone58.0a1
Bug 1409656 - Append log of ContentCacheInParent::RequestIMEToCommitComposition() in the latest 2 sets of composition events to app notes of crash report when ContentCacheInParent::OnEventNeedingAckHandled() meets unexpected state and crash itself r?m_kato This is a follow up patch of bug 1408086. The previous patch starts to append log of 2 sets of composition events to app notes of crash report when ContentCacheInParent::OnEventNeedingAckHandled() meets unexpected state and crash itself. However, now, we know the unexpected state occurs when TabParent receives eCompositionCommitRequestHandled message from its remote process. The event comes when ContentCacheInParent::RequestIMEToCommitComposition() returns true. So, we need to know what occurs in the method before the crash. This patch defines each case of RequestIMEToCommitComposition() with an enum class, RequestIMEToCommitCompositionResult and make RequestIMEToCommitComposition() append one of its value to the array. Then, ContentCacheInParent discards unnecessary log of this when it discards log of old composition events. Finally, appends the log to the app notes of crash report. MozReview-Commit-ID: 9sJyl4SvUXu
widget/ContentCache.cpp
widget/ContentCache.h
--- a/widget/ContentCache.cpp
+++ b/widget/ContentCache.cpp
@@ -1222,17 +1222,17 @@ ContentCacheInParent::OnEventNeedingAckH
 #ifdef MOZ_CRASHREPORTER
     if (mPendingCompositionCount == 1) {
       RemoveUnnecessaryEventMessageLog();
     }
 #endif // #ifdef MOZ_CRASHREPORTER
 
     if (NS_WARN_IF(!mPendingCompositionCount)) {
 #ifdef MOZ_CRASHREPORTER
-      nsPrintfCString info("There is no pending composition but received %s "
+      nsPrintfCString info("\nThere is no pending composition but received %s "
                            "message from the remote child\n\n",
                            ToChar(aMessage));
       AppendEventMessageLog(info);
       CrashReporter::AppendAppNotesToCrashReport(info);
 #endif // #ifdef MOZ_CRASHREPORTER
       MOZ_CRASH("No pending composition but received unexpected commit event");
     }
 
@@ -1248,17 +1248,17 @@ ContentCacheInParent::OnEventNeedingAckH
     // process.  Note that this doesn't care too old composition's commit
     // string because in such case, we cannot return proper information
     // to IME synchornously.
     mPendingCommitLength = 0;
   }
 
   if (NS_WARN_IF(!mPendingEventsNeedingAck)) {
 #ifdef MOZ_CRASHREPORTER
-    nsPrintfCString info("There is no pending events but received %s "
+    nsPrintfCString info("\nThere is no pending events but received %s "
                          "message from the remote child\n\n",
                          ToChar(aMessage));
     AppendEventMessageLog(info);
     CrashReporter::AppendAppNotesToCrashReport(info);
 #endif // #ifdef MOZ_CRASHREPORTER
     MOZ_CRASH("No pending event message but received unexpected event");
   }
   if (--mPendingEventsNeedingAck) {
@@ -1285,43 +1285,63 @@ ContentCacheInParent::RequestIMEToCommit
   MOZ_ASSERT(!mCommitStringByRequest);
 
   // If there are 2 or more pending compositions, we already sent
   // eCompositionCommit(AsIs) to the remote process.  So, this request is
   // too late for IME.  The remote process should wait following
   // composition events for cleaning up TextComposition and handle the
   // request as it's handled asynchronously.
   if (mPendingCompositionCount > 1) {
+#ifdef MOZ_CRASHREPORTER
+    mRequestIMEToCommitCompositionResults.
+      AppendElement(RequestIMEToCommitCompositionResult::
+                      eToOldCompositionReceived);
+#endif // #ifdef MOZ_CRASHREPORTER
     return false;
   }
 
   // If there is no pending composition, we may have already sent
   // eCompositionCommit(AsIs) event for the active composition.  If so, the
   // remote process will receive composition events which causes cleaning up
   // TextComposition.  So, this shouldn't do nothing and TextComposition
   // should handle the request as it's handled asynchronously.
   if (mIsPendingLastCommitEvent) {
+#ifdef MOZ_CRASHREPORTER
+    mRequestIMEToCommitCompositionResults.
+      AppendElement(RequestIMEToCommitCompositionResult::
+                      eToCommittedCompositionReceived);
+#endif // #ifdef MOZ_CRASHREPORTER
     return false;
   }
 
   // If TabParent which has IME focus was already changed to different one, the
   // request shouldn't be sent to IME because it's too late.
   if (!IMEStateManager::DoesTabParentHaveIMEFocus(&mTabParent)) {
     // Use the latest composition string which may not be handled in the
     // remote process for avoiding data loss.
+#ifdef MOZ_CRASHREPORTER
+    mRequestIMEToCommitCompositionResults.
+      AppendElement(RequestIMEToCommitCompositionResult::
+                      eReceivedAfterTabParentBlur);
+#endif // #ifdef MOZ_CRASHREPORTER
     aCommittedString = mCompositionString;
     return true;
   }
 
   RefPtr<TextComposition> composition =
     IMEStateManager::GetTextCompositionFor(aWidget);
   if (NS_WARN_IF(!composition)) {
     MOZ_LOG(sContentCacheLog, LogLevel::Warning,
       ("  0x%p RequestToCommitComposition(), "
        "does nothing due to no composition", this));
+#ifdef MOZ_CRASHREPORTER
+    mRequestIMEToCommitCompositionResults.
+      AppendElement(RequestIMEToCommitCompositionResult::
+                      eReceivedButNoTextComposition);
+#endif // #ifdef MOZ_CRASHREPORTER
     return false;
   }
 
   mCommitStringByRequest = &aCommittedString;
 
   aWidget->NotifyIME(IMENotification(aCancel ? REQUEST_TO_CANCEL_COMPOSITION :
                                                REQUEST_TO_COMMIT_COMPOSITION));
 
@@ -1338,27 +1358,36 @@ ContentCacheInParent::RequestIMEToCommit
     // TextComposition instance will synthesize commit events and wait to
     // receive delayed composition events.  When TextComposition instances both
     // in this process and the remote process will be destroyed when delayed
     // composition events received. TextComposition instance in the parent
     // process will dispatch following composition events and be destroyed
     // normally. On the other hand, TextComposition instance in the remote
     // process won't dispatch following composition events and will be
     // destroyed by IMEStateManager::DispatchCompositionEvent().
+#ifdef MOZ_CRASHREPORTER
+    mRequestIMEToCommitCompositionResults.
+      AppendElement(RequestIMEToCommitCompositionResult::
+                      eHandledAsynchronously);
+#endif // #ifdef MOZ_CRASHREPORTER
     return false;
   }
 
   // When the composition is committed synchronously, the commit string will be
   // returned to the remote process. Then, PuppetWidget will dispatch
   // eCompositionCommit event with the returned commit string (i.e., the value
   // is aCommittedString of this method).  Finally, TextComposition instance in
   // the remote process will be destroyed by
   // IMEStateManager::DispatchCompositionEvent() at receiving the
   // eCompositionCommit event (Note that TextComposition instance in this
   // process was already destroyed).
+#ifdef MOZ_CRASHREPORTER
+  mRequestIMEToCommitCompositionResults.
+    AppendElement(RequestIMEToCommitCompositionResult::eHandledSynchronously);
+#endif // #ifdef MOZ_CRASHREPORTER
   return true;
 }
 
 void
 ContentCacheInParent::MaybeNotifyIME(nsIWidget* aWidget,
                                      const IMENotification& aNotification)
 {
   if (!mPendingEventsNeedingAck) {
@@ -1464,30 +1493,59 @@ ContentCacheInParent::RemoveUnnecessaryE
       // Find previous eCompositionStart of the latest eCompositionStart.
       foundLastCompositionStart = true;
       continue;
     }
     // Remove the messages before the last 2 sets of composition events.
     mDispatchedEventMessages.RemoveElementsAt(0, i - 1);
     break;
   }
+  uint32_t numberOfCompositionCommitRequestHandled = 0;
   foundLastCompositionStart = false;
   for (size_t i = mReceivedEventMessages.Length(); i > 1; i--) {
+    if (mReceivedEventMessages[i - 1] == eCompositionCommitRequestHandled) {
+      numberOfCompositionCommitRequestHandled++;
+    }
     if (mReceivedEventMessages[i - 1] != eCompositionStart) {
       continue;
     }
     if (!foundLastCompositionStart) {
       // Find previous eCompositionStart of the latest eCompositionStart.
       foundLastCompositionStart = true;
       continue;
     }
     // Remove the messages before the last 2 sets of composition events.
     mReceivedEventMessages.RemoveElementsAt(0, i - 1);
     break;
   }
+
+  if (!numberOfCompositionCommitRequestHandled) {
+    // If there is no eCompositionCommitRequestHandled in
+    // mReceivedEventMessages, we don't need to store log of
+    // RequestIMEToCommmitComposition().
+    mRequestIMEToCommitCompositionResults.Clear();
+  } else {
+    // We need to keep all reason of eCompositionCommitRequestHandled, which
+    // is sent when mRequestIMEToCommitComposition() returns true.
+    // So, we can discard older log than the first
+    // eCompositionCommitRequestHandled in mReceivedEventMessages.
+    for (size_t i = mRequestIMEToCommitCompositionResults.Length();
+         i > 1; i--) {
+      if (mRequestIMEToCommitCompositionResults[i - 1] ==
+            RequestIMEToCommitCompositionResult::eReceivedAfterTabParentBlur ||
+          mRequestIMEToCommitCompositionResults[i - 1] ==
+            RequestIMEToCommitCompositionResult::eHandledSynchronously) {
+        --numberOfCompositionCommitRequestHandled;
+        if (!numberOfCompositionCommitRequestHandled) {
+          mRequestIMEToCommitCompositionResults.RemoveElementsAt(0, i - 1);
+          break;
+        }
+      }
+    }
+  }
 }
 
 void
 ContentCacheInParent::AppendEventMessageLog(nsACString& aLog) const
 {
   aLog.AppendLiteral("Dispatched Event Message Log:\n");
   for (EventMessage message : mDispatchedEventMessages) {
     aLog.AppendLiteral("  ");
@@ -1495,16 +1553,23 @@ ContentCacheInParent::AppendEventMessage
     aLog.AppendLiteral("\n");
   }
   aLog.AppendLiteral("\nReceived Event Message Log:\n");
   for (EventMessage message : mReceivedEventMessages) {
     aLog.AppendLiteral("  ");
     aLog.Append(ToChar(message));
     aLog.AppendLiteral("\n");
   }
+  aLog.AppendLiteral("\nResult of RequestIMEToCommitComposition():\n");
+  for (RequestIMEToCommitCompositionResult result :
+         mRequestIMEToCommitCompositionResults) {
+    aLog.AppendLiteral("  ");
+    aLog.Append(ToReadableText(result));
+    aLog.AppendLiteral("\n");
+  }
   aLog.AppendLiteral("\n");
 }
 
 #endif // #ifdef MOZ_CRASHREPORTER
 
 /*****************************************************************************
  * mozilla::ContentCache::TextRectArray
  *****************************************************************************/
--- a/widget/ContentCache.h
+++ b/widget/ContentCache.h
@@ -409,16 +409,52 @@ private:
   IMENotification mPendingTextChange;
   IMENotification mPendingLayoutChange;
   IMENotification mPendingCompositionUpdate;
 
 #ifdef MOZ_CRASHREPORTER
   // Log of event messages to be output to crash report.
   nsTArray<EventMessage> mDispatchedEventMessages;
   nsTArray<EventMessage> mReceivedEventMessages;
+  // Log of RequestIMEToCommitComposition() in the last 2 compositions.
+  enum class RequestIMEToCommitCompositionResult : uint8_t
+  {
+    eToOldCompositionReceived,
+    eToCommittedCompositionReceived,
+    eReceivedAfterTabParentBlur,
+    eReceivedButNoTextComposition,
+    eHandledAsynchronously,
+    eHandledSynchronously,
+  };
+  const char* ToReadableText(RequestIMEToCommitCompositionResult aResult) const
+  {
+    switch (aResult) {
+      case RequestIMEToCommitCompositionResult::eToOldCompositionReceived:
+        return "Commit request is not handled because it's for "
+               "older composition";
+      case RequestIMEToCommitCompositionResult::eToCommittedCompositionReceived:
+        return "Commit request is not handled because TabParent has already "
+               "sent commit event for the composition";
+      case RequestIMEToCommitCompositionResult::eReceivedAfterTabParentBlur:
+        return "Commit request is handled with stored composition string "
+               "because TabParent has already lost focus";
+      case RequestIMEToCommitCompositionResult::eReceivedButNoTextComposition:
+        return "Commit request is not handled because there is no "
+               "TextCompsition instance";
+      case RequestIMEToCommitCompositionResult::eHandledAsynchronously:
+        return "Commit request is handled but IME doesn't commit current "
+               "composition synchronously";
+      case RequestIMEToCommitCompositionResult::eHandledSynchronously:
+        return "Commit reqeust is handled synchronously";
+      default:
+        return "Unknown reason";
+    }
+  }
+  nsTArray<RequestIMEToCommitCompositionResult>
+    mRequestIMEToCommitCompositionResults;
 #endif // #ifdef MOZ_CRASHREPORTER
 
   // mTabParent is owner of the instance.
   dom::TabParent& MOZ_NON_OWNING_REF mTabParent;
   // mCompositionString is composition string which were sent to the remote
   // process but not yet committed in the remote process.
   nsString mCompositionString;
   // This is not nullptr only while the instance is requesting IME to