[fuchsia] Implement fuchsia.web.Frame.SetConsoleLogSink() API.

Migrate console logging from content hosted by a FrameImpl to use
per-Frame fx_loggers, rather than the //base LOG() macros.  Log messages
are tagged with the |debug_name| specified when the Frame was created,
if any.

Implement a SetConsoleLogSink() API to allow callers to redirect logging
on a per-Frame basis.

Bug: 1088094, 1051533, 1139396
Change-Id: I7c4d6b55fa34ba6e8a343d5830c91594eedcca7e
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2517534
Commit-Queue: Wez <wez@chromium.org>
Reviewed-by: David Dorwin <ddorwin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#836072}

base/fuchsia/scoped_fx_logger.cc

@@ -5,19 +5,28 @@
 #include "base/fuchsia/scoped_fx_logger.h"
 
 #include "base/fuchsia/fuchsia_logging.h"
+#include "base/strings/string_piece.h"
 
 namespace base {
 
 ScopedFxLogger CreateFxLoggerFromLogSink(
     fuchsia::logger::LogSinkHandle log_sink) {
+  return CreateFxLoggerFromLogSinkWithTag(std::move(log_sink), {});
+}
+
+ScopedFxLogger CreateFxLoggerFromLogSinkWithTag(
+    fuchsia::logger::LogSinkHandle log_sink,
+    base::StringPiece tag) {
+  std::string tag_string = tag.as_string();
+  const char* tag_c_string = tag_string.c_str();
+
   fx_logger_config_t config = {
       // Selecting based on log level is handled outside the fx_logger.
       .min_severity = FX_LOG_ALL,
       .console_fd = -1,
       .log_sink_channel = log_sink.TakeChannel().release(),
-      // Do not set any custom tags.
-      .tags = nullptr,
-      .num_tags = 0,
+      .tags = tag.empty() ? nullptr : &tag_c_string,
+      .num_tags = tag.empty() ? 0 : 1,
   };
 
   fx_logger_t* fx_logger = nullptr;

base/fuchsia/scoped_fx_logger.h

@@ -11,6 +11,7 @@
 #include <memory>
 
 #include "base/base_export.h"
+#include "base/strings/string_piece_forward.h"
 
 namespace base {
 
@@ -24,12 +25,17 @@ struct FxLoggerDeleter {
 
 using ScopedFxLogger = std::unique_ptr<fx_logger_t, internal::FxLoggerDeleter>;
 
-// Creates a new logger connected to the specified |log_sink| service.
-// The logger is configured to log all severities of message, and has no
-// custom tags set.
+// Returns a new logger connected to the specified |log_sink| service.
+// The logger is initially configured to log all severities of message.
 // Returns null if creation of the new logger fails.
 BASE_EXPORT ScopedFxLogger
-CreateFxLoggerFromLogSink(fuchsia::logger::LogSinkHandle log_sink);
+CreateFxLoggerFromLogSink(::fuchsia::logger::LogSinkHandle log_sink);
+
+// Similar to CreateFxLoggerFromLogSink(), but returns a logger which annotates
+// messages with the specified |tag|, if non-empty.
+BASE_EXPORT ScopedFxLogger
+CreateFxLoggerFromLogSinkWithTag(::fuchsia::logger::LogSinkHandle log_sink,
+                                 base::StringPiece tag);
 
 }  // namespace base
 

base/fuchsia/test_log_listener_safe.cc

@@ -93,6 +93,7 @@ SimpleTestLogListener::RunUntilMessageReceived(
 
 void SimpleTestLogListener::PushLoggedMessage(
     const fuchsia::logger::LogMessage& message) {
+  DVLOG(1) << "TestLogListener received: " << message.msg;
   if (on_log_message_) {
     DCHECK(logged_messages_.empty());
     on_log_message_.Run(message);

fuchsia/engine/browser/frame_impl.cc

@@ -61,12 +61,6 @@
 
 namespace {
 
-// logging::LogSeverity does not define a value to disable logging; define one.
-// Since this value is used to determine whether incoming log severity is above
-// a threshold, set the value much higher than logging::LOG_ERROR.
-const logging::LogSeverity kLogSeverityUnreachable =
-    std::numeric_limits<logging::LogSeverity>::max();
-
 // Simulated screen bounds to use when headless rendering is enabled.
 constexpr gfx::Size kHeadlessWindowSize = {1, 1};
 
@@ -124,24 +118,46 @@ bool IsUrlMatchedByOriginList(const GURL& url,
   return false;
 }
 
-logging::LogSeverity ConsoleLogLevelToLoggingSeverity(
+fx_log_severity_t FuchsiaWebConsoleLogLevelToFxLogSeverity(
     fuchsia::web::ConsoleLogLevel level) {
   switch (level) {
-    case fuchsia::web::ConsoleLogLevel::NONE:
-      return kLogSeverityUnreachable;
     case fuchsia::web::ConsoleLogLevel::DEBUG:
-      return logging::LOG_VERBOSE;
+      return FX_LOG_DEBUG;
     case fuchsia::web::ConsoleLogLevel::INFO:
-      return logging::LOG_INFO;
+      return FX_LOG_INFO;
     case fuchsia::web::ConsoleLogLevel::WARN:
-      return logging::LOG_WARNING;
+      return FX_LOG_WARNING;
     case fuchsia::web::ConsoleLogLevel::ERROR:
-      return logging::LOG_ERROR;
+      return FX_LOG_ERROR;
+    case fuchsia::web::ConsoleLogLevel::NONE:
+      return FX_LOG_NONE;
+    default:
+      // Cope gracefully with callers setting undefined levels.
+      DLOG(ERROR) << "Unknown log level:"
+                  << static_cast<std::underlying_type<decltype(level)>::type>(
+                         level);
+      return FX_LOG_NONE;
   }
-  NOTREACHED()
-      << "Unknown log level: "
-      << static_cast<std::underlying_type<fuchsia::web::ConsoleLogLevel>::type>(
+}
+
+fx_log_severity_t BlinkConsoleMessageLevelToFxLogSeverity(
+    blink::mojom::ConsoleMessageLevel level) {
+  switch (level) {
+    case blink::mojom::ConsoleMessageLevel::kVerbose:
+      return FX_LOG_DEBUG;
+    case blink::mojom::ConsoleMessageLevel::kInfo:
+      return FX_LOG_INFO;
+    case blink::mojom::ConsoleMessageLevel::kWarning:
+      return FX_LOG_WARNING;
+    case blink::mojom::ConsoleMessageLevel::kError:
+      return FX_LOG_ERROR;
+  }
+
+  // Cope gracefully with callers setting undefined levels.
+  DLOG(ERROR) << "Unknown log level:"
+              << static_cast<std::underlying_type<decltype(level)>::type>(
                      level);
+  return FX_LOG_NONE;
 }
 
 bool IsHeadless() {
@@ -245,13 +261,15 @@ FrameImpl* FrameImpl::FromRenderFrameHost(
 
 FrameImpl::FrameImpl(std::unique_ptr<content::WebContents> web_contents,
                      ContextImpl* context,
-                     fuchsia::web::CreateFrameParams params_for_popups,
+                     fuchsia::web::CreateFrameParams params,
                      fidl::InterfaceRequest<fuchsia::web::Frame> frame_request)
     : web_contents_(std::move(web_contents)),
       context_(context),
-      params_for_popups_(std::move(params_for_popups)),
+      console_log_tag_(params.has_debug_name()
+                           ? params.debug_name()
+                           : std::string()),
+      params_for_popups_(std::move(params)),
       navigation_controller_(web_contents_.get()),
-      log_level_(kLogSeverityUnreachable),
       url_request_rewrite_rules_manager_(web_contents_.get()),
       binding_(this, std::move(frame_request)),
       media_blocker_(web_contents_.get()),
@@ -751,7 +769,16 @@ void FrameImpl::SetNavigationEventListener(
 }
 
 void FrameImpl::SetJavaScriptLogLevel(fuchsia::web::ConsoleLogLevel level) {
-  log_level_ = ConsoleLogLevelToLoggingSeverity(level);
+  log_level_ = FuchsiaWebConsoleLogLevelToFxLogSeverity(level);
+}
+
+void FrameImpl::SetConsoleLogSink(fuchsia::logger::LogSinkHandle sink) {
+  if (sink) {
+    console_logger_ = base::CreateFxLoggerFromLogSinkWithTag(std::move(sink),
+                                                             console_log_tag_);
+  } else {
+    console_logger_ = nullptr;
+  }
 }
 
 void FrameImpl::ConfigureInputTypes(fuchsia::web::InputTypes types,
@@ -981,39 +1008,29 @@ bool FrameImpl::DidAddMessageToConsole(
     const base::string16& message,
     int32_t line_no,
     const base::string16& source_id) {
-  logging::LogSeverity log_severity =
-      blink::ConsoleMessageLevelToLogSeverity(log_level);
-  if (log_level_ > log_severity) {
+  fx_log_severity_t severity =
+      BlinkConsoleMessageLevelToFxLogSeverity(log_level);
+  if (severity < log_level_) {
     // Prevent the default logging mechanism from logging the message.
     return true;
   }
 
+  if (!console_logger_) {
+    // Log via the process' LogSink service if none was set on the Frame.
+    // Connect on-demand, so that embedders need not provide a LogSink in the
+    // CreateContextParams services, unless they actually enable logging.
+    console_logger_ = base::CreateFxLoggerFromLogSinkWithTag(
+        base::ComponentContextForProcess()
+            ->svc()
+            ->Connect<fuchsia::logger::LogSink>(),
+        console_log_tag_);
+  }
+
   std::string formatted_message =
       base::StringPrintf("%s:%d : %s", base::UTF16ToUTF8(source_id).data(),
                          line_no, base::UTF16ToUTF8(message).data());
-  switch (log_level) {
-    case blink::mojom::ConsoleMessageLevel::kVerbose:
-      // TODO(crbug.com/1139396): Use a more verbose value than INFO once using
-      // fx_logger directly. LOG() does not support VERBOSE.
-      LOG(INFO) << "debug:" << formatted_message;
-      break;
-    case blink::mojom::ConsoleMessageLevel::kInfo:
-      LOG(INFO) << "info:" << formatted_message;
-      break;
-    case blink::mojom::ConsoleMessageLevel::kWarning:
-      LOG(WARNING) << "warn:" << formatted_message;
-      break;
-    case blink::mojom::ConsoleMessageLevel::kError:
-      LOG(ERROR) << "error:" << formatted_message;
-      break;
-    default:
-      // TODO(crbug.com/1139396): Eliminate this case via refactoring. All
-      // values are handled above.
-      DLOG(WARNING) << "Unknown log level: " << log_severity;
-      // Let the default logging mechanism handle the message.
-      return false;
-  }
-
+  fx_logger_log(console_logger_.get(), severity, nullptr,
+                formatted_message.data());
   return true;
 }
 

fuchsia/engine/browser/frame_impl.h

@@ -5,8 +5,10 @@
 #ifndef FUCHSIA_ENGINE_BROWSER_FRAME_IMPL_H_
 #define FUCHSIA_ENGINE_BROWSER_FRAME_IMPL_H_
 
+#include <fuchsia/logger/cpp/fidl.h>
 #include <fuchsia/web/cpp/fidl.h>
 #include <lib/fidl/cpp/binding_set.h>
+#include <lib/syslog/logger.h>
 #include <lib/ui/scenic/cpp/view_ref_pair.h>
 #include <lib/zx/channel.h>
 
@@ -17,6 +19,7 @@
 #include <utility>
 #include <vector>
 
+#include "base/fuchsia/scoped_fx_logger.h"
 #include "base/macros.h"
 #include "base/memory/read_only_shared_memory_region.h"
 #include "base/optional.h"
@@ -59,11 +62,13 @@ class FrameImpl : public fuchsia::web::Frame,
   static FrameImpl* FromRenderFrameHost(
       content::RenderFrameHost* render_frame_host);
 
-  // |params_for_popups| is saved and applied to popups created by content
-  // running in this Frame.
+  // |context| must out-live |this|.
+  // |params| apply both to this Frame, and also to any popup Frames it creates.
+  // DestroyFrame() is automatically called on |context| if the |frame_request|
+  // channel disconnects.
   FrameImpl(std::unique_ptr<content::WebContents> web_contents,
             ContextImpl* context,
-            fuchsia::web::CreateFrameParams params_for_popups,
+            fuchsia::web::CreateFrameParams params,
             fidl::InterfaceRequest<fuchsia::web::Frame> frame_request);
   ~FrameImpl() override;
 
@@ -187,6 +192,7 @@ class FrameImpl : public fuchsia::web::Frame,
       fidl::InterfaceHandle<fuchsia::web::NavigationEventListener> listener)
       override;
   void SetJavaScriptLogLevel(fuchsia::web::ConsoleLogLevel level) override;
+  void SetConsoleLogSink(fuchsia::logger::LogSinkHandle sink) override;
   void ConfigureInputTypes(fuchsia::web::InputTypes types,
                            fuchsia::web::AllowInputState allow) override;
   void SetPopupFrameCreationListener(
@@ -267,6 +273,13 @@ class FrameImpl : public fuchsia::web::Frame,
   const std::unique_ptr<content::WebContents> web_contents_;
   ContextImpl* const context_;
 
+  // Optional tag to apply when emitting web console logs.
+  const std::string console_log_tag_;
+
+  // Logger used for console messages from content, depending on |log_level_|.
+  base::ScopedFxLogger console_logger_;
+  fx_log_severity_t log_level_ = FX_LOG_NONE;
+
   // Parameters applied to popups created by content running in this Frame.
   const fuchsia::web::CreateFrameParams params_for_popups_;
 
@@ -283,7 +296,6 @@ class FrameImpl : public fuchsia::web::Frame,
 
   EventFilter event_filter_;
   NavigationControllerImpl navigation_controller_;
-  logging::LogSeverity log_level_;
   UrlRequestRewriteRulesManager url_request_rewrite_rules_manager_;
   FramePermissionController permission_controller_;
   std::unique_ptr<NavigationPolicyHandler> navigation_policy_handler_;

fuchsia/engine/web_engine_integration_logging_test.cc

@@ -17,31 +17,24 @@
 
 namespace {
 
-// Name of the console logging test page. This is also used as the expected
-// message text, since console log messages include the name of the originating
-// file.
+// Name of the console logging test page.
 constexpr char kLogTestPageFileName[] = "console_logging.html";
+constexpr char kLogTestPageDebugMessage[] = "This is a debug() message.";
 
-constexpr char kWebEngineLogTag[] = "web_engine_exe";
+// Debug name to create Frames with, to use as their logging tag.
+constexpr char kFrameLogTag[] = "Test🖼🪵";
 
-constexpr char kNormalizedLineNumber[] = "12345";
 constexpr char kNormalizedPortNumber[] = "678";
 
 // Replaces the line number in frame_impl.cc with kNormalizedLineNumber and
 // the port with kNormalizedPortNumber to enable reliable comparison of
 // console log messages.
 std::string NormalizeConsoleLogMessage(base::StringPiece original) {
-  size_t line_number_begin = original.find("(") + 1;
-  size_t close_parenthesis = original.find(")", line_number_begin);
-  std::string normalized = original.as_string().replace(
-      line_number_begin, close_parenthesis - line_number_begin,
-      kNormalizedLineNumber);
-
   const char kSchemePortColon[] = "http://127.0.0.1:";
   size_t port_begin =
-      normalized.find(kSchemePortColon) + strlen(kSchemePortColon);
-  size_t path_begin = normalized.find("/", port_begin);
-  return normalized.replace(port_begin, path_begin - port_begin,
+      original.find(kSchemePortColon) + strlen(kSchemePortColon);
+  size_t path_begin = original.find("/", port_begin);
+  return original.as_string().replace(port_begin, path_begin - port_begin,
                                       kNormalizedPortNumber);
 }
 
@@ -135,30 +128,42 @@ class WebEngineIntegrationLoggingTest : public WebEngineIntegrationTestBase {
 // Verifies that calling messages from console.debug() calls go to the Fuchsia
 // system log when the script log level is set to DEBUG.
 TEST_F(WebEngineIntegrationLoggingTest, SetJavaScriptLogLevel_DEBUG) {
-  auto options = std::make_unique<fuchsia::logger::LogFilterOptions>();
-  options->tags = {kWebEngineLogTag};
   base::SimpleTestLogListener log_listener;
-  log_listener.ListenToLog(logger_.get(), std::move(options));
+  log_listener.ListenToLog(logger_.get(), nullptr);
 
   // Create the Context & Frame with all log severities enabled.
-  CreateContextAndFrame(ContextParamsWithIsolatedLogSink());
+  fuchsia::web::CreateFrameParams frame_params;
+  frame_params.set_debug_name(kFrameLogTag);
+  CreateContextAndFrameWithParams(ContextParamsWithIsolatedLogSink(),
+                                  std::move(frame_params));
   frame_->SetJavaScriptLogLevel(fuchsia::web::ConsoleLogLevel::DEBUG);
 
+  // Re-connect to the NavigationController, to ensure that the new log level
+  // has been applied before the LoadUrl() request is processed.
+  navigation_controller_ = nullptr;
+  navigation_listener_ = nullptr;
+  AddNavigationControllerAndListenerToFrame(&frame_);
+
+  // Navigate to the test page, which will emit console logging.
   LoadLogTestPage();
   navigation_listener_->RunUntilTitleEquals("ended");
 
-  // Run until a message containing kLogTestPageFileName is received.
+  // Run until the message passed to console.debug() is received.
   base::Optional<fuchsia::logger::LogMessage> logged_message =
-      log_listener.RunUntilMessageReceived(kLogTestPageFileName);
+      log_listener.RunUntilMessageReceived(kLogTestPageDebugMessage);
 
   ASSERT_TRUE(logged_message.has_value());
+
+  // console.debug() should map to Fuchsia's DEBUG log severity.
   EXPECT_EQ(logged_message->severity,
-            static_cast<int32_t>(fuchsia::logger::LogLevelFilter::INFO));
-  ASSERT_EQ(logged_message->tags.size(), 1u);
-  EXPECT_EQ(logged_message->tags[0], kWebEngineLogTag);
+            static_cast<int32_t>(fuchsia::logger::LogLevelFilter::DEBUG));
+
+  // Verify that the Frame's |debug_name| is amongst the log message tags.
+  EXPECT_FALSE(logged_message->tags.empty());
+  EXPECT_TRUE(base::Contains(logged_message->tags, kFrameLogTag));
+
+  // Verify that the message is formatted as expected.
   EXPECT_EQ(NormalizeConsoleLogMessage(logged_message->msg),
-            "[frame_impl.cc(" + std::string(kNormalizedLineNumber) +
-                ")] debug:http://127.0.0.1:" + kNormalizedPortNumber +
-                "/console_logging.html:8 "
-                ": This is a debug() message.");
+            std::string("http://127.0.0.1:") + kNormalizedPortNumber +
+                "/console_logging.html:8 : This is a debug() message.");
 }