From 03a18ab1cb4d90b093b9147b04ef1d4c333dced0 Mon Sep 17 00:00:00 2001 From: Eric Rahm Date: Tue, 5 Jan 2016 13:05:19 -0800 Subject: [PATCH] Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell --- media/webrtc/signaling/test/FakeLogging.h | 18 +++ .../signaling/test/jsep_session_unittest.cpp | 1 + .../signaling/test/jsep_track_unittest.cpp | 1 + .../signaling/test/mediaconduit_unittests.cpp | 1 + .../signaling/test/mediapipeline_unittest.cpp | 1 + .../webrtc/signaling/test/sdp_file_parser.cpp | 1 + media/webrtc/signaling/test/sdp_unittests.cpp | 1 + .../signaling/test/signaling_unittests.cpp | 1 + netwerk/test/NetwerkTestLogging.h | 23 +++ netwerk/test/TestBlockingSocket.cpp | 2 +- netwerk/test/TestProtocols.cpp | 2 +- netwerk/test/TestServ.cpp | 2 +- netwerk/test/TestStreamLoader.cpp | 2 +- netwerk/test/TestUpload.cpp | 2 +- xpcom/base/Logging.cpp | 131 +++++++++++++++++- xpcom/base/Logging.h | 44 +++++- xpcom/base/NSPRLogModulesParser.cpp | 21 +-- xpcom/libxpcomrt/XPCOMRTStubs.cpp | 6 + .../tests/gtest/TestNSPRLogModulesParser.cpp | 21 +-- 19 files changed, 231 insertions(+), 50 deletions(-) create mode 100644 media/webrtc/signaling/test/FakeLogging.h create mode 100644 netwerk/test/NetwerkTestLogging.h diff --git a/media/webrtc/signaling/test/FakeLogging.h b/media/webrtc/signaling/test/FakeLogging.h new file mode 100644 index 00000000000..4363a55a456 --- /dev/null +++ b/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 diff --git a/media/webrtc/signaling/test/jsep_session_unittest.cpp b/media/webrtc/signaling/test/jsep_session_unittest.cpp index 1208e6a83f4..48923152a92 100644 --- a/media/webrtc/signaling/test/jsep_session_unittest.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/jsep_track_unittest.cpp b/media/webrtc/signaling/test/jsep_track_unittest.cpp index c2c36857f05..44d39ddfa5c 100644 --- a/media/webrtc/signaling/test/jsep_track_unittest.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/mediaconduit_unittests.cpp b/media/webrtc/signaling/test/mediaconduit_unittests.cpp index 4a6b1b61493..c14dc373c77 100644 --- a/media/webrtc/signaling/test/mediaconduit_unittests.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/mediapipeline_unittest.cpp b/media/webrtc/signaling/test/mediapipeline_unittest.cpp index 06febf8c9fa..d67fc6dacbd 100644 --- a/media/webrtc/signaling/test/mediapipeline_unittest.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/sdp_file_parser.cpp b/media/webrtc/signaling/test/sdp_file_parser.cpp index b7984303129..fe2f63b0039 100644 --- a/media/webrtc/signaling/test/sdp_file_parser.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/sdp_unittests.cpp b/media/webrtc/signaling/test/sdp_unittests.cpp index aa27fadc57a..c13d87b8baa 100644 --- a/media/webrtc/signaling/test/sdp_unittests.cpp +++ b/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" diff --git a/media/webrtc/signaling/test/signaling_unittests.cpp b/media/webrtc/signaling/test/signaling_unittests.cpp index fd176945e5f..c3817171ba1 100644 --- a/media/webrtc/signaling/test/signaling_unittests.cpp +++ b/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" diff --git a/netwerk/test/NetwerkTestLogging.h b/netwerk/test/NetwerkTestLogging.h new file mode 100644 index 00000000000..68e955fd394 --- /dev/null +++ b/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 diff --git a/netwerk/test/TestBlockingSocket.cpp b/netwerk/test/TestBlockingSocket.cpp index 3312a87b34b..d4b4a615fb0 100644 --- a/netwerk/test/TestBlockingSocket.cpp +++ b/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 diff --git a/netwerk/test/TestProtocols.cpp b/netwerk/test/TestProtocols.cpp index 9de713d9c28..9724a9dce95 100644 --- a/netwerk/test/TestProtocols.cpp +++ b/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; diff --git a/netwerk/test/TestServ.cpp b/netwerk/test/TestServ.cpp index 17978a2b885..7a013ea60a5 100644 --- a/netwerk/test/TestServ.cpp +++ b/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 diff --git a/netwerk/test/TestStreamLoader.cpp b/netwerk/test/TestStreamLoader.cpp index 6b26b854ca2..79f8b23591c 100644 --- a/netwerk/test/TestStreamLoader.cpp +++ b/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" diff --git a/netwerk/test/TestUpload.cpp b/netwerk/test/TestUpload.cpp index 6e18d89395d..23e3d8aa242 100644 --- a/netwerk/test/TestUpload.cpp +++ b/netwerk/test/TestUpload.cpp @@ -17,7 +17,7 @@ #include "nsIUploadChannel.h" -#include "mozilla/Logging.h" +#include "NetwerkTestLogging.h" // // set NSPR_LOG_MODULES=Test:5 // diff --git a/xpcom/base/Logging.cpp b/xpcom/base/Logging.cpp index b20fa81af80..221aab6e242 100644 --- a/xpcom/base/Logging.cpp +++ b/xpcom/base/Logging.cpp @@ -9,12 +9,15 @@ #include #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(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 mModules; + ScopedCloseFile mOutFile; + bool mAddTimestamp; }; StaticAutoPtr 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 diff --git a/xpcom/base/Logging.h b/xpcom/base/Logging.h index a975575932b..30aa611bf41 100644 --- a/xpcom/base/Logging.h +++ b/xpcom/base/Logging.h @@ -7,6 +7,8 @@ #ifndef mozilla_logging_h #define mozilla_logging_h +#include + #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 mLevel; }; @@ -143,21 +161,43 @@ inline bool log_test(const PRLogModuleInfo* module, LogLevel level) { return module && module->level >= static_cast(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 diff --git a/xpcom/base/NSPRLogModulesParser.cpp b/xpcom/base/NSPRLogModulesParser.cpp index 883485e5e2e..43c80e915f4 100644 --- a/xpcom/base/NSPRLogModulesParser.cpp +++ b/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(); diff --git a/xpcom/libxpcomrt/XPCOMRTStubs.cpp b/xpcom/libxpcomrt/XPCOMRTStubs.cpp index 0820c002b3c..ea8c95beae9 100644 --- a/xpcom/libxpcomrt/XPCOMRTStubs.cpp +++ b/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 diff --git a/xpcom/tests/gtest/TestNSPRLogModulesParser.cpp b/xpcom/tests/gtest/TestNSPRLogModulesParser.cpp index ab06f3e1610..e6884cabb65 100644 --- a/xpcom/tests/gtest/TestNSPRLogModulesParser.cpp +++ b/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 expected[] = { + { "timestamp", mozilla::LogLevel::Error }, { "Foo", mozilla::LogLevel::Info }, { "Bar", mozilla::LogLevel::Error }, { "Baz", mozilla::LogLevel::Warning },