gecko-dev/xpcom/base/Logging.cpp

/* -*- 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/LateWriteChecks.h"
#include "mozilla/Mutex.h"
#include "mozilla/StaticPtr.h"
#include "mozilla/Printf.h"
#include "mozilla/Atomics.h"
#include "mozilla/Sprintf.h"
#include "mozilla/UniquePtrExtensions.h"
#include "MainThreadUtils.h"
#include "nsClassHashtable.h"
#include "nsDebug.h"
#include "nsDebugImpl.h"
#include "NSPRLogModulesParser.h"
#include "LogCommandLineHandler.h"
#ifdef MOZ_GECKO_PROFILER
#  include "ProfilerMarkerPayload.h"
#endif

#include "prenv.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.
//
// (Note: When this is changed to be >= 10, SandboxBroker::LaunchApp must add
// another rule to allow logfile.?? be written by content processes.)
const uint32_t kRotateFilesNumber = 4;

namespace mozilla {

namespace detail {

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);
}

void log_print(const LogModule* aModule, LogLevel aLevel, TimeStamp* aStart,
               const char* aFmt, ...) {
  va_list ap;
  va_start(ap, aFmt);
  aModule->Printv(aLevel, aStart, aFmt, ap);
  va_end(ap);
}

}  // namespace 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);
}

static 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;
};

static const char* ExpandLogFileName(const char* aFilename,
                                     char (&buffer)[2048]) {
  MOZ_ASSERT(aFilename);
  static const char kPIDToken[] = MOZ_LOG_PID_TOKEN;
  static const char kMOZLOGExt[] = MOZ_LOG_FILE_EXTENSION;

  bool hasMozLogExtension = StringEndsWith(nsDependentCString(aFilename),
                                           nsLiteralCString(kMOZLOGExt));

  const char* pidTokenPtr = strstr(aFilename, kPIDToken);
  if (pidTokenPtr &&
      SprintfLiteral(buffer, "%.*s%s%d%s%s",
                     static_cast<int>(pidTokenPtr - aFilename), aFilename,
                     XRE_IsParentProcess() ? "-main." : "-child.",
                     base::GetCurrentProcId(), pidTokenPtr + strlen(kPIDToken),
                     hasMozLogExtension ? "" : kMOZLOGExt) > 0) {
    return buffer;
  }

  if (!hasMozLogExtension &&
      SprintfLiteral(buffer, "%s%s", aFilename, kMOZLOGExt) > 0) {
    return buffer;
  }

  return aFilename;
}

}  // namespace 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);
}
}  // namespace

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),
        mAddProfilerMarker(false),
        mIsRaw(false),
        mIsSync(false),
        mRotate(0),
        mInitialized(false) {}

  ~LogModuleManager() {
    detail::LogFile* logFile = mOutFile.exchange(nullptr);
    delete logFile;
  }

  /**
   * Loads config from command line args or env vars if present, in
   * this specific order of priority.
   *
   * Notes:
   *
   * 1) This function is only intended to be called once per session.
   * 2) None of the functions used in Init should rely on logging.
   */
  void Init(int argc, char* argv[]) {
    MOZ_DIAGNOSTIC_ASSERT(!mInitialized);
    mInitialized = true;

    LoggingHandleCommandLineArgs(argc, static_cast<char const* const*>(argv),
                                 [](nsACString const& env) {
                                   // We deliberately set/rewrite the
                                   // environment variables so that when child
                                   // processes are spawned w/o passing the
                                   // arguments they still inherit the logging
                                   // settings as well as sandboxing can be
                                   // correctly set. Scripts can pass
                                   // -MOZ_LOG=$MOZ_LOG,modules as an argument
                                   // to merge existing settings, if required.

                                   // PR_SetEnv takes ownership of the string.
                                   PR_SetEnv(ToNewCString(env));
                                 });

    bool shouldAppend = false;
    bool addTimestamp = false;
    bool isSync = false;
    bool isRaw = false;
    bool isMarkers = 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.");
      }
    }

    // Need to capture `this` since `sLogModuleManager` is not set until after
    // initialization is complete.
    NSPRLogModulesParser(
        modules, [this, &shouldAppend, &addTimestamp, &isSync, &isRaw, &rotate,
                  &isMarkers](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, "raw") == 0) {
            isRaw = true;
          } else if (strcmp(aName, "rotate") == 0) {
            rotate = (aValue << 20) / kRotateFilesNumber;
          } else if (strcmp(aName, "profilermarkers") == 0) {
            isMarkers = true;
          } else {
            this->CreateOrGetModule(aName)->SetLevel(aLevel);
          }
        });

    // Rotate implies timestamp to make the files readable
    mAddTimestamp = addTimestamp || rotate > 0;
    mIsSync = isSync;
    mIsRaw = isRaw;
    mRotate = rotate;
    mAddProfilerMarker = isMarkers;

    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::ExpandLogFileName(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::ExpandLogFileName(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) MOZ_FORMAT_PRINTF(4, 0) {
    Print(aName, aLevel, nullptr, aFmt, aArgs);
  }

  void Print(const char* aName, LogLevel aLevel, const TimeStamp* aStart,
             const char* aFmt, va_list aArgs) MOZ_FORMAT_PRINTF(5, 0) {
    AutoSuspendLateWriteChecks suspendLateWriteChecks;
    long pid = static_cast<long>(base::GetCurrentProcId());
    const size_t kBuffSize = 1024;
    char buff[kBuffSize];

    char* buffToWrite = buff;
    SmprintfPointer allocatedBuff;

    va_list argsCopy;
    va_copy(argsCopy, aArgs);
    int charsWritten = VsprintfLiteral(buff, aFmt, argsCopy);
    va_end(argsCopy);

    if (charsWritten < 0) {
      // Print out at least something.  We must copy to the local buff,
      // can't just assign aFmt to buffToWrite, since when
      // buffToWrite != buff, we try to release it.
      MOZ_ASSERT(false, "Probably incorrect format string in LOG?");
      strncpy(buff, aFmt, kBuffSize - 1);
      buff[kBuffSize - 1] = '\0';
      charsWritten = strlen(buff);
    } else if (static_cast<size_t>(charsWritten) >= kBuffSize - 1) {
      // We may have maxed out, allocate a buffer instead.
      allocatedBuff = mozilla::Vsmprintf(aFmt, aArgs);
      buffToWrite = allocatedBuff.get();
      charsWritten = strlen(buffToWrite);
    }

#ifdef MOZ_GECKO_PROFILER
    if (mAddProfilerMarker && profiler_can_accept_markers()) {
      if (aStart) {
        PROFILER_ADD_MARKER_WITH_PAYLOAD(
            "LogMessages", OTHER, LogMarkerPayload,
            (aName, buffToWrite, *aStart, TimeStamp::Now()));
      } else {
        PROFILER_ADD_MARKER_WITH_PAYLOAD(
            "LogMessages", OTHER, LogMarkerPayload,
            (aName, buffToWrite, TimeStamp::Now()));
      }
    }
#endif

    // 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 && !aStart) {
      if (!mIsRaw) {
        fprintf_stderr(out, "[%s %ld: %s]: %s/%s %s%s",
                       nsDebugImpl::GetMultiprocessMode(), pid,
                       currentThreadName, ToLogStr(aLevel), aName, buffToWrite,
                       newline);
      } else {
        fprintf_stderr(out, "%s%s", buffToWrite, newline);
      }
    } else {
      if (aStart) {
        // XXX is there a reasonable way to convert one to the other?  this is
        // bad
        PRTime prnow = PR_Now();
        TimeStamp tmnow = TimeStamp::NowUnfuzzed();
        TimeDuration duration = tmnow - *aStart;
        PRTime prstart = prnow - duration.ToMicroseconds();

        PRExplodedTime now;
        PRExplodedTime start;
        PR_ExplodeTime(prnow, PR_GMTParameters, &now);
        PR_ExplodeTime(prstart, PR_GMTParameters, &start);
        // Ignore that the start time might be in a different day
        fprintf_stderr(
            out,
            "%04d-%02d-%02d %02d:%02d:%02d.%06d -> %02d:%02d:%02d.%06d UTC "
            "(%.1gms)- [%s %ld: %s]: %s/%s %s%s",
            now.tm_year, now.tm_month + 1, start.tm_mday, start.tm_hour,
            start.tm_min, start.tm_sec, start.tm_usec, now.tm_hour, now.tm_min,
            now.tm_sec, now.tm_usec, duration.ToMilliseconds(),
            nsDebugImpl::GetMultiprocessMode(), pid, 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 %ld: %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, nsDebugImpl::GetMultiprocessMode(), pid,
            currentThreadName, ToLogStr(aLevel), aName, buffToWrite, newline);
      }
    }

    if (mIsSync) {
      fflush(out);
    }

    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> mAddProfilerMarker;
  Atomic<bool, Relaxed> mIsRaw;
  Atomic<bool, Relaxed> mIsSync;
  int32_t mRotate;
  bool mInitialized;
};

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);
}

// This function is defined in gecko_logger/src/lib.rs
// We mirror the level in rust code so we don't get forwarded all of the
// rust logging and have to create an LogModule for each rust component.
extern "C" void set_rust_log_level(const char* name, uint8_t level);

void LogModule::SetLevel(LogLevel level) {
  mLevel = level;

  // If the log module contains `::` it is likely a rust module, so we
  // pass the level into the rust code so it will know to forward the logging
  // to Gecko.
  if (strstr(mName, "::")) {
    set_rust_log_level(mName, static_cast<uint8_t>(level));
  }
}

void LogModule::Init(int argc, char* argv[]) {
  // NB: This method is not threadsafe; it is expected to be called very early
  //     in startup prior to any other threads being run.
  MOZ_DIAGNOSTIC_ASSERT(NS_IsMainThread());

  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.

  // Don't assign the pointer until after Init is called. This should help us
  // detect if any of the functions called by Init somehow rely on logging.
  auto mgr = new LogModuleManager();
  mgr->Init(argc, argv);
  sLogModuleManager = mgr;
}

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);
}

void LogModule::Printv(LogLevel aLevel, const TimeStamp* aStart,
                       const char* aFmt, va_list aArgs) const {
  MOZ_ASSERT(sLogModuleManager != nullptr);

  // Forward to LogModule manager w/ level and name
  sLogModuleManager->Print(Name(), aLevel, aStart, aFmt, aArgs);
}

}  // namespace mozilla

extern "C" {

// This function is called by external code (rust) to log to one of our
// log modules.
void ExternMozLog(const char* aModule, mozilla::LogLevel aLevel,
                  const char* aMsg) {
  MOZ_ASSERT(sLogModuleManager != nullptr);

  LogModule* m = sLogModuleManager->CreateOrGetModule(aModule);
  if (MOZ_LOG_TEST(m, aLevel)) {
    mozilla::detail::log_print(m, aLevel, "%s", aMsg);
  }
}

}  // extern "C"