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 314404 d6809e466fe6c6cdeebeebe8878ee0d03e59d4f6
parent 314403 945544b11e381c00753eb64e6c79196d7609033e
child 314406 80a9c7007243ac4e931a8c4352723cbf840aff03
child 314436 9b792ae11734c602485896031a6d3400a3f603b3
push id20571
push userkwierso@gmail.com
push dateMon, 19 Sep 2016 22:56:59 +0000
treeherderfx-team@671c2af548b2 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersnfroyd
bugs1239686
milestone51.0a1
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; }