Bug 1239686 - Add method to set logging file at runtime r=nfroyd
authorValentin Gosu <valentin.gosu@gmail.com>
Mon, 19 Sep 2016 17:39:47 +0200
changeset 314398 d6809e466fe6c6cdeebeebe8878ee0d03e59d4f6
parent 314397 945544b11e381c00753eb64e6c79196d7609033e
child 314399 80a9c7007243ac4e931a8c4352723cbf840aff03
child 314435 9b792ae11734c602485896031a6d3400a3f603b3
push id30725
push userkwierso@gmail.com
push dateMon, 19 Sep 2016 22:51:45 +0000
treeherdermozilla-central@80a9c7007243 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersnfroyd
bugs1239686
milestone51.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1239686 - Add method to set logging file at runtime r=nfroyd * Only allows setting the log file at runtime if not set by an Env Var * LogModulePrefWatcher will watch logging.config. prefs and call into Logging.cpp to set the log file, sync or timestamp * Log files set by pref will have a -main.PID or -child.PID suffix * If the logging.config.clear_on_startup pref is true, prefs will be reset upon restart. MozReview-Commit-ID: CWJujX4jm2A
modules/libpref/init/all.js
xpcom/base/LogModulePrefWatcher.cpp
xpcom/base/Logging.cpp
xpcom/base/Logging.h
--- a/modules/libpref/init/all.js
+++ b/modules/libpref/init/all.js
@@ -1287,16 +1287,21 @@ pref("javascript.options.dump_stack_on_d
 
 // advanced prefs
 pref("advanced.mailftp",                    false);
 pref("image.animation_mode",                "normal");
 
 // Same-origin policy for file URIs, "false" is traditional
 pref("security.fileuri.strict_origin_policy", true);
 
+// If this pref is true, prefs in the logging.config branch will be cleared on
+// startup. This is done so that setting a log-file and log-modules at runtime
+// doesn't persist across restarts leading to huge logfile and low disk space.
+pref("logging.config.clear_on_startup", true);
+
 // If there is ever a security firedrill that requires
 // us to block certian ports global, this is the pref
 // to use.  Is is a comma delimited list of port numbers
 // for example:
 //   pref("network.security.ports.banned", "1,2,3,4,5");
 // prevents necko connecting to ports 1-5 unless the protocol
 // overrides.
 
--- a/xpcom/base/LogModulePrefWatcher.cpp
+++ b/xpcom/base/LogModulePrefWatcher.cpp
@@ -4,47 +4,106 @@
  * 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 "LogModulePrefWatcher.h"
 
 #include "mozilla/Logging.h"
 #include "mozilla/Preferences.h"
 #include "nsString.h"
+#include "nsXULAppAPI.h"
+#include "base/process_util.h"
 
 static const char kLoggingPrefPrefix[] = "logging.";
+static const char kLoggingConfigPrefPrefix[] = "logging.config";
+static const int  kLoggingConfigPrefixLen = sizeof(kLoggingConfigPrefPrefix) - 1;
+static const char kLoggingPrefClearOnStartup[] = "logging.config.clear_on_startup";
+static const char kLoggingPrefLogFile[] = "logging.config.LOG_FILE";
+static const char kLoggingPrefAddTimestamp[] = "logging.config.add_timestamp";
+static const char kLoggingPrefSync[] = "logging.config.sync";
 
 namespace mozilla {
 
 NS_IMPL_ISUPPORTS(LogModulePrefWatcher, nsIObserver)
 
 /**
+ * Resets all the preferences in the logging. branch
+ * This is needed because we may crash while logging, and this would cause us
+ * to log after restarting as well.
+ *
+ * If logging after restart is desired, set the logging.config.clear_on_startup
+ * pref to false, or use the MOZ_LOG_FILE and MOZ_LOG_MODULES env vars.
+ */
+void ResetExistingPrefs()
+{
+  uint32_t count;
+  char** names;
+  nsresult rv = Preferences::GetRootBranch()->
+      GetChildList(kLoggingPrefPrefix, &count, &names);
+  if (NS_SUCCEEDED(rv) && count) {
+    for (size_t i = 0; i < count; i++) {
+      // Clearing the pref will cause it to reload, thus resetting the log level
+      Preferences::ClearUser(names[i]);
+    }
+    NS_FREE_XPCOM_ALLOCATED_POINTER_ARRAY(count, names);
+  }
+}
+
+/**
  * Loads the log level from the given pref and updates the corresponding
  * LogModule.
  */
-void
+static void
 LoadPrefValue(const char* aName)
 {
   LogLevel logLevel = LogLevel::Disabled;
 
+  nsresult rv;
   int32_t prefLevel = 0;
-  nsAutoCString prefStr;
+  nsAutoCString prefValue;
+
+  if (strncmp(aName, kLoggingConfigPrefPrefix, kLoggingConfigPrefixLen) == 0) {
+    nsAutoCString prefName(aName);
+
+    if (prefName.EqualsLiteral(kLoggingPrefLogFile)) {
+      rv = Preferences::GetCString(aName, &prefValue);
+      // The pref was reset. Clear the user file.
+      if (NS_FAILED(rv) || prefValue.IsEmpty()) {
+        LogModule::SetLogFile(nullptr);
+        return;
+      }
+
+      // If the pref value doesn't have a PID placeholder, append it to the end.
+      if (!strstr(prefValue.get(), "%PID")) {
+        prefValue.Append("%PID");
+      }
+
+      LogModule::SetLogFile(prefValue.BeginReading());
+    } else if (prefName.EqualsLiteral(kLoggingPrefAddTimestamp)) {
+      bool addTimestamp = Preferences::GetBool(aName, false);
+      LogModule::SetAddTimestamp(addTimestamp);
+    } else if (prefName.EqualsLiteral(kLoggingPrefSync)) {
+      bool sync = Preferences::GetBool(aName, false);
+      LogModule::SetIsSync(sync);
+    }
+    return;
+  }
 
   if (Preferences::GetInt(aName, &prefLevel) == NS_OK) {
     logLevel = ToLogLevel(prefLevel);
-  } else if (Preferences::GetCString(aName, &prefStr) == NS_OK) {
-    if (prefStr.LowerCaseEqualsLiteral("error")) {
+  } else if (Preferences::GetCString(aName, &prefValue) == NS_OK) {
+    if (prefValue.LowerCaseEqualsLiteral("error")) {
       logLevel = LogLevel::Error;
-    } else if (prefStr.LowerCaseEqualsLiteral("warning")) {
+    } else if (prefValue.LowerCaseEqualsLiteral("warning")) {
       logLevel = LogLevel::Warning;
-    } else if (prefStr.LowerCaseEqualsLiteral("info")) {
+    } else if (prefValue.LowerCaseEqualsLiteral("info")) {
       logLevel = LogLevel::Info;
-    } else if (prefStr.LowerCaseEqualsLiteral("debug")) {
+    } else if (prefValue.LowerCaseEqualsLiteral("debug")) {
       logLevel = LogLevel::Debug;
-    } else if (prefStr.LowerCaseEqualsLiteral("verbose")) {
+    } else if (prefValue.LowerCaseEqualsLiteral("verbose")) {
       logLevel = LogLevel::Verbose;
     }
   }
 
   const char* moduleName = aName + strlen(kLoggingPrefPrefix);
   LogModule::Get(moduleName)->SetLevel(logLevel);
 }
 
@@ -71,24 +130,41 @@ LogModulePrefWatcher::LogModulePrefWatch
 {
 }
 
 void
 LogModulePrefWatcher::RegisterPrefWatcher()
 {
   RefPtr<LogModulePrefWatcher> prefWatcher = new LogModulePrefWatcher();
   Preferences::AddStrongObserver(prefWatcher, kLoggingPrefPrefix);
+
+  nsCOMPtr<nsIObserverService> observerService =
+    mozilla::services::GetObserverService();
+  if (observerService && XRE_IsParentProcess()) {
+    observerService->AddObserver(prefWatcher, "browser-delayed-startup-finished", false);
+  }
+
   LoadExistingPrefs();
 }
 
 NS_IMETHODIMP
 LogModulePrefWatcher::Observe(nsISupports* aSubject, const char* aTopic,
                               const char16_t* aData)
 {
   if (strcmp(NS_PREFBRANCH_PREFCHANGE_TOPIC_ID, aTopic) == 0) {
     NS_LossyConvertUTF16toASCII prefName(aData);
     LoadPrefValue(prefName.get());
+  } else if (strcmp("browser-delayed-startup-finished", aTopic) == 0) {
+    bool clear = Preferences::GetBool(kLoggingPrefClearOnStartup, true);
+    if (clear) {
+      ResetExistingPrefs();
+    }
+    nsCOMPtr<nsIObserverService> observerService =
+      mozilla::services::GetObserverService();
+    if (observerService) {
+      observerService->RemoveObserver(this, "browser-delayed-startup-finished");
+    }
   }
 
   return NS_OK;
 }
 
 } // namespace mozilla
--- a/xpcom/base/Logging.cpp
+++ b/xpcom/base/Logging.cpp
@@ -58,25 +58,16 @@ void log_print(const LogModule* aModule,
                const char* aFmt, ...)
 {
   va_list ap;
   va_start(ap, aFmt);
   aModule->Printv(aLevel, aFmt, ap);
   va_end(ap);
 }
 
-int log_pid()
-{
-#ifdef XP_WIN
-  return _getpid();
-#else
-  return getpid();
-#endif
-}
-
 } // 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);
@@ -131,29 +122,50 @@ public:
   }
 
   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
 
 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()
   {
@@ -212,45 +224,84 @@ public:
     }
 
     const char* logFile = PR_GetEnv("MOZ_LOG_FILE");
     if (!logFile || !logFile[0]) {
       logFile = PR_GetEnv("NSPR_LOG_FILE");
     }
 
     if (logFile && logFile[0]) {
-      static const char kPIDToken[] = "%PID";
-      const char* pidTokenPtr = strstr(logFile, kPIDToken);
       char buf[2048];
-      if (pidTokenPtr &&
-          SprintfLiteral(buf, "%.*s%d%s",
-                         static_cast<int>(pidTokenPtr - logFile), logFile,
-                         detail::log_pid(),
-                         pidTokenPtr + strlen(kPIDToken)) > 0)
-      {
-        logFile = buf;
-      }
-
+      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");
+  }
+
+  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);
 
@@ -423,33 +474,60 @@ private:
   // 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 mAddTimestamp;
-  bool mIsSync;
+  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;
   }
--- a/xpcom/base/Logging.h
+++ b/xpcom/base/Logging.h
@@ -81,16 +81,39 @@ public:
    * @param aName The name of the module.
    * @return A log module for the given name. This may be shared.
    */
   static LogModule* Get(const char* aName);
 
   static void Init();
 
   /**
+   * Sets the log file to the given filename.
+   */
+  static void SetLogFile(const char* aFilename);
+
+  /**
+   * @param aBuffer - pointer to a buffer
+   * @param aLength - the length of the buffer
+   *
+   * @return the actual length of the filepath.
+   */
+  static uint32_t GetLogFile(char *aBuffer, size_t aLength);
+
+  /**
+   * @param aAddTimestamp If we should log a time stamp with every message.
+   */
+  static void SetAddTimestamp(bool aAddTimestamp);
+
+  /**
+   * @param aIsSync If we should flush the file after every logged message.
+   */
+  static void SetIsSync(bool aIsSync);
+
+  /**
    * Indicates whether or not the given log level is enabled.
    */
   bool ShouldLog(LogLevel aLevel) const { return mLevel >= aLevel; }
 
   /**
    * Retrieves the log module's current level.
    */
   LogLevel Level() const { return mLevel; }