Bug 1850865: Improve MOZ_IPC_MESSAGE_LOG. r=ipc-reviewers,nika

Use MOZ_IPC_MESSAGE_LOG to filter GOODBYE_MESSAGE_TYPE messages.

Interpret MOZ_IPC_MESSAGE_LOG elements without the "Child" or "Parent"
suffix as a request to log both sides of the given protocol.

Differential Revision: https://phabricator.services.mozilla.com/D187167

Author: jimblandy

ipc/docs/ipdl.rst

@@ -1756,11 +1756,19 @@ The environment variable ``MOZ_IPC_MESSAGE_LOG`` controls the logging of IPC
 messages.  It logs details about the transmission and reception of messages.
 This isn't controlled by ``MOZ_LOG`` -- it is a separate system.  Set this
 variable to ``1`` to log information on all IPDL messages, or specify a
-comma-separated list of **top-level** protocols to log (e.g.
-``MOZ_IPC_MESSAGE_LOG="PMyManagerChild,PMyManagedParent,PMyManagedChild"``).
+comma-separated list of protocols to log.
+If the ``Child`` or ``Parent`` suffix is given, then only activity on the given
+side is logged; otherwise, both sides are logged.  All protocol names must
+include the ``P`` prefix.
+
+For example:
+
+.. code-block::
+
+    MOZ_IPC_MESSAGE_LOG="PMyManagerChild,PMyManaged"
+
+This requests logging of child-side activity on ``PMyManager``, and both
+parent- and child-side activity on ``PMyManaged``.
+
 :ref:`Debugging with IPDL Logging` has an example where IPDL logging is useful
 in tracking down a bug.
-
-.. important::
-    The preceding ``P`` and the ``Parent`` or ``Child`` suffix are required
-    when listing individual protocols in ``MOZ_IPC_MESSAGE_LOG``.

ipc/docs/processes.rst

@@ -1160,7 +1160,7 @@ section on :ref:`Message Logging`.  We just need to set an environment variable
 before starting the browser.  Let's turn it on for all ``PDemo`` and
 ``PDemoHelpline`` actors: ::
 
-    MOZ_IPC_MESSAGE_LOG="PDemoParent,PDemoChild,PDemoHelplineParent,PDemoHelplineChild"
+    MOZ_IPC_MESSAGE_LOG="PDemo,PDemoHelpline"
 
 To underscore what we said above, when logging is active, the change in timing
 makes the error message go away and everything closes properly on a tested

ipc/glue/MessageChannel.cpp

@@ -941,13 +941,14 @@ bool MessageChannel::MaybeInterceptSpecialIOMessage(const Message& aMsg) {
       // ourselves as "Closing".
       mLink->Close();
       mChannelState = ChannelClosing;
-      if (LoggingEnabled()) {
+      if (LoggingEnabledFor(mListener->GetProtocolName(), mSide)) {
         printf(
-            "[%s %u] NOTE: %s actor received `Goodbye' message.  Closing "
+            "[%s %u] NOTE: %s%s actor received `Goodbye' message.  Closing "
             "channel.\n",
             XRE_GeckoProcessTypeToString(XRE_GetProcessType()),
             static_cast<uint32_t>(base::GetCurrentProcId()),
-            (mSide == ChildSide) ? "child" : "parent");
+            mListener->GetProtocolName(),
+            (mSide == ChildSide) ? "Child" : "Parent");
       }
 
       // Notify the worker thread that the connection has been closed, as we

ipc/glue/ProtocolUtils.cpp

@@ -25,6 +25,7 @@
 #endif
 #include "mozilla/Unused.h"
 #include "nsPrintfCString.h"
+#include "nsReadableUtils.h"
 
 #if defined(MOZ_SANDBOX) && defined(XP_WIN)
 #  include "mozilla/sandboxTarget.h"
@@ -104,10 +105,20 @@ void AnnotateCrashReportWithErrno(CrashReporter::Annotation tag, int error) {
 #endif  // defined(XP_MACOSX)
 
 #if defined(DEBUG) || defined(FUZZING)
+// If aTopLevelProtocol matches any token in aFilter, return true.
+//
+// aTopLevelProtocol is a protocol name, without the "Parent" / "Child" suffix.
+// aSide indicates whether we're logging parent-side or child-side activity.
+//
+// aFilter is a list of protocol names separated by commas and/or
+// spaces. These may include the "Child" / "Parent" suffix, or omit
+// the suffix to log activity on both sides.
+//
 // This overload is for testability; application code should use the single-
 // argument version (defined in the ProtocolUtils.h) which takes the filter from
 // the environment.
-bool LoggingEnabledFor(const char* aTopLevelProtocol, const char* aFilter) {
+bool LoggingEnabledFor(const char* aTopLevelProtocol, Side aSide,
+                       const char* aFilter) {
   if (!aFilter) {
     return false;
   }
@@ -119,9 +130,27 @@ bool LoggingEnabledFor(const char* aTopLevelProtocol, const char* aFilter) {
   Tokenizer tokens(aFilter, kDelimiters);
   Tokenizer::Token t;
   while (tokens.Next(t)) {
-    if (t.Type() == Tokenizer::TOKEN_WORD &&
-        t.AsString() == aTopLevelProtocol) {
-      return true;
+    if (t.Type() == Tokenizer::TOKEN_WORD) {
+      auto filter = t.AsString();
+
+      // Since aTopLevelProtocol never includes the "Parent" / "Child" suffix,
+      // this will only occur when filter doesn't include it either, meaning
+      // that we should log activity on both sides.
+      if (filter == aTopLevelProtocol) {
+        return true;
+      }
+
+      if (aSide == ParentSide &&
+          StringEndsWith(filter, nsDependentCString("Parent")) &&
+          Substring(filter, 0, filter.Length() - 6) == aTopLevelProtocol) {
+        return true;
+      }
+
+      if (aSide == ChildSide &&
+          StringEndsWith(filter, nsDependentCString("Child")) &&
+          Substring(filter, 0, filter.Length() - 5) == aTopLevelProtocol) {
+        return true;
+      }
     }
   }
 

ipc/glue/ProtocolUtils.h

@@ -566,12 +566,15 @@ inline bool LoggingEnabled() {
 }
 
 #if defined(DEBUG) || defined(FUZZING)
-bool LoggingEnabledFor(const char* aTopLevelProtocol, const char* aFilter);
+bool LoggingEnabledFor(const char* aTopLevelProtocol, mozilla::ipc::Side aSide,
+                       const char* aFilter);
 #endif
 
-inline bool LoggingEnabledFor(const char* aTopLevelProtocol) {
+inline bool LoggingEnabledFor(const char* aTopLevelProtocol,
+                              mozilla::ipc::Side aSide) {
 #if defined(DEBUG) || defined(FUZZING)
-  return LoggingEnabledFor(aTopLevelProtocol, PR_GetEnv("MOZ_IPC_MESSAGE_LOG"));
+  return LoggingEnabledFor(aTopLevelProtocol, aSide,
+                           PR_GetEnv("MOZ_IPC_MESSAGE_LOG"));
 #else
   return false;
 #endif

ipc/gtest/TestLogging.cpp

@@ -14,42 +14,51 @@ namespace mozilla::ipc {
 TEST(IPCLogging, EmptyFilter)
 {
   const char* emptyFilter = "";
-  EXPECT_FALSE(LoggingEnabledFor("PContentParent", emptyFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentChild", emptyFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ParentSide, emptyFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ChildSide, emptyFilter));
 }
 
 TEST(IPCLogging, SingleProtocolFilter)
 {
   const char* contentParentFilter = "PContentParent";
-  EXPECT_TRUE(LoggingEnabledFor("PContentParent", contentParentFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentChild", contentParentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PContent", ParentSide, contentParentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ChildSide, contentParentFilter));
 }
 
 TEST(IPCLogging, CommaDelimitedProtocolsFilter)
 {
   const char* gmpContentFilter = "PGMPContentChild,PGMPContentParent";
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentChild", gmpContentFilter));
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentParent", gmpContentFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentParent", gmpContentFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentChild", gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ChildSide, gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ParentSide, gmpContentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ParentSide, gmpContentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ChildSide, gmpContentFilter));
 }
 
 TEST(IPCLogging, SpaceDelimitedProtocolsFilter)
 {
   const char* gmpContentFilter = "PGMPContentChild PGMPContentParent";
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentChild", gmpContentFilter));
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentParent", gmpContentFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentParent", gmpContentFilter));
-  EXPECT_FALSE(LoggingEnabledFor("PContentChild", gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ChildSide, gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ParentSide, gmpContentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ParentSide, gmpContentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ChildSide, gmpContentFilter));
 }
 
 TEST(IPCLogging, CatchAllFilter)
 {
   const char* catchAllFilter = "1";
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentChild", catchAllFilter));
-  EXPECT_TRUE(LoggingEnabledFor("PGMPContentParent", catchAllFilter));
-  EXPECT_TRUE(LoggingEnabledFor("PContentParent", catchAllFilter));
-  EXPECT_TRUE(LoggingEnabledFor("PContentChild", catchAllFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ChildSide, catchAllFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ParentSide, catchAllFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PContent", ParentSide, catchAllFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PContent", ChildSide, catchAllFilter));
+}
+
+TEST(IPCLogging, BothSidesFilter)
+{
+  const char* gmpContentFilter = "PGMPContent,PContentParent";
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ChildSide, gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PGMPContent", ParentSide, gmpContentFilter));
+  EXPECT_TRUE(LoggingEnabledFor("PContent", ParentSide, gmpContentFilter));
+  EXPECT_FALSE(LoggingEnabledFor("PContent", ChildSide, gmpContentFilter));
 }
 #endif  // defined(DEBUG) || defined(FUZZING)
 

ipc/ipdl/ipdl/lower.py

@@ -363,18 +363,6 @@ def _otherSide(side):
     assert 0
 
 
-def _ifLogging(topLevelProtocol, stmts):
-    return StmtCode(
-        """
-        if (mozilla::ipc::LoggingEnabledFor(${proto})) {
-            $*{stmts}
-        }
-        """,
-        proto=topLevelProtocol,
-        stmts=stmts,
-    )
-
-
 # XXX we need to remove these and install proper error handling
 
 
@@ -5582,9 +5570,14 @@ def makeSendMethodDecl(self, md, promise=False, paramsems="in"):
 
     def logMessage(self, md, msgptr, pfx, actor=None, receiving=False):
         actorname = _actorName(self.protocol.name, self.side)
+        if self.side == "parent":
+            side = ExprVar("mozilla::ipc::ParentSide")
+        else:
+            side = ExprVar("mozilla::ipc::ChildSide")
+
         return StmtCode(
             """
-            if (mozilla::ipc::LoggingEnabledFor(${actorname})) {
+            if (mozilla::ipc::LoggingEnabledFor(${protocolname}, ${side})) {
                 mozilla::ipc::LogMessageForProtocol(
                     ${actorname},
                     ${actor}->ToplevelProtocol()->OtherPidMaybeInvalid(),
@@ -5593,6 +5586,8 @@ def logMessage(self, md, msgptr, pfx, actor=None, receiving=False):
                     mozilla::ipc::MessageDirection::${direction});
             }
             """,
+            protocolname=ExprLiteral.String(self.protocol.name),
+            side=side,
             actorname=ExprLiteral.String(actorname),
             actor=actor or ExprVar.THIS,
             pfx=ExprLiteral.String(pfx),