base: Add optional prefix to log lines

When working on out-of-process mojo services it is hard to figure out
which log line comes from which process. Often both the browser process
and the remote process are running shared components (e.g. code in
//ui/views in both out-of-process ash and browser process). Trying to
back-correlate pids with process types is really awkward.

Add a optional prefix to the start of log lines so things look like:
[my_process:80672:80672:0730/151208.285440:ERROR:file.cc(2982)]...

Only add the prefix to new mojo service processes because it's
possible there are consumers of existing browser process logging
and I don't want change the format of existing browser or renderer
logs.

Bug: 869181
Test: added to base_unittests
Change-Id: Ia26a78d69c19e1f5cbf8ecd269e962ad0589d008
Reviewed-on: https://chromium-review.googlesource.com/1156988Reviewed-by: kylechar <kylechar@chromium.org>
Reviewed-by: Scott Violet <sky@chromium.org>
Commit-Queue: James Cook <jamescook@chromium.org>
Cr-Commit-Position: refs/heads/master@{#579918}

base/logging.cc

@@ -149,6 +149,7 @@ bool g_log_process_id = false;
 bool g_log_thread_id = false;
 bool g_log_timestamp = true;
 bool g_log_tickcount = false;
+const char* g_log_prefix = nullptr;
 
 // Should we pop up fatal debug messages in a dialog?
 bool show_error_dialogs = false;
@@ -489,6 +490,12 @@ void SetLogItems(bool enable_process_id, bool enable_thread_id,
   g_log_tickcount = enable_tickcount;
 }
 
+void SetLogPrefix(const char* prefix) {
+  DCHECK(!prefix ||
+         base::ContainsOnlyChars(prefix, "abcdefghijklmnopqrstuvwxyz"));
+  g_log_prefix = prefix;
+}
+
 void SetShowErrorDialogs(bool enable_dialogs) {
   show_error_dialogs = enable_dialogs;
 }
@@ -871,6 +878,8 @@ void LogMessage::Init(const char* file, int line) {
   // TODO(darin): It might be nice if the columns were fixed width.
 
   stream_ <<  '[';
+  if (g_log_prefix)
+    stream_ << g_log_prefix << ':';
   if (g_log_process_id)
     stream_ << CurrentProcessId() << ':';
   if (g_log_thread_id)

base/logging.h

@@ -268,6 +268,12 @@ int GetVlogLevel(const char (&file)[N]) {
 BASE_EXPORT void SetLogItems(bool enable_process_id, bool enable_thread_id,
                              bool enable_timestamp, bool enable_tickcount);
 
+// Sets an optional prefix to add to each log message. |prefix| is not copied
+// and should be a raw string constant. |prefix| must only contain ASCII letters
+// to avoid confusion with PIDs and timestamps. Pass null to remove the prefix.
+// Logging defaults to no prefix.
+BASE_EXPORT void SetLogPrefix(const char* prefix);
+
 // Sets whether or not you'd like to see fatal debug messages popped up in
 // a dialog box or not.
 // Dialogs are not shown by default.

base/logging_unittest.cc

@@ -799,6 +799,36 @@ TEST_F(LoggingTest, FuchsiaLogging) {
 }
 #endif  // defined(OS_FUCHSIA)
 
+TEST_F(LoggingTest, LogPrefix) {
+  // Set up a callback function to capture the log output string.
+  auto old_log_message_handler = GetLogMessageHandler();
+  // Use a static because only captureless lambdas can be converted to a
+  // function pointer for SetLogMessageHandler().
+  static std::string* log_string_ptr = nullptr;
+  std::string log_string;
+  log_string_ptr = &log_string;
+  SetLogMessageHandler([](int severity, const char* file, int line,
+                          size_t start, const std::string& str) -> bool {
+    *log_string_ptr = str;
+    return true;
+  });
+
+  // Logging with a prefix includes the prefix string after the opening '['.
+  const char kPrefix[] = "prefix";
+  SetLogPrefix(kPrefix);
+  LOG(ERROR) << "test";  // Writes into |log_string|.
+  EXPECT_EQ(1u, log_string.find(kPrefix));
+
+  // Logging without a prefix does not include the prefix string.
+  SetLogPrefix(nullptr);
+  LOG(ERROR) << "test";  // Writes into |log_string|.
+  EXPECT_EQ(std::string::npos, log_string.find(kPrefix));
+
+  // Clean up.
+  SetLogMessageHandler(old_log_message_handler);
+  log_string_ptr = nullptr;
+}
+
 }  // namespace
 
 }  // namespace logging

chrome/utility/mash_service_factory.cc

@@ -16,6 +16,7 @@
 #include "ash/components/tap_visualizer/tap_visualizer_app.h"
 #include "ash/public/interfaces/constants.mojom.h"
 #include "base/bind.h"
+#include "base/logging.h"
 #include "base/metrics/histogram_macros.h"
 #include "build/build_config.h"
 
@@ -53,27 +54,33 @@ void RecordMashServiceLaunch(MashService service) {
 
 std::unique_ptr<service_manager::Service> CreateAshService() {
   RecordMashServiceLaunch(MashService::kAsh);
+  logging::SetLogPrefix("ash");
   return std::make_unique<ash::AshService>();
 }
 
 std::unique_ptr<service_manager::Service> CreateAutoclickApp() {
   RecordMashServiceLaunch(MashService::kAutoclick);
+  // Use an abbreviation of the service name to keep log lines shorter.
+  logging::SetLogPrefix("autoclick");
   return std::make_unique<autoclick::AutoclickApplication>();
 }
 
 std::unique_ptr<service_manager::Service> CreateQuickLaunchApp() {
   RecordMashServiceLaunch(MashService::kQuickLaunch);
+  logging::SetLogPrefix("quick");
   return std::make_unique<quick_launch::QuickLaunchApplication>();
 }
 
 std::unique_ptr<service_manager::Service> CreateShortcutViewerApp() {
   RecordMashServiceLaunch(MashService::kShortcutViewer);
+  logging::SetLogPrefix("shortcut");
   return std::make_unique<
       keyboard_shortcut_viewer::ShortcutViewerApplication>();
 }
 
 std::unique_ptr<service_manager::Service> CreateTapVisualizerApp() {
   RecordMashServiceLaunch(MashService::kTapVisualizer);
+  logging::SetLogPrefix("tap");
   return std::make_unique<tap_visualizer::TapVisualizerApp>();
 }