Improve logging of frame connection state (see issue #3260)

Run with "--vmodule=frame_*=1 --enable-logging=stderr --no-sandbox" on the
command-line to see these log messages from both the browser and renderer
processes.

libcef/browser/browser_info.cc

@@ -225,9 +225,11 @@ void CefBrowserInfo::RemoveFrame(content::RenderFrameHost* host) {
     // Explicitly Detach everything but the current main frame.
     const auto& frame_info = *it2;
     if (frame_info->frame_ && !frame_info->IsCurrentMainFrame()) {
-      if (frame_info->frame_->Detach())
+      if (frame_info->frame_->Detach(
+              CefFrameHostImpl::DetachReason::RENDER_FRAME_DELETED)) {
         MaybeNotifyFrameDetached(browser_, frame_info->frame_);
       }
+    }
 
     frame_info_set_.erase(it2);
   }
@@ -408,9 +410,10 @@ void CefBrowserInfo::SetMainFrame(CefRefPtr<CefBrowserHostBase> browser,
   CefRefPtr<CefFrameHostImpl> old_frame;
   if (main_frame_) {
     old_frame = main_frame_;
-    if (old_frame->Detach())
+    if (old_frame->Detach(CefFrameHostImpl::DetachReason::NEW_MAIN_FRAME)) {
       MaybeNotifyFrameDetached(browser, old_frame);
     }
+  }
 
   main_frame_ = frame;
 
@@ -489,10 +492,12 @@ void CefBrowserInfo::RemoveAllFrames(
   // Explicitly Detach everything but the current main frame.
   for (auto& info : frame_info_set_) {
     if (info->frame_ && !info->IsCurrentMainFrame()) {
-      if (info->frame_->Detach())
+      if (info->frame_->Detach(
+              CefFrameHostImpl::DetachReason::BROWSER_DESTROYED)) {
         MaybeNotifyFrameDetached(old_browser, info->frame_);
       }
     }
+  }
 
   if (main_frame_)
     SetMainFrame(old_browser, nullptr);

libcef/browser/frame_host_impl.cc

@@ -439,9 +439,27 @@ content::RenderFrameHost* CefFrameHostImpl::GetRenderFrameHost() const {
   return render_frame_host_;
 }
 
-bool CefFrameHostImpl::Detach() {
+bool CefFrameHostImpl::Detach(DetachReason reason) {
   CEF_REQUIRE_UIT();
 
+  if (VLOG_IS_ON(1)) {
+    std::string reason_str;
+    switch (reason) {
+      case DetachReason::RENDER_FRAME_DELETED:
+        reason_str = "RENDER_FRAME_DELETED";
+        break;
+      case DetachReason::NEW_MAIN_FRAME:
+        reason_str = "NEW_MAIN_FRAME";
+        break;
+      case DetachReason::BROWSER_DESTROYED:
+        reason_str = "BROWSER_DESTROYED";
+        break;
+    };
+
+    VLOG(1) << GetDebugString() << " detached (reason=" << reason_str
+            << ", is_connected=" << render_frame_.is_bound() << ")";
+  }
+
   // May be called multiple times (e.g. from CefBrowserInfo SetMainFrame and
   // RemoveFrame).
   bool first_detach = false;
@@ -539,9 +557,7 @@ void CefFrameHostImpl::SendToRenderFrame(const std::string& function_name,
     return;
   } else if (!render_frame_host_) {
     // We've been detached.
-    LOG(WARNING) << function_name << " sent to detached "
+    LOG(WARNING) << function_name << " sent to detached " << GetDebugString()
-                 << (is_main_frame_ ? "main" : "sub") << "frame "
-                 << frame_util::GetFrameDebugString(frame_id_)
                  << " will be ignored";
     return;
   }
@@ -603,11 +619,7 @@ void CefFrameHostImpl::FrameAttached(
     return;
   }
 
-  if (reattached) {
+  VLOG(1) << GetDebugString() << " " << (reattached ? "re" : "") << "connected";
-    LOG(INFO) << (is_main_frame_ ? "main" : "sub") << "frame "
-              << frame_util::GetFrameDebugString(frame_id_)
-              << " has reconnected";
-  }
 
   render_frame_.Bind(std::move(render_frame_remote));
   render_frame_.set_disconnect_handler(
@@ -662,6 +674,11 @@ void CefFrameHostImpl::UpdateDraggableRegions(
       browser, this, std::move(draggable_regions));
 }
 
+std::string CefFrameHostImpl::GetDebugString() const {
+  return "frame " + frame_util::GetFrameDebugString(frame_id_) +
+         (is_main_frame_ ? " (main)" : " (sub)");
+}
+
 void CefExecuteJavaScriptWithUserGestureForTests(CefRefPtr<CefFrame> frame,
                                                  const CefString& javascript) {
   CefFrameHostImpl* impl = static_cast<CefFrameHostImpl*>(frame.get());

libcef/browser/frame_host_impl.h

@@ -112,11 +112,17 @@ class CefFrameHostImpl : public CefFrame, public cef::mojom::BrowserFrame {
   // thread.
   content::RenderFrameHost* GetRenderFrameHost() const;
 
+  enum class DetachReason {
+    RENDER_FRAME_DELETED,
+    NEW_MAIN_FRAME,
+    BROWSER_DESTROYED,
+  };
+
   // Owned frame objects will be detached explicitly when the associated
   // RenderFrame is deleted. Temporary frame objects will be detached
   // implicitly via CefBrowserInfo::browser() returning nullptr. Returns true
   // if this was the first call to Detach() for the frame.
-  bool Detach();
+  bool Detach(DetachReason reason);
 
   // A frame has swapped to active status from prerendering or the back-forward
   // cache. We may need to re-attach if the RFH has changed. See
@@ -160,6 +166,8 @@ class CefFrameHostImpl : public CefFrame, public cef::mojom::BrowserFrame {
 
   void OnRenderFrameDisconnect();
 
+  std::string GetDebugString() const;
+
   const bool is_main_frame_;
 
   // The following members may be read/modified from any thread. All access must

libcef/renderer/frame_impl.cc

@@ -32,6 +32,7 @@
 #include "libcef/renderer/thread_util.h"
 #include "libcef/renderer/v8_impl.h"
 
+#include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "content/renderer/render_frame_impl.h"
 #include "third_party/blink/public/mojom/frame/frame.mojom-blink.h"
@@ -331,13 +332,13 @@ CefFrameImpl::CreateResourceLoadInfoNotifierWrapper() {
 
 void CefFrameImpl::OnAttached() {
   // Called indirectly from RenderFrameCreated.
-  ConnectBrowserFrame();
+  ConnectBrowserFrame(ConnectReason::RENDER_FRAME_CREATED);
 }
 
 void CefFrameImpl::OnWasShown() {
   if (browser_connection_state_ == ConnectionState::DISCONNECTED) {
     // Reconnect a frame that has exited the bfcache.
-    ConnectBrowserFrame();
+    ConnectBrowserFrame(ConnectReason::WAS_SHOWN);
   }
 }
 
@@ -449,7 +450,7 @@ void CefFrameImpl::OnDetached() {
 
   browser_->FrameDetached(frame_id_);
 
-  OnBrowserFrameDisconnect();
+  OnDisconnect(DisconnectReason::DETACHED);
 
   browser_ = nullptr;
   url_loader_factory_.reset();
@@ -457,8 +458,7 @@ void CefFrameImpl::OnDetached() {
   // In case we never attached.
   while (!queued_browser_actions_.empty()) {
     auto& action = queued_browser_actions_.front();
-    LOG(WARNING) << action.first << " sent to detached frame "
+    LOG(WARNING) << action.first << " sent to detached " << GetDebugString()
-                 << frame_util::GetFrameDebugString(frame_id_)
                  << " will be ignored";
     queued_browser_actions_.pop();
   }
@@ -466,8 +466,7 @@ void CefFrameImpl::OnDetached() {
   // In case we're destroyed without the context being created.
   while (!queued_context_actions_.empty()) {
     auto& action = queued_context_actions_.front();
-    LOG(WARNING) << action.first << " sent to detached frame "
+    LOG(WARNING) << action.first << " sent to detached " << GetDebugString()
-                 << frame_util::GetFrameDebugString(frame_id_)
                  << " will be ignored";
     queued_context_actions_.pop();
   }
@@ -487,33 +486,44 @@ void CefFrameImpl::ExecuteOnLocalFrame(const std::string& function_name,
   if (frame_) {
     std::move(action).Run(frame_);
   } else {
-    LOG(WARNING) << function_name << " sent to detached frame "
+    LOG(WARNING) << function_name << " sent to detached " << GetDebugString()
-                 << frame_util::GetFrameDebugString(frame_id_)
                  << " will be ignored";
   }
 }
 
-void CefFrameImpl::ConnectBrowserFrame() {
+void CefFrameImpl::ConnectBrowserFrame(ConnectReason reason) {
   DCHECK(browser_connection_state_ == ConnectionState::DISCONNECTED ||
          browser_connection_state_ == ConnectionState::RECONNECT_PENDING);
 
+  if (VLOG_IS_ON(1)) {
+    std::string reason_str;
+    switch (reason) {
+      case ConnectReason::RENDER_FRAME_CREATED:
+        reason_str = "RENDER_FRAME_CREATED";
+        break;
+      case ConnectReason::WAS_SHOWN:
+        reason_str = "WAS_SHOWN";
+        break;
+      case ConnectReason::RETRY:
+        reason_str = base::StringPrintf(
+            "RETRY %zu/%zu", browser_connect_retry_ct_, kConnectionRetryMaxCt);
+        break;
+    }
+    VLOG(1) << GetDebugString() << " connection request (reason=" << reason_str
+            << ")";
+  }
+
   // Don't attempt to connect an invalid or bfcache'd frame. If a bfcache'd
   // frame returns to active status a reconnect will be triggered via
   // OnWasShown().
   if (!frame_ || blink_glue::IsInBackForwardCache(frame_)) {
     browser_connection_state_ = ConnectionState::DISCONNECTED;
     browser_connect_timer_.Stop();
-    LOG(INFO) << "Connection retry canceled for frame "
+    VLOG(1) << GetDebugString() << " connection retry canceled (reason="
-              << frame_util::GetFrameDebugString(frame_id_);
+            << (frame_ ? "BFCACHED" : "INVALID") << ")";
     return;
   }
 
-  if (browser_connect_retry_ct_ > 0) {
-    LOG(INFO) << "Connection retry " << browser_connect_retry_ct_ << "/"
-              << kConnectionRetryMaxCt << " for frame "
-              << frame_util::GetFrameDebugString(frame_id_);
-  }
-
   browser_connection_state_ = ConnectionState::CONNECTION_PENDING;
   browser_connect_timer_.Start(FROM_HERE, kConnectionTimeout, this,
                                &CefFrameImpl::OnBrowserFrameTimeout);
@@ -522,12 +532,13 @@ void CefFrameImpl::ConnectBrowserFrame() {
   CHECK(browser_frame);
 
   // If the channel is working we should get a call to FrameAttachedAck().
-  // Otherwise, OnBrowserFrameDisconnect() should be called to retry the
+  // Otherwise, OnDisconnect() should be called to retry the
   // connection.
   browser_frame->FrameAttached(receiver_.BindNewPipeAndPassRemote(),
                                browser_connect_retry_ct_ > 0);
   receiver_.set_disconnect_handler(
-      base::BindOnce(&CefFrameImpl::OnBrowserFrameDisconnect, this));
+      base::BindOnce(&CefFrameImpl::OnDisconnect, this,
+                     DisconnectReason::RENDER_FRAME_DISCONNECT));
 }
 
 const mojo::Remote<cef::mojom::BrowserFrame>& CefFrameImpl::GetBrowserFrame(
@@ -542,19 +553,19 @@ const mojo::Remote<cef::mojom::BrowserFrame>& CefFrameImpl::GetBrowserFrame(
       render_frame->GetBrowserInterfaceBroker()->GetInterface(
           browser_frame_.BindNewPipeAndPassReceiver());
       browser_frame_.set_disconnect_handler(
-          base::BindOnce(&CefFrameImpl::OnBrowserFrameDisconnect, this));
+          base::BindOnce(&CefFrameImpl::OnDisconnect, this,
+                         DisconnectReason::BROWSER_FRAME_DISCONNECT));
     }
   }
   return browser_frame_;
 }
 
 void CefFrameImpl::OnBrowserFrameTimeout() {
-  LOG(ERROR) << "Connection timeout for frame "
+  LOG(ERROR) << GetDebugString() << " connection timeout";
-             << frame_util::GetFrameDebugString(frame_id_);
+  OnDisconnect(DisconnectReason::CONNECT_TIMEOUT);
-  OnBrowserFrameDisconnect();
 }
 
-void CefFrameImpl::OnBrowserFrameDisconnect() {
+void CefFrameImpl::OnDisconnect(DisconnectReason reason) {
   // Ignore multiple calls in close proximity (which may occur if both
   // |browser_frame_| and |receiver_| disconnect). |frame_| will be nullptr
   // when called from/after OnDetached().
@@ -563,6 +574,46 @@ void CefFrameImpl::OnBrowserFrameDisconnect() {
     return;
   }
 
+  if (VLOG_IS_ON(1)) {
+    std::string reason_str;
+    switch (reason) {
+      case DisconnectReason::DETACHED:
+        reason_str = "DETACHED";
+        break;
+      case DisconnectReason::CONNECT_TIMEOUT:
+        reason_str = "CONNECT_TIMEOUT";
+        break;
+      case DisconnectReason::RENDER_FRAME_DISCONNECT:
+        reason_str = "RENDER_FRAME_DISCONNECT";
+        break;
+      case DisconnectReason::BROWSER_FRAME_DISCONNECT:
+        reason_str = "BROWSER_FRAME_DISCONNECT";
+        break;
+    };
+
+    std::string state_str;
+    switch (browser_connection_state_) {
+      case ConnectionState::DISCONNECTED:
+        state_str = "DISCONNECTED";
+        break;
+      case ConnectionState::CONNECTION_PENDING:
+        state_str = "CONNECTION_PENDING";
+        break;
+      case ConnectionState::CONNECTION_ACKED:
+        state_str = "CONNECTION_ACKED";
+        break;
+      case ConnectionState::RECONNECT_PENDING:
+        state_str = "RECONNECT_PENDING";
+        break;
+    }
+
+    if (!frame_)
+      state_str += ", FRAME_INVALID";
+
+    VLOG(1) << GetDebugString() << " disconnected (reason=" << reason_str
+            << ", current_state=" << state_str << ")";
+  }
+
   browser_frame_.reset();
   receiver_.reset();
   browser_connection_state_ = ConnectionState::DISCONNECTED;
@@ -571,6 +622,8 @@ void CefFrameImpl::OnBrowserFrameDisconnect() {
   // Only retry if the frame is still valid.
   if (frame_) {
     if (browser_connect_retry_ct_++ < kConnectionRetryMaxCt) {
+      VLOG(1) << GetDebugString() << " connection retry scheduled";
+
       // Retry after a delay in case the frame is currently navigating, being
       // destroyed, or entering the bfcache. In the navigation case the retry
       // will likely succeed. In the destruction case the retry will be
@@ -578,12 +631,13 @@ void CefFrameImpl::OnBrowserFrameDisconnect() {
       // may not be updated immediately, so we allow the reconnect timer to
       // trigger and check the status in ConnectBrowserFrame() instead.
       browser_connection_state_ = ConnectionState::RECONNECT_PENDING;
-      browser_connect_timer_.Start(FROM_HERE, kConnectionRetryDelay, this,
+      browser_connect_timer_.Start(
-                                   &CefFrameImpl::ConnectBrowserFrame);
+          FROM_HERE, kConnectionRetryDelay,
+          base::BindOnce(&CefFrameImpl::ConnectBrowserFrame, this,
+                         ConnectReason::RETRY));
     } else {
       // Trigger a crash in official builds.
-      LOG(FATAL) << "Connection retry failure for frame "
+      LOG(FATAL) << GetDebugString() << " connection retry failed";
-                 << frame_util::GetFrameDebugString(frame_id_);
     }
   }
 }
@@ -592,8 +646,7 @@ void CefFrameImpl::SendToBrowserFrame(const std::string& function_name,
                                       BrowserFrameAction action) {
   if (!frame_) {
     // We've been detached.
-    LOG(WARNING) << function_name << " sent to detached frame "
+    LOG(WARNING) << function_name << " sent to detached " << GetDebugString()
-                 << frame_util::GetFrameDebugString(frame_id_)
                  << " will be ignored";
     return;
   }
@@ -763,6 +816,10 @@ void CefFrameImpl::ContextLifecycleStateChanged(
   }
 }
 
+std::string CefFrameImpl::GetDebugString() const {
+  return "frame " + frame_util::GetFrameDebugString(frame_id_);
+}
+
 // Enable deprecation warnings on Windows. See http://crbug.com/585142.
 #if BUILDFLAG(IS_WIN)
 #if defined(__clang__)

libcef/renderer/frame_impl.h

@@ -109,8 +109,14 @@ class CefFrameImpl
   void ExecuteOnLocalFrame(const std::string& function_name,
                            LocalFrameAction action);
 
+  enum class ConnectReason {
+    RENDER_FRAME_CREATED,
+    WAS_SHOWN,
+    RETRY,
+  };
+
   // Initiate the connection to the BrowserFrame channel.
-  void ConnectBrowserFrame();
+  void ConnectBrowserFrame(ConnectReason reason);
 
   // Returns the remote BrowserFrame object.
   using BrowserFrameType = mojo::Remote<cef::mojom::BrowserFrame>;
@@ -119,10 +125,17 @@ class CefFrameImpl
   // Called if the BrowserFrame connection attempt times out.
   void OnBrowserFrameTimeout();
 
-  // Called if/when the BrowserFrame channel is disconnected. This may occur due
+  enum class DisconnectReason {
-  // to frame navigation, destruction, or insertion into the bfcache (when the
+    DETACHED,
-  // browser-side frame representation is destroyed and closes the connection).
+    CONNECT_TIMEOUT,
-  void OnBrowserFrameDisconnect();
+    RENDER_FRAME_DISCONNECT,
+    BROWSER_FRAME_DISCONNECT,
+  };
+
+  // Called if/when a disconnect occurs. This may occur due to frame navigation,
+  // destruction, or insertion into the bfcache (when the browser-side frame
+  // representation is destroyed and closes the connection).
+  void OnDisconnect(DisconnectReason reason);
 
   // Send an action to the remote BrowserFrame. This will queue the action if
   // the remote frame is not yet attached.
@@ -152,6 +165,8 @@ class CefFrameImpl
   void ContextLifecycleStateChanged(
       blink::mojom::blink::FrameLifecycleState state) override;
 
+  std::string GetDebugString() const;
+
   CefBrowserImpl* browser_;
   blink::WebLocalFrame* frame_;
   const int64 frame_id_;