Bug 1592297 - Remove MOZ_QUIET and disable this output by default. r=mccr8,jdescottes

Instead of setting MOZ_QUIET to hide the DOMWINDOW and DOCSHELL log messages, you now must set a regular logging module to enable them. They are automatically enabled on tests that rely on these messages are leak checking. That module is DocShellAndDOMWindowLeak:3 One disadvantage of this change is that you cannot set MOZ_QUIET to hide these messages when running those tests (primarily browser-chrome). Differential Revision: https://phabricator.services.mozilla.com/D52413 --HG-- extra : moz-landing-system : lando
2019-12-02 15:41:35 +00:00 · 2019-12-02 15:41:35 +00:00 · e751bb508a
--- a/devtools/client/shared/vendor/REACT_UPGRADING.md
+++ b/devtools/client/shared/vendor/REACT_UPGRADING.md
@ -155,6 +155,6 @@ cd <srcdir> # where sourcedir is the root of your Firefox repo.
 - When the interface appears type `debugger`.
 - Press `<enter>`.

-Once these tests pass on try then push to try as normal e.g. `./mach try -b do -p all -u all -t all -e all --setenv MOZ_QUIET=1`.
+Once these tests pass on try then push to try as normal e.g. `./mach try -b do -p all -u all -t all -e all`.

 If try passes then go celebrate otherwise you are on your own.
--- a/devtools/docs/index.md
+++ b/devtools/docs/index.md
@ -27,7 +27,6 @@
    * [Chrome mochitests](tests/mochitest-chrome.md)
    * [DevTools mochitests](tests/mochitest-devtools.md)
    * [Node tests](tests/node-tests.md)
-    * [Tips](tests/tips.md)
  * [Writing tests](tests/writing-tests.md)
  * [Debugging intermittent failures](tests/debugging-intermittents.md)
  * [Performance tests (DAMP)](tests/performance-tests.md)
--- a/devtools/docs/tests/tips.md
+++ b/devtools/docs/tests/tips.md
@ -1,22 +0,0 @@
-# Automated tests: Tips
-
-If you run tests in debug mode, e.g. when debugging memory leaks, the test logs are often dominated by `++DOMWINDOW`, `++DOCSHELL`, `--DOMWINDOW`, `--DOCSHELL` lines.
-
-These lines pollute the test logs making it difficult to find real problems. They also slow down our tests because they are not useful for debugging DevTools issues.
-
-You can add this to your `.zshrc` or `.bashrc` to disable them:
-
-```bash
-# Disable those annoying +++DOMWINDOW and +++DOCSHELL printfs from Firefox logs
-export MOZ_QUIET=1
-```
-
-You can also send `MOZ_QUIET` when you push to try&hellip; it makes the logs easier to read and makes the tests run faster because there is so much less logging.
-
-Example try syntax containing `MOZ_QUIET`:
-
-```
-./mach try -b do -p linux,linux64,macosx64,win32,win64 \
-  -u xpcshell,mochitest-bc,mochitest-e10s-bc,mochitest-dt,mochitest-chrome \
-  -t damp --setenv MOZ_QUIET=1
-```
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@ -262,6 +262,8 @@ static uint32_t gNumberOfPrivateDocShells = 0;

 #ifdef DEBUG
 static mozilla::LazyLogModule gDocShellLog("nsDocShell");
+static mozilla::LazyLogModule gDocShellAndDOMWindowLeakLogging(
+    "DocShellAndDOMWindowLeak");
 #endif
 static mozilla::LazyLogModule gDocShellLeakLog("nsDocShellLeak");
 extern mozilla::LazyLogModule gPageCacheLog;
@ -411,11 +413,9 @@ nsDocShell::nsDocShell(BrowsingContext* aBrowsingContext,
 #ifdef DEBUG
  // We're counting the number of |nsDocShells| to help find leaks
  ++gNumberOfDocShells;
-  if (!PR_GetEnv("MOZ_QUIET")) {
-    printf_stderr("++DOCSHELL %p == %ld [pid = %d] [id = %s]\n", (void*)this,
-                  gNumberOfDocShells, getpid(),
-                  nsIDToCString(mHistoryID).get());
-  }
+  MOZ_LOG(gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+          ("++DOCSHELL %p == %ld [pid = %d] [id = %s]\n", (void*)this,
+           gNumberOfDocShells, getpid(), nsIDToCString(mHistoryID).get()));
 #endif
 }

@ -438,22 +438,24 @@ nsDocShell::~nsDocShell() {
  MOZ_LOG(gDocShellLeakLog, LogLevel::Debug, ("DOCSHELL %p destroyed\n", this));

 #ifdef DEBUG
-  nsAutoCString url;
-  if (mLastOpenedURI) {
-    url = mLastOpenedURI->GetSpecOrDefault();
+  if (MOZ_LOG_TEST(gDocShellAndDOMWindowLeakLogging, LogLevel::Info)) {
+    nsAutoCString url;
+    if (mLastOpenedURI) {
+      url = mLastOpenedURI->GetSpecOrDefault();

-    // Data URLs can be very long, so truncate to avoid flooding the log.
-    const uint32_t maxURLLength = 1000;
-    if (url.Length() > maxURLLength) {
-      url.Truncate(maxURLLength);
+      // Data URLs can be very long, so truncate to avoid flooding the log.
+      const uint32_t maxURLLength = 1000;
+      if (url.Length() > maxURLLength) {
+        url.Truncate(maxURLLength);
+      }
    }
-  }
-  // We're counting the number of |nsDocShells| to help find leaks
-  --gNumberOfDocShells;
-  if (!PR_GetEnv("MOZ_QUIET")) {
-    printf_stderr("--DOCSHELL %p == %ld [pid = %d] [id = %s] [url = %s]\n",
-                  (void*)this, gNumberOfDocShells, getpid(),
-                  nsIDToCString(mHistoryID).get(), url.get());
+
+    // We're counting the number of |nsDocShells| to help find leaks
+    --gNumberOfDocShells;
+    MOZ_LOG(gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+            ("--DOCSHELL %p == %ld [pid = %d] [id = %s] [url = %s]\n",
+             (void*)this, gNumberOfDocShells, getpid(),
+             nsIDToCString(mHistoryID).get(), url.get()));
  }
 #endif
 }
--- a/dom/base/nsGlobalWindowInner.cpp
+++ b/dom/base/nsGlobalWindowInner.cpp
@ -348,6 +348,11 @@ static nsGlobalWindowOuter* GetOuterWindowForForwarding(

 static LazyLogModule gDOMLeakPRLogInner("DOMLeakInner");

+#ifdef DEBUG
+static LazyLogModule gDocShellAndDOMWindowLeakLogging(
+    "DocShellAndDOMWindowLeak");
+#endif
+
 static FILE* gDumpFile = nullptr;

 nsGlobalWindowInner::InnerWindowByIdTable*
@ -919,13 +924,11 @@ nsGlobalWindowInner::nsGlobalWindowInner(nsGlobalWindowOuter* aOuterWindow,
 #ifdef DEBUG
  mSerial = nsContentUtils::InnerOrOuterWindowCreated();

-  if (!PR_GetEnv("MOZ_QUIET")) {
-    printf_stderr(
-        "++DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p]\n",
-        nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
-        static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
-        static_cast<void*>(ToCanonicalSupports(aOuterWindow)));
-  }
+  MOZ_LOG(gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+          ("++DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p]\n",
+           nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
+           static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
+           static_cast<void*>(ToCanonicalSupports(aOuterWindow))));
 #endif

  MOZ_LOG(gDOMLeakPRLogInner, LogLevel::Debug,
@ -991,7 +994,7 @@ nsGlobalWindowInner::~nsGlobalWindowInner() {
  nsContentUtils::InnerOrOuterWindowDestroyed();

 #ifdef DEBUG
-  if (!PR_GetEnv("MOZ_QUIET")) {
+  if (MOZ_LOG_TEST(gDocShellAndDOMWindowLeakLogging, LogLevel::Info)) {
    nsAutoCString url;
    if (mLastOpenedURI) {
      url = mLastOpenedURI->GetSpecOrDefault();
@ -1004,15 +1007,15 @@ nsGlobalWindowInner::~nsGlobalWindowInner() {
    }

    nsGlobalWindowOuter* outer = nsGlobalWindowOuter::Cast(mOuterWindow);
-    printf_stderr(
-        "--DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p] [url = "
-        "%s]\n",
-        nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
-        static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
-        static_cast<void*>(ToCanonicalSupports(outer)), url.get());
+    MOZ_LOG(
+        gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+        ("--DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p] [url = "
+         "%s]\n",
+         nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
+         static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
+         static_cast<void*>(ToCanonicalSupports(outer)), url.get()));
  }
 #endif
-
  MOZ_LOG(gDOMLeakPRLogInner, LogLevel::Debug,
          ("DOMWINDOW %p destroyed", this));

--- a/dom/base/nsGlobalWindowOuter.cpp
+++ b/dom/base/nsGlobalWindowOuter.cpp
@ -312,6 +312,11 @@ using mozilla::TimeStamp;
 static LazyLogModule gDOMLeakPRLogOuter("DOMLeakOuter");
 extern LazyLogModule gPageCacheLog;

+#ifdef DEBUG
+static LazyLogModule gDocShellAndDOMWindowLeakLogging(
+    "DocShellAndDOMWindowLeak");
+#endif
+
 nsGlobalWindowOuter::OuterWindowByIdTable*
    nsGlobalWindowOuter::sOuterWindowsById = nullptr;

@ -1134,13 +1139,11 @@ nsGlobalWindowOuter::nsGlobalWindowOuter(uint64_t aWindowID)
 #ifdef DEBUG
  mSerial = nsContentUtils::InnerOrOuterWindowCreated();

-  if (!PR_GetEnv("MOZ_QUIET")) {
-    printf_stderr(
-        "++DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p]\n",
-        nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
-        static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
-        nullptr);
-  }
+  MOZ_LOG(gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+          ("++DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p]\n",
+           nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
+           static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
+           nullptr));
 #endif

  MOZ_LOG(gDOMLeakPRLogOuter, LogLevel::Debug,
@ -1190,7 +1193,7 @@ nsGlobalWindowOuter::~nsGlobalWindowOuter() {
  nsContentUtils::InnerOrOuterWindowDestroyed();

 #ifdef DEBUG
-  if (!PR_GetEnv("MOZ_QUIET")) {
+  if (MOZ_LOG_TEST(gDocShellAndDOMWindowLeakLogging, LogLevel::Info)) {
    nsAutoCString url;
    if (mLastOpenedURI) {
      url = mLastOpenedURI->GetSpecOrDefault();
@ -1202,12 +1205,13 @@ nsGlobalWindowOuter::~nsGlobalWindowOuter() {
      }
    }

-    printf_stderr(
-        "--DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p] [url = "
-        "%s]\n",
-        nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
-        static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
-        nullptr, url.get());
+    MOZ_LOG(
+        gDocShellAndDOMWindowLeakLogging, LogLevel::Info,
+        ("--DOMWINDOW == %d (%p) [pid = %d] [serial = %d] [outer = %p] [url = "
+         "%s]\n",
+         nsContentUtils::GetCurrentInnerOrOuterWindowCount(),
+         static_cast<void*>(ToCanonicalSupports(this)), getpid(), mSerial,
+         nullptr, url.get()));
  }
 #endif

--- a/testing/mochitest/leaks.py
+++ b/testing/mochitest/leaks.py
@ -8,6 +8,9 @@
 import re
 from operator import itemgetter

+RE_DOCSHELL = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOCSHELL")
+RE_DOMWINDOW = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOMWINDOW")
+

 class ShutdownLeaks(object):

@ -24,6 +27,10 @@ class ShutdownLeaks(object):
        self.hiddenWindowsCount = 0
        self.leakedDocShells = set()
        self.hiddenDocShellsCount = 0
+        self.numDocShellCreatedLogsSeen = 0
+        self.numDocShellDestroyedLogsSeen = 0
+        self.numDomWindowCreatedLogsSeen = 0
+        self.numDomWindowDestroyedLogsSeen = 0
        self.currentTest = None
        self.seenShutdown = set()

@ -34,11 +41,17 @@ class ShutdownLeaks(object):
        if action in ('log', 'process_output'):
            line = message['message'] if action == 'log' else message['data']

-            if line[2:11] == "DOMWINDOW":
-                self._logWindow(line)
-            elif line[2:10] == "DOCSHELL":
-                self._logDocShell(line)
-            elif line.startswith("Completed ShutdownLeaks collections in process"):
+            m = RE_DOMWINDOW.search(line)
+            if m:
+                self._logWindow(line, m.group(1) == "++")
+                return
+
+            m = RE_DOCSHELL.search(line)
+            if m:
+                self._logDocShell(line, m.group(1) == "++")
+                return
+
+            if line.startswith("Completed ShutdownLeaks collections in process"):
                pid = int(line.split()[-1])
                self.seenShutdown.add(pid)
        elif action == 'test_start':
@ -60,6 +73,31 @@ class ShutdownLeaks(object):
                "TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite")
            failures += 1

+        if self.numDocShellCreatedLogsSeen == 0 or self.numDocShellDestroyedLogsSeen == 0:
+            self.logger.error("TEST-UNEXPECTED-FAIL | did not see DOCSHELL log strings."
+                              " this occurs if the DOCSHELL logging gets disabled by"
+                              " something. %d created seen %d destroyed seen" %
+                              (self.numDocShellCreatedLogsSeen, self.numDocShellDestroyedLogsSeen))
+            failures += 1
+        else:
+            self.logger.info(
+                    "TEST-INFO | Confirming we saw %d DOCSHELL created and %d destroyed log"
+                    " strings." %
+                    (self.numDocShellCreatedLogsSeen, self.numDocShellDestroyedLogsSeen))
+
+        if self.numDomWindowCreatedLogsSeen == 0 or self.numDomWindowDestroyedLogsSeen == 0:
+            self.logger.error("TEST-UNEXPECTED-FAIL | did not see DOMWINDOW log strings."
+                              " this occurs if the DOMWINDOW logging gets disabled by"
+                              " something%d created seen %d destroyed seen" %
+                              (self.numDomWindowCreatedLogsSeen,
+                               self.numDomWindowDestroyedLogsSeen))
+            failures += 1
+        else:
+            self.logger.info(
+                    "TEST-INFO | Confirming we saw %d DOMWINDOW created and %d destroyed log"
+                    " strings." %
+                    (self.numDomWindowCreatedLogsSeen, self.numDomWindowDestroyedLogsSeen))
+
        for test in self._parseLeakingTests():
            for url, count in self._zipLeakedWindows(test["leakedWindows"]):
                self.logger.error(
@ -96,10 +134,11 @@ class ShutdownLeaks(object):

        return failures

-    def _logWindow(self, line):
-        created = line[:2] == "++"
+    def _logWindow(self, line, created):
        pid = self._parseValue(line, "pid")
        serial = self._parseValue(line, "serial")
+        self.numDomWindowCreatedLogsSeen += 1 if created else 0
+        self.numDomWindowDestroyedLogsSeen += 0 if created else 1

        # log line has invalid format
        if not pid or not serial:
@ -122,10 +161,11 @@ class ShutdownLeaks(object):
            else:
                self.hiddenWindowsCount += 1

-    def _logDocShell(self, line):
-        created = line[:2] == "++"
+    def _logDocShell(self, line, created):
        pid = self._parseValue(line, "pid")
        id = self._parseValue(line, "id")
+        self.numDocShellCreatedLogsSeen += 1 if created else 0
+        self.numDocShellDestroyedLogsSeen += 0 if created else 1

        # log line has invalid format
        if not pid or not id:
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@ -2214,6 +2214,8 @@ toolbar#nav-bar {
            self.start_script_kwargs['testUrl'] = testUrl or 'about:blank'

            if detectShutdownLeaks:
+                env['MOZ_LOG'] = (env['MOZ_LOG'] + "," if env['MOZ_LOG'] else "") + \
+                    "DocShellAndDOMWindowLeak:3"
                shutdownLeaks = ShutdownLeaks(self.log)
            else:
                shutdownLeaks = None