Fix broken states in WebRTC text logging.

* Removes the log state CHANNEL_CLOSING, which is actually not a log state.
* Adds channel_is_closing_ flag instead.

This way, it's possible to check in WebRtcLoggingHandlerHost::StoreLogInDirectory and WebRtcLoggingHandlerHost::DoUploadLogAndRtpDumps if the log is in closed state or not when channel is closing to avoid multiple upload/store attempts.

Multiple stores/uploads could happen if channel is closing and a store or upload operation has been issued around the same time.

Bug: 807547
Change-Id: I5e41d5a02095044582c06037d440d22a2edc0be2
Reviewed-on: https://chromium-review.googlesource.com/c/1296538Reviewed-by: Tommi <tommi@chromium.org>
Commit-Queue: Henrik Grunell <grunell@chromium.org>
Cr-Commit-Position: refs/heads/master@{#602104}

chrome/browser/media/webrtc/webrtc_logging_handler_host.cc

@@ -342,6 +342,8 @@ void WebRtcLoggingHandlerHost::DumpRtpPacketOnIOThread(
 
 void WebRtcLoggingHandlerHost::OnChannelClosing() {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
+
+  if (!text_log_handler_->GetChannelIsClosing()) {
     switch (text_log_handler_->GetState()) {
       case WebRtcTextLogHandler::STARTING:
       case WebRtcTextLogHandler::STARTED:
@@ -351,10 +353,10 @@ void WebRtcLoggingHandlerHost::OnChannelClosing() {
         if (upload_log_on_render_close_) {
           base::PostTaskAndReplyWithResult(
               log_uploader_->background_task_runner().get(), FROM_HERE,
-            base::Bind(
+              base::BindOnce(
                   &WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists,
                   this),
-            base::Bind(&WebRtcLoggingHandlerHost::TriggerUpload, this,
+              base::BindOnce(&WebRtcLoggingHandlerHost::TriggerUpload, this,
                              UploadDoneCallback()));
         } else {
           log_uploader_->LoggingStoppedDontUpload();
@@ -362,12 +364,13 @@ void WebRtcLoggingHandlerHost::OnChannelClosing() {
         }
         break;
       case WebRtcTextLogHandler::CLOSED:
-    case WebRtcTextLogHandler::CHANNEL_CLOSING:
         // Do nothing
         break;
       default:
         NOTREACHED();
     }
+  }
+
   content::BrowserMessageFilter::OnChannelClosing();
 }
 
@@ -459,8 +462,15 @@ void WebRtcLoggingHandlerHost::StoreLogInDirectory(
     const base::FilePath& directory) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
-  if (text_log_handler_->GetState() != WebRtcTextLogHandler::STOPPED &&
-      text_log_handler_->GetState() != WebRtcTextLogHandler::CHANNEL_CLOSING) {
+  // If channel is not closing, storing is only allowed when in STOPPED state.
+  // If channel is closing, storing is allowed for all states except CLOSED.
+  const WebRtcTextLogHandler::LoggingState text_logging_state =
+      text_log_handler_->GetState();
+  const bool channel_is_closing = text_log_handler_->GetChannelIsClosing();
+  if ((!channel_is_closing &&
+       text_logging_state != WebRtcTextLogHandler::STOPPED) ||
+      (channel_is_closing &&
+       text_log_handler_->GetState() == WebRtcTextLogHandler::CLOSED)) {
     base::PostTaskWithTraits(
         FROM_HERE, {content::BrowserThread::UI},
         base::BindOnce(done_callback, false,
@@ -488,8 +498,15 @@ void WebRtcLoggingHandlerHost::DoUploadLogAndRtpDumps(
     const UploadDoneCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
-  if (text_log_handler_->GetState() != WebRtcTextLogHandler::STOPPED &&
-      text_log_handler_->GetState() != WebRtcTextLogHandler::CHANNEL_CLOSING) {
+  // If channel is not closing, upload is only allowed when in STOPPED state.
+  // If channel is closing, uploading is allowed for all states except CLOSED.
+  const WebRtcTextLogHandler::LoggingState text_logging_state =
+      text_log_handler_->GetState();
+  const bool channel_is_closing = text_log_handler_->GetChannelIsClosing();
+  if ((!channel_is_closing &&
+       text_logging_state != WebRtcTextLogHandler::STOPPED) ||
+      (channel_is_closing &&
+       text_log_handler_->GetState() == WebRtcTextLogHandler::CLOSED)) {
     base::PostTaskWithTraits(
         FROM_HERE, {content::BrowserThread::UI},
         base::BindOnce(callback, false, "",

chrome/browser/media/webrtc/webrtc_text_log_handler.cc

@@ -146,18 +146,33 @@ WebRtcTextLogHandler::WebRtcTextLogHandler(int render_process_id)
 WebRtcTextLogHandler::~WebRtcTextLogHandler() {
   // If the log isn't closed that means we haven't decremented the log count
   // in the LogUploader.
-  DCHECK(logging_state_ == CLOSED || logging_state_ == CHANNEL_CLOSING);
+  DCHECK(logging_state_ == CLOSED || channel_is_closing_);
   DCHECK(!log_buffer_);
 }
 
+WebRtcTextLogHandler::LoggingState WebRtcTextLogHandler::GetState() const {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  return logging_state_;
+}
+
+bool WebRtcTextLogHandler::GetChannelIsClosing() const {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  return channel_is_closing_;
+}
+
 void WebRtcTextLogHandler::SetMetaData(std::unique_ptr<MetaDataMap> meta_data,
                                        const GenericDoneCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   DCHECK(!callback.is_null());
 
+  if (channel_is_closing_) {
+    FireGenericDoneCallback(callback, false, "The renderer is closing.");
+    return;
+  }
+
   if (logging_state_ != CLOSED && logging_state_ != STARTED) {
-    std::string error_message = "Meta data must be set before stop or upload.";
-    FireGenericDoneCallback(callback, false, error_message);
+    FireGenericDoneCallback(callback, false,
+                            "Meta data must be set before stop or upload.");
     return;
   }
 
@@ -184,7 +199,7 @@ bool WebRtcTextLogHandler::StartLogging(WebRtcLogUploader* log_uploader,
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   DCHECK(!callback.is_null());
 
-  if (logging_state_ == CHANNEL_CLOSING) {
+  if (channel_is_closing_) {
     FireGenericDoneCallback(callback, false, "The renderer is closing.");
     return false;
   }
@@ -220,7 +235,7 @@ void WebRtcTextLogHandler::StartDone(const GenericDoneCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   DCHECK(!callback.is_null());
 
-  if (logging_state_ == CHANNEL_CLOSING) {
+  if (channel_is_closing_) {
     FireGenericDoneCallback(callback, false,
                             "Failed to start log. Renderer is closing.");
     return;
@@ -237,7 +252,7 @@ bool WebRtcTextLogHandler::StopLogging(const GenericDoneCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   DCHECK(!callback.is_null());
 
-  if (logging_state_ == CHANNEL_CLOSING) {
+  if (channel_is_closing_) {
     FireGenericDoneCallback(callback, false,
                             "Can't stop log. Renderer is closing.");
     return false;
@@ -257,11 +272,19 @@ bool WebRtcTextLogHandler::StopLogging(const GenericDoneCallback& callback) {
 
 void WebRtcTextLogHandler::StopDone() {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  DCHECK_EQ(STOPPING, logging_state_);
+  DCHECK(stop_callback_);
+
+  if (channel_is_closing_) {
+    FireGenericDoneCallback(stop_callback_, false,
+                            "Failed to stop log. Renderer is closing.");
+    return;
+  }
+
   // If we aren't in STOPPING state, then there is a bug in the caller, since
   // it is responsible for checking the state before making the call. If we do
   // enter here in a bad state, then we can't use the stop_callback_ or we
   // might fire the same callback multiple times.
+  DCHECK_EQ(STOPPING, logging_state_);
   if (logging_state_ == STOPPING) {
     logging_started_time_ = base::Time();
     logging_state_ = STOPPED;
@@ -275,15 +298,16 @@ void WebRtcTextLogHandler::ChannelClosing() {
 
   if (logging_state_ == STARTING || logging_state_ == STARTED)
     content::WebRtcLog::ClearLogMessageCallback(render_process_id_);
-  logging_state_ = LoggingState::CHANNEL_CLOSING;
+  channel_is_closing_ = true;
 }
 
 void WebRtcTextLogHandler::DiscardLog() {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  DCHECK(logging_state_ == STOPPED || logging_state_ == CHANNEL_CLOSING);
+  DCHECK(logging_state_ == STOPPED ||
+         (channel_is_closing_ && logging_state_ != CLOSED));
+
   log_buffer_.reset();
   meta_data_.reset();
-  if (logging_state_ != CHANNEL_CLOSING)
   logging_state_ = LoggingState::CLOSED;
 }
 
@@ -291,10 +315,14 @@ void WebRtcTextLogHandler::ReleaseLog(
     std::unique_ptr<WebRtcLogBuffer>* log_buffer,
     std::unique_ptr<MetaDataMap>* meta_data) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  DCHECK(logging_state_ == STOPPED || logging_state_ == CHANNEL_CLOSING);
+  DCHECK(logging_state_ == STOPPED ||
+         (channel_is_closing_ && logging_state_ != CLOSED));
+  DCHECK(log_buffer_);
+  DCHECK(meta_data_);
 
   // Checking log_buffer_ here due to seeing some crashes out in the wild.
   // See crbug/699960 for more details.
+  // TODO(crbug/807547): Remove if condition.
   if (log_buffer_) {
     log_buffer_->SetComplete();
     *log_buffer = std::move(log_buffer_);
@@ -303,7 +331,6 @@ void WebRtcTextLogHandler::ReleaseLog(
   if (meta_data_)
     *meta_data = std::move(meta_data_);
 
-  if (logging_state_ != CHANNEL_CLOSING)
   logging_state_ = LoggingState::CLOSED;
 }
 
@@ -317,7 +344,7 @@ void WebRtcTextLogHandler::LogToCircularBuffer(const std::string& message) {
 
 void WebRtcTextLogHandler::LogMessage(const std::string& message) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  if (logging_state_ == STARTED) {
+  if (logging_state_ == STARTED && !channel_is_closing_) {
     LogToCircularBuffer(WebRtcLoggingMessageData::Format(
         message, base::Time::Now(), logging_started_time_));
   }
@@ -357,27 +384,26 @@ void WebRtcTextLogHandler::FireGenericDoneCallback(
   DCHECK(!success);
 
   // Add current logging state to error message.
-  std::string error_message_with_state(error_message);
+  auto state_string = [&] {
     switch (logging_state_) {
       case LoggingState::CLOSED:
-      error_message_with_state += " State=closed.";
-      break;
+        return "closed";
       case LoggingState::STARTING:
-      error_message_with_state += " State=starting.";
-      break;
+        return "starting";
       case LoggingState::STARTED:
-      error_message_with_state += " State=started.";
-      break;
+        return "started";
       case LoggingState::STOPPING:
-      error_message_with_state += " State=stopping.";
-      break;
+        return "stopping";
       case LoggingState::STOPPED:
-      error_message_with_state += " State=stopped.";
-      break;
-    case LoggingState::CHANNEL_CLOSING:
-      error_message_with_state += " State=channel closing.";
-      break;
+        return "stopped";
     }
+    NOTREACHED();
+    return "";
+  };
+
+  std::string error_message_with_state =
+      base::StrCat({error_message, ". State=", state_string(), ". Channel is ",
+                    channel_is_closing_ ? "" : "not ", "closing."});
 
   base::PostTaskWithTraits(
       FROM_HERE, {BrowserThread::UI},
@@ -388,7 +414,8 @@ void WebRtcTextLogHandler::LogInitialInfoOnIOThread(
     const GenericDoneCallback& callback,
     const net::NetworkInterfaceList& network_list) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
-  if (logging_state_ != STARTING) {
+
+  if (logging_state_ != STARTING || channel_is_closing_) {
     FireGenericDoneCallback(callback, false, "Logging cancelled.");
     return;
   }

chrome/browser/media/webrtc/webrtc_text_log_handler.h

@@ -57,25 +57,21 @@ class WebRtcTextLogHandler
  public:
   // States used for protecting from function calls made at non-allowed points
   // in time. For example, StartLogging() is only allowed in CLOSED state.
-  // Transitions: SetMetaData():    CLOSED -> CLOSED.
+  // See also comment on |channel_is_closing_| below.
+  // Transitions: SetMetaData():    CLOSED -> CLOSED, or
+  //                                STARTED -> STARTED
   //              StartLogging():   CLOSED -> STARTING.
   //              StartDone():      STARTING -> STARTED.
   //              StopLogging():    STARTED -> STOPPING.
   //              StopDone():       STOPPING -> STOPPED.
-  //              DiscardLog():     STOPPED -> CLOSED or
-  //                                CHANNEL_CLOSING -> CHANNEL_CLOSING.
-  //              ReleaseLog():     STOPPED -> CLOSED. or
-  //                                CHANNEL_CLOSING -> CHANNEL_CLOSING.
-  //              ChannelClosing(): ANY -> CHANNEL_CLOSING.
+  //              DiscardLog():     STOPPED -> CLOSED.
+  //              ReleaseLog():     STOPPED -> CLOSED.
   enum LoggingState {
     CLOSED,           // Logging not started, no log in memory.
     STARTING,         // Start logging is in progress.
     STARTED,          // Logging started.
     STOPPING,         // Stop logging is in progress.
     STOPPED,          // Logging has been stopped, log still open in memory.
-    CHANNEL_CLOSING,  // Renderer is closing. The log (if there is one) can
-                      // still be uploaded, but no new logs can be created and
-                      // and no state transitions can be made.
   };
 
   typedef base::Callback<void(bool, const std::string&)> GenericDoneCallback;
@@ -83,8 +79,15 @@ class WebRtcTextLogHandler
   explicit WebRtcTextLogHandler(int render_process_id);
 
   // Returns the current state of the log. Must be called on the IO thread.
-  LoggingState GetState() const { return logging_state_; }
+  LoggingState GetState() const;
 
+  // Returns true if channel is closing. Must be called on the IO thread.
+  bool GetChannelIsClosing() const;
+
+  // Sets meta data for log uploading. Merged with any already set meta data.
+  // Values for existing keys are overwritten. The meta data already set at log
+  // start is written to the beginning of the log. Meta data set after log start
+  // is written to the log at that time.
   void SetMetaData(std::unique_ptr<MetaDataMap> meta_data,
                    const GenericDoneCallback& callback);
 
@@ -153,12 +156,18 @@ class WebRtcTextLogHandler
   // Should be created by StartLogging().
   std::unique_ptr<MetaDataMap> meta_data_;
 
-  // These are only accessed on the IO thread.
+  // Only accessed on the IO thread.
   GenericDoneCallback stop_callback_;
 
   // Only accessed on the IO thread.
   LoggingState logging_state_;
 
+  // True if renderer is closing. The log (if there is one) can still be
+  // released or discarded (i.e. closed). No new logs can be created. The only
+  // state change possible when channel is closing is from any state to CLOSED.
+  // Can only accessed on the IO thread.
+  bool channel_is_closing_ = false;
+
   // The system time in ms when logging is started. Reset when logging_state_
   // changes to STOPPED.
   base::Time logging_started_time_;