From 2bf3d536ea96969bf3ffd60a1fd08b5db9a8e8b4 Mon Sep 17 00:00:00 2001 From: Marshall Greenblatt Date: Tue, 16 Aug 2022 13:10:43 -0400 Subject: [PATCH] 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 | 11 ++- libcef/browser/frame_host_impl.cc | 35 ++++++--- libcef/browser/frame_host_impl.h | 10 ++- libcef/renderer/frame_impl.cc | 119 ++++++++++++++++++++++-------- libcef/renderer/frame_impl.h | 25 +++++-- 5 files changed, 151 insertions(+), 49 deletions(-) diff --git a/libcef/browser/browser_info.cc b/libcef/browser/browser_info.cc index b0ba616f1..c50cbe01d 100644 --- a/libcef/browser/browser_info.cc +++ b/libcef/browser/browser_info.cc @@ -225,8 +225,10 @@ 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,8 +410,9 @@ void CefBrowserInfo::SetMainFrame(CefRefPtr browser, CefRefPtr 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,8 +492,10 @@ 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_); + } } } diff --git a/libcef/browser/frame_host_impl.cc b/libcef/browser/frame_host_impl.cc index 59dbbbe19..5624d0974 100644 --- a/libcef/browser/frame_host_impl.cc +++ b/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 " - << (is_main_frame_ ? "main" : "sub") << "frame " - << frame_util::GetFrameDebugString(frame_id_) + LOG(WARNING) << function_name << " sent to detached " << GetDebugString() << " will be ignored"; return; } @@ -603,11 +619,7 @@ void CefFrameHostImpl::FrameAttached( return; } - if (reattached) { - LOG(INFO) << (is_main_frame_ ? "main" : "sub") << "frame " - << frame_util::GetFrameDebugString(frame_id_) - << " has reconnected"; - } + VLOG(1) << GetDebugString() << " " << (reattached ? "re" : "") << "connected"; 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 frame, const CefString& javascript) { CefFrameHostImpl* impl = static_cast(frame.get()); diff --git a/libcef/browser/frame_host_impl.h b/libcef/browser/frame_host_impl.h index 9a1dd0248..386860165 100644 --- a/libcef/browser/frame_host_impl.h +++ b/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 diff --git a/libcef/renderer/frame_impl.cc b/libcef/renderer/frame_impl.cc index 04278019b..d85ffcb86 100644 --- a/libcef/renderer/frame_impl.cc +++ b/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 " - << frame_util::GetFrameDebugString(frame_id_) + LOG(WARNING) << action.first << " sent to detached " << GetDebugString() << " 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 " - << frame_util::GetFrameDebugString(frame_id_) + LOG(WARNING) << action.first << " sent to detached " << GetDebugString() << " 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 " - << frame_util::GetFrameDebugString(frame_id_) + LOG(WARNING) << function_name << " sent to detached " << GetDebugString() << " 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 " - << frame_util::GetFrameDebugString(frame_id_); + VLOG(1) << GetDebugString() << " connection retry canceled (reason=" + << (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& CefFrameImpl::GetBrowserFrame( @@ -542,19 +553,19 @@ const mojo::Remote& 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 " - << frame_util::GetFrameDebugString(frame_id_); - OnBrowserFrameDisconnect(); + LOG(ERROR) << GetDebugString() << " connection timeout"; + OnDisconnect(DisconnectReason::CONNECT_TIMEOUT); } -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, - &CefFrameImpl::ConnectBrowserFrame); + browser_connect_timer_.Start( + FROM_HERE, kConnectionRetryDelay, + base::BindOnce(&CefFrameImpl::ConnectBrowserFrame, this, + ConnectReason::RETRY)); } else { // Trigger a crash in official builds. - LOG(FATAL) << "Connection retry failure for frame " - << frame_util::GetFrameDebugString(frame_id_); + LOG(FATAL) << GetDebugString() << " connection retry failed"; } } } @@ -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 " - << frame_util::GetFrameDebugString(frame_id_) + LOG(WARNING) << function_name << " sent to detached " << GetDebugString() << " 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__) diff --git a/libcef/renderer/frame_impl.h b/libcef/renderer/frame_impl.h index 78c62049b..00f218314 100644 --- a/libcef/renderer/frame_impl.h +++ b/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; @@ -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 - // to frame navigation, destruction, or insertion into the bfcache (when the - // browser-side frame representation is destroyed and closes the connection). - void OnBrowserFrameDisconnect(); + enum class DisconnectReason { + DETACHED, + CONNECT_TIMEOUT, + 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_;