feat: bring --enable-logging functionality in line with Chromium (#25089

)

Co-authored-by: Jeremy Rose <jeremya@chromium.org>

docs/api/command-line-switches.md

@@ -67,13 +67,22 @@ Enables caller stack logging for the following APIs (filtering events):
 
 * `desktopCapturer.getSources()` / `desktop-capturer-get-sources`
 
-### --enable-logging
+### --enable-logging[=file]
 
-Prints Chromium's logging into console.
+Prints Chromium's logging to stderr (or a log file).
 
-This switch can not be used in `app.commandLine.appendSwitch` since it is parsed
-earlier than user's app is loaded, but you can set the `ELECTRON_ENABLE_LOGGING`
-environment variable to achieve the same effect.
+The `ELECTRON_ENABLE_LOGGING` environment variable has the same effect as
+passing `--enable-logging`.
+
+Passing `--enable-logging` will result in logs being printed on stderr.
+Passing `--enable-logging=file` will result in logs being saved to the file
+specified by `--log-file=...`, or to `electron_debug.log` in the user-data
+directory if `--log-file` is not specified.
+
+> **Note:** On Windows, logs from child processes cannot be sent to stderr.
+> Logging to a file is the most reliable way to collect logs on Windows.
+
+See also `--log-file`, `--log-level`, `--v`, and `--vmodule`.
 
 ### --force-fieldtrials=`trials`
 
@@ -126,10 +135,37 @@ See the [Node.js documentation][node-cli] or run `node --help` in your terminal
 
 Set a custom locale.
 
+### --log-file=`path`
+
+If `--enable-logging` is specified, logs will be written to the given path. The
+parent directory must exist.
+
+Setting the `ELECTRON_LOG_FILE` environment variable is equivalent to passing
+this flag. If both are present, the command-line switch takes precedence.
+
 ### --log-net-log=`path`
 
 Enables net log events to be saved and writes them to `path`.
 
+### --log-level=`N`
+
+Sets the verbosity of logging when used together with `--enable-logging`.
+`N` should be one of [Chrome's LogSeverities][severities].
+
+Note that two complimentary logging mechanisms in Chromium -- `LOG()`
+and `VLOG()` -- are controlled by different switches. `--log-level`
+controls `LOG()` messages, while `--v` and `--vmodule` control `VLOG()`
+messages. So you may want to use a combination of these three switches
+depending on the granularity you want and what logging calls are made
+by the code you're trying to watch.
+
+See [Chromium Logging source][logging] for more information on how
+`LOG()` and `VLOG()` interact. Loosely speaking, `VLOG()` can be thought
+of as sub-levels / per-module levels inside `LOG(INFO)` to control the
+firehose of `LOG(INFO)` data.
+
+See also `--enable-logging`, `--log-level`, `--v`, and `--vmodule`.
+
 ### --no-proxy-server
 
 Don't use a proxy server and always make direct connections. Overrides any other
@@ -181,6 +217,8 @@ positive values are used for V-logging levels.
 
 This switch only works when `--enable-logging` is also passed.
 
+See also `--enable-logging`, `--log-level`, and `--vmodule`.
+
 ### --vmodule=`pattern`
 
 Gives the per-module maximal V-logging levels to override the value given by
@@ -193,6 +231,8 @@ logging level for all code in the source files under a `foo/bar` directory.
 
 This switch only works when `--enable-logging` is also passed.
 
+See also `--enable-logging`, `--log-level`, and `--v`.
+
 ### --force_high_performance_gpu
 
 Force using discrete GPU when there are multiple GPUs available.
@@ -240,4 +280,8 @@ By default inspector websocket url is available in stderr and under /json/list e
 [ready]: app.md#event-ready
 [play-silent-audio]: https://github.com/atom/atom/pull/9485/files
 [debugging-main-process]: ../tutorial/debugging-main-process.md
+[logging]: https://source.chromium.org/chromium/chromium/src/+/master:base/logging.h
 [node-cli]: https://nodejs.org/api/cli.html
+[play-silent-audio]: https://github.com/atom/atom/pull/9485/files
+[ready]: app.md#event-ready
+[severities]: https://source.chromium.org/chromium/chromium/src/+/master:base/logging.h?q=logging::LogSeverity&ss=chromium

docs/api/environment-variables.md

@@ -118,7 +118,19 @@ debugging purposes.
 
 ### `ELECTRON_ENABLE_LOGGING`
 
-Prints Chrome's internal logging to the console.
+Prints Chromium's internal logging to the console.
+
+Setting this variable is the same as passing `--enable-logging`
+on the command line. For more info, see `--enable-logging` in [command-line
+switches](./command-line-switches.md#enable-loggingfile).
+
+### `ELECTRON_LOG_FILE`
+
+Sets the file destination for Chromium's internal logging.
+
+Setting this variable is the same as passing `--log-file`
+on the command line. For more info, see `--log-file` in [command-line
+switches](./command-line-switches.md#log-filepath).
 
 ### `ELECTRON_DEBUG_DRAG_REGIONS`
 
@@ -127,7 +139,8 @@ green and non-draggable regions will be colored red to aid debugging.
 
 ### `ELECTRON_DEBUG_NOTIFICATIONS`
 
-Adds extra logs to [`Notification`](./notification.md) lifecycles on macOS to aid in debugging. Extra logging will be displayed when new Notifications are created or activated. They will also be displayed when common actions are taken: a notification is shown, dismissed, its button is clicked, or it is replied to.
+Adds extra logs to [`Notification`](./notification.md) lifecycles on macOS to aid in debugging. Extra logging will be displayed when new Notifications are created or activated. They will also be displayed when common a
+tions are taken: a notification is shown, dismissed, its button is clicked, or it is replied to.
 
 Sample output:
 

docs/tutorial/application-debugging.md

@@ -45,4 +45,4 @@ If the V8 context crashes, the DevTools will display this message.
 
 Chromium logs can be enabled via the `ELECTRON_ENABLE_LOGGING` environment variable. For more information, see the [environment variables documentation](../api/environment-variables.md#electron_enable_logging).
 
-Alternatively, the command line argument `--enable-logging` can be passed. More information is available in the [command line switches documentation](../api/command-line-switches.md#--enable-logging).
+Alternatively, the command line argument `--enable-logging` can be passed. More information is available in the [command line switches documentation](../api/command-line-switches.md#--enable-loggingfile).

filenames.gni

@@ -510,6 +510,7 @@ filenames = {
     "shell/common/api/electron_api_native_image.cc",
     "shell/common/api/electron_api_native_image.h",
     "shell/common/api/electron_api_shell.cc",
+    "shell/common/api/electron_api_testing.cc",
     "shell/common/api/electron_api_v8_util.cc",
     "shell/common/api/electron_bindings.cc",
     "shell/common/api/electron_bindings.h",
@@ -604,6 +605,8 @@ filenames = {
     "shell/common/keyboard_util.cc",
     "shell/common/keyboard_util.h",
     "shell/common/language_util.h",
+    "shell/common/logging.cc",
+    "shell/common/logging.h",
     "shell/common/mouse_util.cc",
     "shell/common/mouse_util.h",
     "shell/common/node_bindings.cc",

shell/app/electron_main_delegate.cc

@@ -32,6 +32,7 @@
 #include "shell/browser/relauncher.h"
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
+#include "shell/common/logging.h"
 #include "shell/common/options_switches.h"
 #include "shell/common/platform_util.h"
 #include "shell/renderer/electron_renderer_client.h"
@@ -71,6 +72,10 @@ namespace {
 
 const char* kRelauncherProcess = "relauncher";
 
+constexpr base::StringPiece kElectronDisableSandbox("ELECTRON_DISABLE_SANDBOX");
+constexpr base::StringPiece kElectronEnableStackDumping(
+    "ELECTRON_ENABLE_STACK_DUMPING");
+
 bool IsBrowserProcess(base::CommandLine* cmd) {
   std::string process_type = cmd->GetSwitchValueASCII(::switches::kProcessType);
   return process_type.empty();
@@ -236,51 +241,23 @@ const size_t ElectronMainDelegate::kNonWildcardDomainNonPortSchemesSize =
 bool ElectronMainDelegate::BasicStartupComplete(int* exit_code) {
   auto* command_line = base::CommandLine::ForCurrentProcess();
 
-  logging::LoggingSettings settings;
 #if defined(OS_WIN)
   v8_crashpad_support::SetUp();
 
   // On Windows the terminal returns immediately, so we add a new line to
   // prevent output in the same line as the prompt.
   if (IsBrowserProcess(command_line))
     std::wcout << std::endl;
-#if defined(DEBUG)
-  // Print logging to debug.log on Windows
-  settings.logging_dest = logging::LOG_TO_ALL;
-  base::FilePath log_filename;
-  base::PathService::Get(base::DIR_EXE, &log_filename);
-  log_filename = log_filename.AppendASCII("debug.log");
-  settings.log_file_path = log_filename.value().c_str();
-  settings.lock_log = logging::LOCK_LOG_FILE;
-  settings.delete_old = logging::DELETE_OLD_LOG_FILE;
-#else
-  settings.logging_dest =
-      logging::LOG_TO_SYSTEM_DEBUG_LOG | logging::LOG_TO_STDERR;
-#endif  // defined(DEBUG)
-#else   // defined(OS_WIN)
-  settings.logging_dest =
-      logging::LOG_TO_SYSTEM_DEBUG_LOG | logging::LOG_TO_STDERR;
 #endif  // !defined(OS_WIN)
 
-  // Only enable logging when --enable-logging is specified.
   auto env = base::Environment::Create();
-  if (!command_line->HasSwitch(::switches::kEnableLogging) &&
-      !env->HasVar("ELECTRON_ENABLE_LOGGING")) {
-    settings.logging_dest = logging::LOG_NONE;
-    logging::SetMinLogLevel(logging::LOGGING_NUM_SEVERITIES);
-  }
-
-  logging::InitLogging(settings);
-
-  // Logging with pid and timestamp.
-  logging::SetLogItems(true, false, true, false);
 
   // Enable convenient stack printing. This is enabled by default in
   // non-official builds.
-  if (env->HasVar("ELECTRON_ENABLE_STACK_DUMPING"))
+  if (env->HasVar(kElectronEnableStackDumping))
     base::debug::EnableInProcessStackDumping();
 
-  if (env->HasVar("ELECTRON_DISABLE_SANDBOX"))
+  if (env->HasVar(kElectronDisableSandbox))
     command_line->AppendSwitch(sandbox::policy::switches::kNoSandbox);
 
   tracing_sampler_profiler_ =
@@ -353,6 +330,19 @@ void ElectronMainDelegate::PreSandboxStartup() {
                                                  user_data_dir, false, true);
   }
 
+#if !defined(OS_WIN)
+  // For windows we call InitLogging later, after the sandbox is initialized.
+  //
+  // On Linux, we force a "preinit" in the zygote (i.e. never log to a default
+  // log file), because the zygote is booted prior to JS running, so it can't
+  // know the correct user-data directory. (And, further, accessing the
+  // application name on Linux can cause glib calls that end up spawning
+  // threads, which if done before the zygote is booted, causes a CHECK().)
+  logging::InitElectronLogging(*command_line,
+                               /* is_preinit = */ process_type.empty() ||
+                                   process_type == ::switches::kZygoteProcess);
+#endif
+
 #if !defined(MAS_BUILD)
   crash_reporter::InitializeCrashKeys();
 #endif
@@ -400,6 +390,13 @@ void ElectronMainDelegate::PreSandboxStartup() {
   }
 }
 
+void ElectronMainDelegate::SandboxInitialized(const std::string& process_type) {
+#if defined(OS_WIN)
+  logging::InitElectronLogging(*base::CommandLine::ForCurrentProcess(),
+                               /* is_preinit = */ process_type.empty());
+#endif
+}
+
 void ElectronMainDelegate::PreBrowserMain() {
   // This is initialized early because the service manager reads some feature
   // flags and we need to make sure the feature list is initialized before the

shell/app/electron_main_delegate.h

@@ -30,6 +30,7 @@ class ElectronMainDelegate : public content::ContentMainDelegate {
   // content::ContentMainDelegate:
   bool BasicStartupComplete(int* exit_code) override;
   void PreSandboxStartup() override;
+  void SandboxInitialized(const std::string& process_type) override;
   void PreBrowserMain() override;
   content::ContentBrowserClient* CreateContentBrowserClient() override;
   content::ContentGpuClient* CreateContentGpuClient() override;

shell/browser/electron_browser_client.cc

@@ -100,6 +100,7 @@
 #include "shell/common/api/api.mojom.h"
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
+#include "shell/common/logging.h"
 #include "shell/common/options_switches.h"
 #include "shell/common/platform_util.h"
 #include "third_party/blink/public/common/loader/url_loader_throttle.h"
@@ -542,6 +543,15 @@ void ElectronBrowserClient::AppendExtraCommandLineSwitches(
   }
 #endif
 
+  // The zygote process is booted before JS runs, so DIR_USER_DATA isn't usable
+  // at that time. It doesn't need --user-data-dir to be correct anyway, since
+  // the zygote itself doesn't access anything in that directory.
+  if (process_type != ::switches::kZygoteProcess) {
+    base::FilePath user_data_dir;
+    if (base::PathService::Get(chrome::DIR_USER_DATA, &user_data_dir))
+      command_line->AppendSwitchPath(::switches::kUserDataDir, user_data_dir);
+  }
+
   if (process_type == ::switches::kUtilityProcess ||
       process_type == ::switches::kRendererProcess) {
     // Copy following switches to child process.
@@ -794,6 +804,11 @@ bool ElectronBrowserClient::ArePersistentMediaDeviceIDsAllowed(
   return true;
 }
 
+base::FilePath ElectronBrowserClient::GetLoggingFileName(
+    const base::CommandLine& cmd_line) {
+  return logging::GetLogFileName(cmd_line);
+}
+
 void ElectronBrowserClient::SiteInstanceDeleting(
     content::SiteInstance* site_instance) {
 #if BUILDFLAG(ENABLE_ELECTRON_EXTENSIONS)

shell/browser/electron_browser_client.h

@@ -263,6 +263,7 @@ class ElectronBrowserClient : public content::ContentBrowserClient,
       const GURL& scope,
       const GURL& site_for_cookies,
       const absl::optional<url::Origin>& top_frame_origin) override;
+  base::FilePath GetLoggingFileName(const base::CommandLine& cmd_line) override;
 
   // content::RenderProcessHostObserver:
   void RenderProcessHostDestroyed(content::RenderProcessHost* host) override;

shell/browser/electron_browser_context.cc

@@ -9,6 +9,7 @@
 #include <utility>
 
 #include "base/barrier_closure.h"
+#include "base/base_paths.h"
 #include "base/command_line.h"
 #include "base/files/file_path.h"
 #include "base/no_destructor.h"

shell/browser/electron_browser_main_parts.cc

@@ -45,6 +45,7 @@
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
 #include "shell/common/gin_helper/trackable_object.h"
+#include "shell/common/logging.h"
 #include "shell/common/node_bindings.h"
 #include "shell/common/node_includes.h"
 #include "third_party/abseil-cpp/absl/types/optional.h"
@@ -269,6 +270,11 @@ void ElectronBrowserMainParts::PostEarlyInitialization() {
   // Initialize field trials.
   InitializeFieldTrials();
 
+  // Reinitialize logging now that the app has had a chance to set the app name
+  // and/or user data directory.
+  logging::InitElectronLogging(*base::CommandLine::ForCurrentProcess(),
+                               /* is_preinit = */ false);
+
   // Initialize after user script environment creation.
   fake_browser_process_->PostEarlyInitialization();
 }

shell/common/api/electron_api_testing.cc

@@ -0,0 +1,48 @@
+// Copyright (c) 2021 Slack Technologies, Inc.
+// Use of this source code is governed by the MIT license that can be
+// found in the LICENSE file.
+
+#include "base/dcheck_is_on.h"
+#include "base/logging.h"
+#include "shell/common/gin_helper/dictionary.h"
+#include "shell/common/node_includes.h"
+#include "v8/include/v8.h"
+
+#if DCHECK_IS_ON()
+namespace {
+
+void Log(int severity, std::string text) {
+  switch (severity) {
+    case logging::LOGGING_VERBOSE:
+      VLOG(1) << text;
+      break;
+    case logging::LOGGING_INFO:
+      LOG(INFO) << text;
+      break;
+    case logging::LOGGING_WARNING:
+      LOG(WARNING) << text;
+      break;
+    case logging::LOGGING_ERROR:
+      LOG(ERROR) << text;
+      break;
+    case logging::LOGGING_FATAL:
+      LOG(FATAL) << text;
+      break;
+    default:
+      LOG(ERROR) << "Unrecognized severity: " << severity;
+      break;
+  }
+}
+
+void Initialize(v8::Local<v8::Object> exports,
+                v8::Local<v8::Value> unused,
+                v8::Local<v8::Context> context,
+                void* priv) {
+  gin_helper::Dictionary dict(context->GetIsolate(), exports);
+  dict.SetMethod("log", &Log);
+}
+
+}  // namespace
+
+NODE_LINKED_MODULE_CONTEXT_AWARE(electron_common_testing, Initialize)
+#endif