summaryrefslogtreecommitdiffstats
path: root/xpcom/base/Logging.cpp
diff options
context:
space:
mode:
Diffstat (limited to 'xpcom/base/Logging.cpp')
-rw-r--r--xpcom/base/Logging.cpp568
1 files changed, 568 insertions, 0 deletions
diff --git a/xpcom/base/Logging.cpp b/xpcom/base/Logging.cpp
new file mode 100644
index 000000000..e87df91e4
--- /dev/null
+++ b/xpcom/base/Logging.cpp
@@ -0,0 +1,568 @@
+/* -*- 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/. */
+
+#include "mozilla/Logging.h"
+
+#include <algorithm>
+
+#include "mozilla/ClearOnShutdown.h"
+#include "mozilla/FileUtils.h"
+#include "mozilla/Mutex.h"
+#include "mozilla/StaticPtr.h"
+#include "mozilla/Sprintf.h"
+#include "mozilla/Atomics.h"
+#include "mozilla/UniquePtrExtensions.h"
+#include "nsClassHashtable.h"
+#include "nsDebug.h"
+#include "NSPRLogModulesParser.h"
+
+#include "prenv.h"
+#include "prprf.h"
+#ifdef XP_WIN
+#include <process.h>
+#else
+#include <sys/types.h>
+#include <unistd.h>
+#endif
+
+// 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.
+const uint32_t kInitialModuleCount = 256;
+// When rotate option is added to the modules list, this is the hardcoded
+// number of files we create and rotate. When there is rotate:40,
+// we will keep four files per process, each limited to 10MB. Sum is 40MB,
+// the given limit.
+const uint32_t kRotateFilesNumber = 4;
+
+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);
+}
+
+} // detail
+
+LogLevel
+ToLogLevel(int32_t aLevel)
+{
+ aLevel = std::min(aLevel, static_cast<int32_t>(LogLevel::Verbose));
+ aLevel = std::max(aLevel, static_cast<int32_t>(LogLevel::Disabled));
+ 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 "";
+ }
+}
+
+namespace detail {
+
+/**
+ * A helper class providing reference counting for FILE*.
+ * It encapsulates the following:
+ * - the FILE handle
+ * - the order number it was created for when rotating (actual path)
+ * - number of active references
+ */
+class LogFile
+{
+ FILE* mFile;
+ uint32_t mFileNum;
+
+public:
+ LogFile(FILE* aFile, uint32_t aFileNum)
+ : mFile(aFile)
+ , mFileNum(aFileNum)
+ , mNextToRelease(nullptr)
+ {
+ }
+
+ ~LogFile()
+ {
+ fclose(mFile);
+ delete mNextToRelease;
+ }
+
+ FILE* File() const { return mFile; }
+ uint32_t Num() const { return mFileNum; }
+
+ LogFile* mNextToRelease;
+};
+
+const char*
+ExpandPIDMarker(const char* aFilename, char (&buffer)[2048])
+{
+ MOZ_ASSERT(aFilename);
+ static const char kPIDToken[] = "%PID";
+ const char* pidTokenPtr = strstr(aFilename, kPIDToken);
+ if (pidTokenPtr &&
+ SprintfLiteral(buffer, "%.*s%s%d%s",
+ static_cast<int>(pidTokenPtr - aFilename), aFilename,
+ XRE_IsParentProcess() ? "-main." : "-child.",
+ base::GetCurrentProcId(),
+ pidTokenPtr + strlen(kPIDToken)) > 0)
+ {
+ return buffer;
+ }
+
+ return aFilename;
+}
+
+} // detail
+
+namespace {
+ // Helper method that initializes an empty va_list to be empty.
+ void empty_va(va_list *va, ...)
+ {
+ va_start(*va, va);
+ va_end(*va);
+ }
+}
+
+class LogModuleManager
+{
+public:
+ LogModuleManager()
+ : mModulesLock("logmodules")
+ , mModules(kInitialModuleCount)
+ , mPrintEntryCount(0)
+ , mOutFile(nullptr)
+ , mToReleaseFile(nullptr)
+ , mOutFileNum(0)
+ , mOutFilePath(strdup(""))
+ , mMainThread(PR_GetCurrentThread())
+ , mSetFromEnv(false)
+ , mAddTimestamp(false)
+ , mIsSync(false)
+ , mRotate(0)
+ {
+ }
+
+ ~LogModuleManager()
+ {
+ detail::LogFile* logFile = mOutFile.exchange(nullptr);
+ delete logFile;
+ }
+
+ /**
+ * Loads config from env vars if present.
+ */
+ void Init()
+ {
+ bool shouldAppend = false;
+ bool addTimestamp = false;
+ bool isSync = false;
+ int32_t rotate = 0;
+ const char* modules = PR_GetEnv("MOZ_LOG");
+ if (!modules || !modules[0]) {
+ modules = PR_GetEnv("MOZ_LOG_MODULES");
+ if (modules) {
+ NS_WARNING("MOZ_LOG_MODULES is deprecated."
+ "\nPlease use MOZ_LOG instead.");
+ }
+ }
+ if (!modules || !modules[0]) {
+ modules = PR_GetEnv("NSPR_LOG_MODULES");
+ if (modules) {
+ NS_WARNING("NSPR_LOG_MODULES is deprecated."
+ "\nPlease use MOZ_LOG instead.");
+ }
+ }
+
+ NSPRLogModulesParser(modules,
+ [&shouldAppend, &addTimestamp, &isSync, &rotate]
+ (const char* aName, LogLevel aLevel, int32_t aValue) mutable {
+ if (strcmp(aName, "append") == 0) {
+ shouldAppend = true;
+ } else if (strcmp(aName, "timestamp") == 0) {
+ addTimestamp = true;
+ } else if (strcmp(aName, "sync") == 0) {
+ isSync = true;
+ } else if (strcmp(aName, "rotate") == 0) {
+ rotate = (aValue << 20) / kRotateFilesNumber;
+ } else {
+ LogModule::Get(aName)->SetLevel(aLevel);
+ }
+ });
+
+ // Rotate implies timestamp to make the files readable
+ mAddTimestamp = addTimestamp || rotate > 0;
+ mIsSync = isSync;
+ mRotate = rotate;
+
+ if (rotate > 0 && shouldAppend) {
+ NS_WARNING("MOZ_LOG: when you rotate the log, you cannot use append!");
+ }
+
+ const char* logFile = PR_GetEnv("MOZ_LOG_FILE");
+ if (!logFile || !logFile[0]) {
+ logFile = PR_GetEnv("NSPR_LOG_FILE");
+ }
+
+ if (logFile && logFile[0]) {
+ char buf[2048];
+ logFile = detail::ExpandPIDMarker(logFile, buf);
+ mOutFilePath.reset(strdup(logFile));
+
+ if (mRotate > 0) {
+ // Delete all the previously captured files, including non-rotated
+ // log files, so that users don't complain our logs eat space even
+ // after the rotate option has been added and don't happen to send
+ // us old large logs along with the rotated files.
+ remove(mOutFilePath.get());
+ for (uint32_t i = 0; i < kRotateFilesNumber; ++i) {
+ RemoveFile(i);
+ }
+ }
+
+ mOutFile = OpenFile(shouldAppend, mOutFileNum);
+ mSetFromEnv = true;
+ }
+ }
+
+ void SetLogFile(const char* aFilename)
+ {
+ // For now we don't allow you to change the file at runtime.
+ if (mSetFromEnv) {
+ NS_WARNING("LogModuleManager::SetLogFile - Log file was set from the "
+ "MOZ_LOG_FILE environment variable.");
+ return;
+ }
+
+ const char * filename = aFilename ? aFilename : "";
+ char buf[2048];
+ filename = detail::ExpandPIDMarker(filename, buf);
+
+ // Can't use rotate at runtime yet.
+ MOZ_ASSERT(mRotate == 0, "We don't allow rotate for runtime logfile changes");
+ mOutFilePath.reset(strdup(filename));
+
+ // Exchange mOutFile and set it to be released once all the writes are done.
+ detail::LogFile* newFile = OpenFile(false, 0);
+ detail::LogFile* oldFile = mOutFile.exchange(newFile);
+
+ // Since we don't allow changing the logfile if MOZ_LOG_FILE is already set,
+ // and we don't allow log rotation when setting it at runtime, mToReleaseFile
+ // will be null, so we're not leaking.
+ DebugOnly<detail::LogFile*> prevFile = mToReleaseFile.exchange(oldFile);
+ MOZ_ASSERT(!prevFile, "Should be null because rotation is not allowed");
+
+ // If we just need to release a file, we must force print, in order to
+ // trigger the closing and release of mToReleaseFile.
+ if (oldFile) {
+ va_list va;
+ empty_va(&va);
+ Print("Logger", LogLevel::Info, "Flushing old log files\n", va);
+ }
+ }
+
+ uint32_t GetLogFile(char *aBuffer, size_t aLength)
+ {
+ uint32_t len = strlen(mOutFilePath.get());
+ if (len + 1 > aLength) {
+ return 0;
+ }
+ snprintf(aBuffer, aLength, "%s", mOutFilePath.get());
+ return len;
+ }
+
+ void SetIsSync(bool aIsSync)
+ {
+ mIsSync = aIsSync;
+ }
+
+ void SetAddTimestamp(bool aAddTimestamp)
+ {
+ mAddTimestamp = aAddTimestamp;
+ }
+
+ detail::LogFile* OpenFile(bool aShouldAppend, uint32_t aFileNum)
+ {
+ FILE* file;
+
+ if (mRotate > 0) {
+ char buf[2048];
+ SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
+
+ // rotate doesn't support append.
+ file = fopen(buf, "w");
+ } else {
+ file = fopen(mOutFilePath.get(), aShouldAppend ? "a" : "w");
+ }
+
+ if (!file) {
+ return nullptr;
+ }
+
+ return new detail::LogFile(file, aFileNum);
+ }
+
+ void RemoveFile(uint32_t aFileNum)
+ {
+ char buf[2048];
+ SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
+ remove(buf);
+ }
+
+ LogModule* CreateOrGetModule(const char* aName)
+ {
+ OffTheBooksMutexAutoLock guard(mModulesLock);
+ LogModule* module = nullptr;
+ if (!mModules.Get(aName, &module)) {
+ 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.
+ va_list argsCopy;
+ va_copy(argsCopy, aArgs);
+ size_t charsWritten = PR_vsnprintf(buff, kBuffSize, aFmt, argsCopy);
+ va_end(argsCopy);
+
+ if (charsWritten == kBuffSize - 1) {
+ // We may have maxed out, allocate a buffer instead.
+ buffToWrite = PR_vsmprintf(aFmt, aArgs);
+ charsWritten = strlen(buffToWrite);
+ }
+
+ // Determine if a newline needs to be appended to the message.
+ const char* newline = "";
+ if (charsWritten == 0 || buffToWrite[charsWritten - 1] != '\n') {
+ newline = "\n";
+ }
+
+ FILE* out = stderr;
+
+ // In case we use rotate, this ensures the FILE is kept alive during
+ // its use. Increased before we load mOutFile.
+ ++mPrintEntryCount;
+
+ detail::LogFile* outFile = mOutFile;
+ if (outFile) {
+ out = outFile->File();
+ }
+
+ // 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.
+ PRThread *currentThread = PR_GetCurrentThread();
+ const char *currentThreadName = (mMainThread == currentThread)
+ ? "Main Thread"
+ : PR_GetThreadName(currentThread);
+
+ char noNameThread[40];
+ if (!currentThreadName) {
+ SprintfLiteral(noNameThread, "Unnamed thread %p", currentThread);
+ currentThreadName = noNameThread;
+ }
+
+ if (!mAddTimestamp) {
+ fprintf_stderr(out,
+ "[%s]: %s/%s %s%s",
+ currentThreadName, ToLogStr(aLevel),
+ aName, buffToWrite, newline);
+ } else {
+ PRExplodedTime now;
+ PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
+ fprintf_stderr(
+ out,
+ "%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%s]: %s/%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,
+ currentThreadName, ToLogStr(aLevel),
+ aName, buffToWrite, newline);
+ }
+
+ if (mIsSync) {
+ fflush(out);
+ }
+
+ if (buffToWrite != buff) {
+ PR_smprintf_free(buffToWrite);
+ }
+
+ if (mRotate > 0 && outFile) {
+ int32_t fileSize = ftell(out);
+ if (fileSize > mRotate) {
+ uint32_t fileNum = outFile->Num();
+
+ uint32_t nextFileNum = fileNum + 1;
+ if (nextFileNum >= kRotateFilesNumber) {
+ nextFileNum = 0;
+ }
+
+ // And here is the trick. The current out-file remembers its order
+ // number. When no other thread shifted the global file number yet,
+ // we are the thread to open the next file.
+ if (mOutFileNum.compareExchange(fileNum, nextFileNum)) {
+ // We can work with mToReleaseFile because we are sure the
+ // mPrintEntryCount can't drop to zero now - the condition
+ // to actually delete what's stored in that member.
+ // And also, no other thread can enter this piece of code
+ // because mOutFile is still holding the current file with
+ // the non-shifted number. The compareExchange() above is
+ // a no-op for other threads.
+ outFile->mNextToRelease = mToReleaseFile;
+ mToReleaseFile = outFile;
+
+ mOutFile = OpenFile(false, nextFileNum);
+ }
+ }
+ }
+
+ if (--mPrintEntryCount == 0 && mToReleaseFile) {
+ // We were the last Print() entered, if there is a file to release
+ // do it now. exchange() is atomic and makes sure we release the file
+ // only once on one thread.
+ detail::LogFile* release = mToReleaseFile.exchange(nullptr);
+ delete release;
+ }
+ }
+
+private:
+ OffTheBooksMutex mModulesLock;
+ nsClassHashtable<nsCharPtrHashKey, LogModule> mModules;
+
+ // Print() entry counter, actually reflects concurrent use of the current
+ // output file. ReleaseAcquire ensures that manipulation with mOutFile
+ // and mToReleaseFile is synchronized by manipulation with this value.
+ Atomic<uint32_t, ReleaseAcquire> mPrintEntryCount;
+ // File to write to. ReleaseAcquire because we need to sync mToReleaseFile
+ // with this.
+ Atomic<detail::LogFile*, ReleaseAcquire> mOutFile;
+ // File to be released when reference counter drops to zero. This member
+ // is assigned mOutFile when the current file has reached the limit.
+ // It can be Relaxed, since it's synchronized with mPrintEntryCount
+ // manipulation and we do atomic exchange() on it.
+ Atomic<detail::LogFile*, Relaxed> mToReleaseFile;
+ // The next file number. This is mostly only for synchronization sake.
+ // Can have relaxed ordering, since we only do compareExchange on it which
+ // is atomic regardless ordering.
+ Atomic<uint32_t, Relaxed> mOutFileNum;
+ // Just keeps the actual file path for further use.
+ UniqueFreePtr<char[]> mOutFilePath;
+
+ PRThread *mMainThread;
+ bool mSetFromEnv;
+ Atomic<bool, Relaxed> mAddTimestamp;
+ Atomic<bool, Relaxed> mIsSync;
+ int32_t mRotate;
+};
+
+StaticAutoPtr<LogModuleManager> sLogModuleManager;
+
+LogModule*
+LogModule::Get(const char* aName)
+{
+ // This is just a pass through to the LogModuleManager so
+ // that the LogModuleManager implementation can be kept internal.
+ MOZ_ASSERT(sLogModuleManager != nullptr);
+ return sLogModuleManager->CreateOrGetModule(aName);
+}
+
+void
+LogModule::SetLogFile(const char* aFilename)
+{
+ MOZ_ASSERT(sLogModuleManager);
+ sLogModuleManager->SetLogFile(aFilename);
+}
+
+uint32_t
+LogModule::GetLogFile(char *aBuffer, size_t aLength)
+{
+ MOZ_ASSERT(sLogModuleManager);
+ return sLogModuleManager->GetLogFile(aBuffer, aLength);
+}
+
+void
+LogModule::SetAddTimestamp(bool aAddTimestamp)
+{
+ sLogModuleManager->SetAddTimestamp(aAddTimestamp);
+}
+
+void
+LogModule::SetIsSync(bool aIsSync)
+{
+ sLogModuleManager->SetIsSync(aIsSync);
+}
+
+void
+LogModule::Init()
+{
+ // NB: This method is not threadsafe; it is expected to be called very early
+ // in startup prior to any other threads being run.
+ if (sLogModuleManager) {
+ // Already initialized.
+ return;
+ }
+
+ // NB: We intentionally do not register for ClearOnShutdown as that happens
+ // before all logging is complete. And, yes, that means we leak, but
+ // we're doing that intentionally.
+ sLogModuleManager = new LogModuleManager();
+ 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