Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell

media/webrtc/signaling/test/FakeLogging.h

@@ -0,0 +1,18 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this file,
+ * You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#ifndef FakeLogging_h
+#define FakeLogging_h
+
+#if !defined(MOZILLA_XPCOMRT_API)
+namespace mozilla {
+namespace detail {
+void log_print(const PRLogModuleInfo* aModule,
+                      LogLevel aLevel,
+                      const char* aFmt, ...) { }
+}
+}
+#endif
+
+#endif

media/webrtc/signaling/test/jsep_session_unittest.cpp

@@ -20,6 +20,7 @@
 
 #include "FakeMediaStreams.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 
 #include "signaling/src/sdp/SdpMediaSection.h"
 #include "signaling/src/sdp/SipccSdpParser.h"

media/webrtc/signaling/test/jsep_track_unittest.cpp

@@ -11,6 +11,7 @@
 // Magic linker includes :(
 #include "FakeMediaStreams.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 
 #include "signaling/src/jsep/JsepTrack.h"
 #include "signaling/src/sdp/SipccSdp.h"

media/webrtc/signaling/test/mediaconduit_unittests.cpp

@@ -17,6 +17,7 @@ using namespace std;
 #include "GmpVideoCodec.h"
 #include "nsIEventTarget.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 #include "nsThreadUtils.h"
 #include "runnable_utils.h"
 #include "signaling/src/common/EncodingConstraints.h"

media/webrtc/signaling/test/mediapipeline_unittest.cpp

@@ -19,6 +19,7 @@
 #include "mozilla/RefPtr.h"
 #include "FakeMediaStreams.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 #include "MediaConduitErrors.h"
 #include "MediaConduitInterface.h"
 #include "MediaPipeline.h"

media/webrtc/signaling/test/sdp_file_parser.cpp

@@ -14,6 +14,7 @@
 
 // without this include linking fails
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 
 #include "signaling/src/sdp/SipccSdpParser.h"
 

media/webrtc/signaling/test/sdp_unittests.cpp

@@ -22,6 +22,7 @@
 #include "nsThreadUtils.h"
 #include "FakeMediaStreams.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 #include "PeerConnectionImpl.h"
 #include "PeerConnectionCtx.h"
 

media/webrtc/signaling/test/signaling_unittests.cpp

@@ -22,6 +22,7 @@
 #include "FakePCObserver.h"
 #include "FakeMediaStreams.h"
 #include "FakeMediaStreamsImpl.h"
+#include "FakeLogging.h"
 #include "PeerConnectionImpl.h"
 #include "PeerConnectionCtx.h"
 #include "PeerConnectionMedia.h"

netwerk/test/NetwerkTestLogging.h

@@ -0,0 +1,23 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#ifndef NetwerkTestLogging_h
+#define NetwerkTestLogging_h
+
+#include "mozilla/Logging.h"
+
+// The netwerk standalone cpp unit tests will just use PR_LogPrint as they don't
+// have access to mozilla::detail::log_print. To support that MOZ_LOG is
+// redefined.
+#undef MOZ_LOG
+#define MOZ_LOG(_module,_level,_args) \
+  PR_BEGIN_MACRO \
+    if (MOZ_LOG_TEST(_module,_level)) { \
+      PR_LogPrint _args; \
+    } \
+  PR_END_MACRO
+
+#endif

netwerk/test/TestBlockingSocket.cpp

@@ -15,7 +15,7 @@
 #include "nsIInputStream.h"
 #include "nsServiceManagerUtils.h"
 #include "nsIOutputStream.h"
-#include "mozilla/Logging.h"
+#include "NetwerkTestLogging.h"
 #include "prenv.h"
 #include "prthread.h"
 #include <stdlib.h>

netwerk/test/TestProtocols.cpp

@@ -56,7 +56,7 @@
 #include "nsStringAPI.h"
 #include "nsNetUtil.h"
 #include "nsServiceManagerUtils.h"
-#include "mozilla/Logging.h"
+#include "NetwerkTestLogging.h"
 
 using namespace mozilla;
 

netwerk/test/TestServ.cpp

@@ -14,7 +14,7 @@
 #include "nsComponentManagerUtils.h"
 #include "nsStringAPI.h"
 #include "nsCOMPtr.h"
-#include "mozilla/Logging.h"
+#include "NetwerkTestLogging.h"
 
 //
 // set NSPR_LOG_MODULES=Test:5

netwerk/test/TestStreamLoader.cpp

@@ -3,7 +3,7 @@
 #include "nsNetUtil.h"
 #include "nsServiceManagerUtils.h"
 #include "nsThreadUtils.h"
-#include "mozilla/Logging.h"
+#include "NetwerkTestLogging.h"
 #include "mozilla/Attributes.h"
 #include "nsIScriptSecurityManager.h"
 

netwerk/test/TestUpload.cpp

@@ -17,7 +17,7 @@
 
 #include "nsIUploadChannel.h"
 
-#include "mozilla/Logging.h"
+#include "NetwerkTestLogging.h"
 //
 // set NSPR_LOG_MODULES=Test:5
 //

xpcom/base/Logging.cpp

@@ -9,12 +9,15 @@
 #include <algorithm>
 
 #include "mozilla/ClearOnShutdown.h"
+#include "mozilla/FileUtils.h"
 #include "mozilla/Mutex.h"
 #include "mozilla/StaticPtr.h"
 #include "nsClassHashtable.h"
+#include "nsDebug.h"
 #include "NSPRLogModulesParser.h"
 
 #include "prenv.h"
+#include "prprf.h"
 
 // NB: Initial amount determined by auditing the codebase for the total amount
 //     of unique module names and padding up to the next power of 2.
@@ -22,6 +25,32 @@ const uint32_t kInitialModuleCount = 256;
 
 namespace mozilla {
 
+namespace detail {
+
+void log_print(const PRLogModuleInfo* aModule,
+               LogLevel aLevel,
+               const char* aFmt, ...)
+{
+  va_list ap;
+  va_start(ap, aFmt);
+  char* buff = PR_vsmprintf(aFmt, ap);
+  PR_LogPrint("%s", buff);
+  PR_smprintf_free(buff);
+  va_end(ap);
+}
+
+void log_print(const LogModule* aModule,
+               LogLevel aLevel,
+               const char* aFmt, ...)
+{
+  va_list ap;
+  va_start(ap, aFmt);
+  aModule->Printv(aLevel, aFmt, ap);
+  va_end(ap);
+}
+
+}
+
 LogLevel
 ToLogLevel(int32_t aLevel)
 {
@@ -30,12 +59,34 @@ ToLogLevel(int32_t aLevel)
   return static_cast<LogLevel>(aLevel);
 }
 
+const char*
+ToLogStr(LogLevel aLevel) {
+  switch (aLevel) {
+    case LogLevel::Error:
+      return "E";
+    case LogLevel::Warning:
+      return "W";
+    case LogLevel::Info:
+      return "I";
+    case LogLevel::Debug:
+      return "D";
+    case LogLevel::Verbose:
+      return "V";
+    case LogLevel::Disabled:
+    default:
+      MOZ_CRASH("Invalid log level.");
+      return "";
+  }
+}
+
 class LogModuleManager
 {
 public:
   LogModuleManager()
     : mModulesLock("logmodules")
     , mModules(kInitialModuleCount)
+    , mOutFile(nullptr)
+    , mAddTimestamp(false)
   {
   }
 
@@ -50,10 +101,27 @@ public:
    */
   void Init()
   {
+    bool shouldAppend = false;
+    bool addTimestamp = false;
     const char* modules = PR_GetEnv("NSPR_LOG_MODULES");
-    NSPRLogModulesParser(modules, [] (const char* aName, LogLevel aLevel) {
-        LogModule::Get(aName)->SetLevel(aLevel);
+    NSPRLogModulesParser(modules,
+        [&shouldAppend, &addTimestamp]
+            (const char* aName, LogLevel aLevel) mutable {
+          if (strcmp(aName, "append") == 0) {
+            shouldAppend = true;
+          } else if (strcmp(aName, "timestamp") == 0) {
+            addTimestamp = true;
+          } else {
+            LogModule::Get(aName)->SetLevel(aLevel);
+          }
     });
+
+    mAddTimestamp = addTimestamp;
+
+    const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
+    if (logFile && logFile[0]) {
+      mOutFile = fopen(logFile, shouldAppend ? "a" : "w");
+    }
   }
 
   LogModule* CreateOrGetModule(const char* aName)
@@ -61,16 +129,64 @@ public:
     OffTheBooksMutexAutoLock guard(mModulesLock);
     LogModule* module = nullptr;
     if (!mModules.Get(aName, &module)) {
-      module = new LogModule(LogLevel::Disabled);
+      module = new LogModule(aName, LogLevel::Disabled);
       mModules.Put(aName, module);
     }
 
     return module;
   }
 
+  void Print(const char* aName, LogLevel aLevel, const char* aFmt, va_list aArgs)
+  {
+    const size_t kBuffSize = 1024;
+    char buff[kBuffSize];
+
+    char* buffToWrite = buff;
+
+    // For backwards compat we need to use the NSPR format string versions
+    // of sprintf and friends and then hand off to printf.
+    size_t charsWritten = PR_vsnprintf(buff, kBuffSize, aFmt, aArgs);
+    if (charsWritten == kBuffSize - 1) {
+      // We may have maxed out, allocate a buffer instead.
+      buffToWrite = PR_vsmprintf(aFmt, aArgs);
+    }
+
+    FILE* out = mOutFile ? mOutFile : stderr;
+
+    // This differs from the NSPR format in that we do not output the
+    // opaque system specific thread pointer (ie pthread_t) cast
+    // to a long. The address of the current PR_Thread continues to be
+    // prefixed.
+    //
+    // Additionally we prefix the output with the abbreviated log level
+    // and the module name.
+    if (!mAddTimestamp) {
+      fprintf_stderr(out,
+                     "[%p]: %s/%s %s",
+                     PR_GetCurrentThread(), ToLogStr(aLevel),
+                     aName, buffToWrite);
+    } else {
+      PRExplodedTime now;
+      PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
+      fprintf_stderr(
+          out,
+          "%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%p]: %s/%s %s",
+          now.tm_year, now.tm_month + 1, now.tm_mday,
+          now.tm_hour, now.tm_min, now.tm_sec, now.tm_usec,
+          PR_GetCurrentThread(), ToLogStr(aLevel),
+          aName, buffToWrite);
+    }
+
+    if (buffToWrite != buff) {
+      PR_smprintf_free(buffToWrite);
+    }
+  }
+
 private:
   OffTheBooksMutex mModulesLock;
   nsClassHashtable<nsCharPtrHashKey, LogModule> mModules;
+  ScopedCloseFile mOutFile;
+  bool mAddTimestamp;
 };
 
 StaticAutoPtr<LogModuleManager> sLogModuleManager;
@@ -101,4 +217,13 @@ LogModule::Init()
   sLogModuleManager->Init();
 }
 
+void
+LogModule::Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const
+{
+  MOZ_ASSERT(sLogModuleManager != nullptr);
+
+  // Forward to LogModule manager w/ level and name
+  sLogModuleManager->Print(Name(), aLevel, aFmt, aArgs);
+}
+
 } // namespace mozilla

xpcom/base/Logging.h

@@ -7,6 +7,8 @@
 #ifndef mozilla_logging_h
 #define mozilla_logging_h
 
+#include <string.h>
+
 #include "prlog.h"
 
 #include "mozilla/Assertions.h"
@@ -53,6 +55,8 @@ LogLevel ToLogLevel(int32_t aLevel);
 class LogModule
 {
 public:
+  ~LogModule() { ::free(mName); }
+
   /**
    * Retrieves the module with the given name. If it does not already exist
    * it will be created.
@@ -84,14 +88,28 @@ public:
    */
   void SetLevel(LogLevel level) { mLevel = level; }
 
+  /**
+   * Print a log message for this module.
+   */
+  void Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const;
+
+  /**
+   * Retrieves the module name.
+   */
+  const char* Name() const { return mName; }
+
 private:
   friend class LogModuleManager;
 
-  explicit LogModule(LogLevel aLevel) : mLevel(aLevel) {}
+  explicit LogModule(const char* aName, LogLevel aLevel)
+    : mName(strdup(aName)), mLevel(aLevel)
+  {
+  }
 
   LogModule(LogModule&) = delete;
   LogModule& operator=(const LogModule&) = delete;
 
+  char* mName;
   Atomic<LogLevel, Relaxed> mLevel;
 };
 
@@ -143,21 +161,43 @@ inline bool log_test(const PRLogModuleInfo* module, LogLevel level) {
   return module && module->level >= static_cast<int>(level);
 }
 
+/**
+ * A rather inefficient wrapper for PR_LogPrint that always allocates.
+ * PR_LogModuleInfo is deprecated so it's not worth the effort to do
+ * any better.
+ */
+void log_print(const PRLogModuleInfo* aModule,
+                      LogLevel aLevel,
+                      const char* aFmt, ...);
+
 inline bool log_test(const LogModule* module, LogLevel level) {
   MOZ_ASSERT(level != LogLevel::Disabled);
   return module && module->ShouldLog(level);
 }
 
+#if !defined(MOZILLA_XPCOMRT_API)
+void log_print(const LogModule* aModule,
+               LogLevel aLevel,
+               const char* aFmt, ...);
+#else
+inline void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt, ...) {}
+#endif
 } // namespace detail
 
 } // namespace mozilla
 
+
 #define MOZ_LOG_TEST(_module,_level) mozilla::detail::log_test(_module, _level)
 
+// Helper macro used convert MOZ_LOG's third parameter, |_args|, from a
+// parenthesized form to a varargs form. For example:
+//   ("%s", "a message") => "%s", "a message"
+#define MOZ_LOG_EXPAND_ARGS(...) __VA_ARGS__
+
 #define MOZ_LOG(_module,_level,_args)     \
   PR_BEGIN_MACRO             \
     if (MOZ_LOG_TEST(_module,_level)) { \
-      PR_LogPrint _args;         \
+      mozilla::detail::log_print(_module, _level, MOZ_LOG_EXPAND_ARGS _args);         \
     }                     \
   PR_END_MACRO
 

xpcom/base/NSPRLogModulesParser.cpp

@@ -10,13 +10,6 @@
 
 const char kDelimiters[] = ", ";
 const char kAdditionalWordChars[] = "_-";
-const char* kReservedNames[] = {
-  "all",
-  "append",
-  "bufsize",
-  "sync",
-  "timestamp",
-};
 
 namespace mozilla {
 
@@ -51,19 +44,7 @@ NSPRLogModulesParser(const char* aLogModules,
       }
     }
 
-    // NSPR reserves a few modules names for logging options. We just skip
-    // those entries here.
-    bool isReserved = false;
-    for (size_t i = 0; i < PR_ARRAY_SIZE(kReservedNames); i++) {
-      if (moduleName.EqualsASCII(kReservedNames[i])) {
-        isReserved = true;
-        break;
-      }
-    }
-
-    if (!isReserved) {
-      aCallback(moduleName.get(), logLevel);
-    }
+    aCallback(moduleName.get(), logLevel);
 
     // Skip ahead to the next token.
     parser.SkipWhites();

xpcom/libxpcomrt/XPCOMRTStubs.cpp

@@ -56,4 +56,10 @@ base::Histogram* GetKeyedHistogramById(ID id, const nsAString&)
 }
 
 } // namespace Telemetry
+
+namespace detail {
+
+void log_print(const PRLogModuleInfo* aModule, LogLevel aLevel, const char* aFmt, ...) {}
+
+} // namespace detail
 } // namespace mozilla

xpcom/tests/gtest/TestNSPRLogModulesParser.cpp

@@ -61,29 +61,10 @@ TEST(NSPRLogModulesParser, LevelSpecified)
   }
 }
 
-TEST(NSPRLogModulesParser, Reserved)
-{
-  const char* reservedNames[] = {
-    "all",
-    "append",
-    "bufsize",
-    "sync",
-    "timestamp",
-  };
-
-  for (size_t i = 0; i < MOZ_ARRAY_LENGTH(reservedNames); i++) {
-    bool callbackInvoked = false;
-    mozilla::NSPRLogModulesParser(reservedNames[i],
-        [&](const char*, mozilla::LogLevel) mutable {
-          callbackInvoked = true;
-        });
-    EXPECT_FALSE(callbackInvoked);
-  }
-}
-
 TEST(NSPRLogModulesParser, Multiple)
 {
   std::pair<const char*, mozilla::LogLevel> expected[] = {
+    { "timestamp", mozilla::LogLevel::Error },
     { "Foo", mozilla::LogLevel::Info },
     { "Bar", mozilla::LogLevel::Error },
     { "Baz", mozilla::LogLevel::Warning },