Bug 1408086 - Append log of the latest 2 sets of composition events when ContentCacheInParent::OnEventNeedingAckHandled() meets unexpected state and crash itself r=m_kato
authorMasayuki Nakano <masayuki@d-toybox.com>
Fri, 13 Oct 2017 02:50:47 +0900
changeset 386424 716fb330cae9c4415951171f2a1af06e92414685
parent 386423 47761f216db8c5a7247226a456b0adbcf1fe772b
child 386425 8225ecd8c02f95e94d82a17c5f0f338f261b5357
push id96257
push userarchaeopteryx@coole-files.de
push dateTue, 17 Oct 2017 09:49:16 +0000
treeherdermozilla-inbound@c44b13d3ac6a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersm_kato
bugs1408086
milestone58.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1408086 - Append log of the latest 2 sets of composition events when ContentCacheInParent::OnEventNeedingAckHandled() meets unexpected state and crash itself r=m_kato We have a lot of crash reports in OnEventNeedingAckHandled() due to unexpected state (hit MOZ_RELEASE_ASSERT). However, it's unclear what occurs and we're not sure there are how many cases to crash because the stack trace is too short because the method is called when TabParent receives event handled message from the remote process. I.e., it doesn't show what happens immediately before the crash. This patch puts 2 sets of composition events to app notes of crash report when it needs to crash. This *might* make damage to the performance. If so, after fixing the crashes, we should back this out. Fortunately, we have a lot of reports from either Nightly or Beta. MozReview-Commit-ID: 9tDrEIf72MG
widget/ContentCache.cpp
widget/ContentCache.h
--- a/widget/ContentCache.cpp
+++ b/widget/ContentCache.cpp
@@ -10,16 +10,19 @@
 #include "mozilla/IMEStateManager.h"
 #include "mozilla/IntegerPrintfMacros.h"
 #include "mozilla/Logging.h"
 #include "mozilla/Move.h"
 #include "mozilla/RefPtr.h"
 #include "mozilla/TextComposition.h"
 #include "mozilla/TextEvents.h"
 #include "mozilla/dom/TabParent.h"
+#ifdef MOZ_CRASHREPORTER
+#include "nsExceptionHandler.h"
+#endif // #ifdef MOZ_CRASHREPORTER
 #include "nsIWidget.h"
 
 namespace mozilla {
 
 using namespace dom;
 using namespace widget;
 
 static const char*
@@ -1105,16 +1108,20 @@ ContentCacheInParent::OnCompositionEvent
      "mPendingEventsNeedingAck=%u, mWidgetHasComposition=%s, "
      "mPendingCompositionCount=%u, mCommitStringByRequest=0x%p",
      this, ToChar(aEvent.mMessage),
      GetEscapedUTF8String(aEvent.mData).get(), aEvent.mData.Length(),
      aEvent.mRanges ? aEvent.mRanges->Length() : 0, mPendingEventsNeedingAck,
      GetBoolName(mWidgetHasComposition), mPendingCompositionCount,
      mCommitStringByRequest));
 
+#ifdef MOZ_CRASHREPORTER
+  mDispatchedEventMessages.AppendElement(aEvent.mMessage);
+#endif // #ifdef MOZ_CRASHREPORTER
+
   // We must be able to simulate the selection because
   // we might not receive selection updates in time
   if (!mWidgetHasComposition) {
     if (aEvent.mWidget && aEvent.mWidget->PluginHasFocus()) {
       // If focus is on plugin, we cannot get selection range
       mCompositionStart = 0;
     } else if (mCompositionStartInChild != UINT32_MAX) {
       // If there is pending composition in the remote process, let's use
@@ -1181,50 +1188,84 @@ ContentCacheInParent::OnSelectionEvent(
      "mPendingCompositionCount=%u",
      this, ToChar(aSelectionEvent.mMessage),
      aSelectionEvent.mOffset, aSelectionEvent.mLength,
      GetBoolName(aSelectionEvent.mReversed),
      GetBoolName(aSelectionEvent.mExpandToClusterBoundary),
      GetBoolName(aSelectionEvent.mUseNativeLineBreak), mPendingEventsNeedingAck,
      GetBoolName(mWidgetHasComposition), mPendingCompositionCount));
 
+#ifdef MOZ_CRASHREPORTER
+  mDispatchedEventMessages.AppendElement(aSelectionEvent.mMessage);
+#endif // #ifdef MOZ_CRASHREPORTER
+
   mPendingEventsNeedingAck++;
 }
 
 void
 ContentCacheInParent::OnEventNeedingAckHandled(nsIWidget* aWidget,
                                                 EventMessage aMessage)
 {
   // This is called when the child process receives WidgetCompositionEvent or
   // WidgetSelectionEvent.
 
   MOZ_LOG(sContentCacheLog, LogLevel::Info,
     ("0x%p OnEventNeedingAckHandled(aWidget=0x%p, "
      "aMessage=%s), mPendingEventsNeedingAck=%u, mPendingCompositionCount=%" PRIu8,
      this, aWidget, ToChar(aMessage), mPendingEventsNeedingAck, mPendingCompositionCount));
 
+#ifdef MOZ_CRASHREPORTER
+  mReceivedEventMessages.AppendElement(aMessage);
+#endif // #ifdef MOZ_CRASHREPORTER
+
   if (WidgetCompositionEvent::IsFollowedByCompositionEnd(aMessage) ||
       aMessage == eCompositionCommitRequestHandled) {
-    MOZ_RELEASE_ASSERT(mPendingCompositionCount > 0);
+
+#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 "
+                           "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");
+    }
+
     mPendingCompositionCount--;
     // Forget composition string only when the latest composition string is
     // handled in the remote process because if there is 2 or more pending
     // composition, this value shouldn't be referred.
     if (!mPendingCompositionCount) {
       mCompositionString.Truncate();
       mIsPendingLastCommitEvent = false;
     }
     // Forget pending commit string length if it's handled in the remote
     // 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;
   }
 
-  MOZ_RELEASE_ASSERT(mPendingEventsNeedingAck > 0);
+  if (NS_WARN_IF(!mPendingEventsNeedingAck)) {
+#ifdef MOZ_CRASHREPORTER
+    nsPrintfCString info("There 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) {
     return;
   }
 
   FlushPendingNotifications(aWidget);
 }
 
 bool
@@ -1404,16 +1445,71 @@ ContentCacheInParent::FlushPendingNotifi
       (mPendingTextChange.HasNotification() ||
        mPendingSelectionChange.HasNotification() ||
        mPendingLayoutChange.HasNotification() ||
        mPendingCompositionUpdate.HasNotification())) {
     FlushPendingNotifications(widget);
   }
 }
 
+#ifdef MOZ_CRASHREPORTER
+
+void
+ContentCacheInParent::RemoveUnnecessaryEventMessageLog()
+{
+  bool foundLastCompositionStart = false;
+  for (size_t i = mDispatchedEventMessages.Length(); i > 1; i--) {
+    if (mDispatchedEventMessages[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.
+    mDispatchedEventMessages.RemoveElementsAt(0, i - 1);
+    break;
+  }
+  foundLastCompositionStart = false;
+  for (size_t i = mReceivedEventMessages.Length(); i > 1; i--) {
+    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;
+  }
+}
+
+void
+ContentCacheInParent::AppendEventMessageLog(nsACString& aLog) const
+{
+  aLog.AppendLiteral("Dispatched Event Message Log:\n");
+  for (EventMessage message : mDispatchedEventMessages) {
+    aLog.AppendLiteral("  ");
+    aLog.Append(ToChar(message));
+    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("\n");
+}
+
+#endif // #ifdef MOZ_CRASHREPORTER
+
 /*****************************************************************************
  * mozilla::ContentCache::TextRectArray
  *****************************************************************************/
 
 LayoutDeviceIntRect
 ContentCache::TextRectArray::GetRect(uint32_t aOffset) const
 {
   LayoutDeviceIntRect rect;
--- a/widget/ContentCache.h
+++ b/widget/ContentCache.h
@@ -405,16 +405,22 @@ public:
                       const IMENotification& aNotification);
 
 private:
   IMENotification mPendingSelectionChange;
   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;
+#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
   // composition.  Then, data value of dispatched composition events should
   // be stored into the instance.
@@ -459,13 +465,26 @@ private:
                    bool aRoundToExistingOffset,
                    LayoutDeviceIntRect& aTextRect) const;
   bool GetUnionTextRects(uint32_t aOffset,
                          uint32_t aLength,
                          bool aRoundToExistingOffset,
                          LayoutDeviceIntRect& aUnionTextRect) const;
 
   void FlushPendingNotifications(nsIWidget* aWidget);
+
+#ifdef MOZ_CRASHREPORTER
+  /**
+   * Remove unnecessary messages from mDispatchedEventMessages and
+   * mReceivedEventMessages.
+   */
+  void RemoveUnnecessaryEventMessageLog();
+
+  /**
+   * Append event message log to aLog.
+   */
+  void AppendEventMessageLog(nsACString& aLog) const;
+#endif // #ifdef MOZ_CRASHREPORTER
 };
 
 } // namespace mozilla
 
 #endif // mozilla_ContentCache_h