[M115 Merge][lacros] Add additional logging for session debugging

This CL adds further logging to command_storage_backend and some
lacros-specific logging to callsites of LoadTabsFromLastSession().

For affected users, session reads are triggered for both tab
and session restore when the lacros process is first started in
windowless mode. This does not occur for unaffected users.
Understanding what specifically is tripping this code path should
help in root causing the restore failures.

Logs in the command_storage_backend will give better insight into
how session files are being handled. Logs in code calling
TabRestoreService::LoadTabsFromLastSession() will help to understand
if this is being run at unexpected times during startup, potentially
influencing the resulting restore state.

Lacros specific overrides to the VLOG level at these callsites
have been added to avoid users needing to run the latest version
of both ash and lacros for the logs to begin appearing in user logs.

(cherry picked from commit dc8656a)

Bug: 1424800, 1450427
Change-Id: I365590f8665d02b3619fc7bf6e5ec582b88a0ac9
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4577089
Commit-Queue: Thomas Lukaszewicz <tluk@chromium.org>
Code-Coverage: Findit <findit-for-me@appspot.gserviceaccount.com>
Reviewed-by: Scott Violet <sky@chromium.org>
Cr-Original-Commit-Position: refs/heads/main@{#1152340}
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4594427
Cr-Commit-Position: refs/branch-heads/5790@{#427}
Cr-Branched-From: 1d71a33-refs/heads/main@{#1148114}

chrome/browser/extensions/api/sessions/sessions_api.cc

@@ -45,6 +45,12 @@
 #include "extensions/common/error_utils.h"
 #include "ui/base/layout.h"
 
+// TODO(crbug.com/1424800): Remove once the restore issue has been resolved.
+#if BUILDFLAG(IS_CHROMEOS_LACROS)
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+#endif
+
 namespace extensions {
 
 namespace windows = api::windows;
@@ -621,6 +627,8 @@ SessionsEventRouter::SessionsEventRouter(Profile* profile)
   // TabRestoreServiceFactory::GetForProfile() can return nullptr (i.e., when in
   // incognito mode)
   if (tab_restore_service_) {
+    VLOG(1) << "SessionsEventRouter::SessionsEventRouter, loading tabs from "
+               "last session.";
     tab_restore_service_->LoadTabsFromLastSession();
     tab_restore_service_->AddObserver(this);
   }

chrome/browser/sessions/session_service_base.cc

@@ -47,6 +47,12 @@
 #include "chrome/browser/app_controller_mac.h"
 #endif
 
+// TODO(crbug.com/1424800): Remove once the restore issue has been resolved.
+#if BUILDFLAG(IS_CHROMEOS_LACROS)
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+#endif
+
 using base::Time;
 using content::NavigationEntry;
 using content::WebContents;
@@ -321,6 +327,8 @@ void SessionServiceBase::GetLastSession(
     sessions::GetLastSessionCallback callback) {
   // OnGotSessionCommands maps the SessionCommands to browser state, then run
   // the callback.
+  VLOG(1) << "SessionServiceBase::GetLastSession, getting session restore "
+             "commands.";
   return command_storage_manager_->GetLastSessionCommands(
       base::BindOnce(&SessionServiceBase::OnGotSessionCommands,
                      weak_factory_.GetWeakPtr(), std::move(callback)));

chrome/browser/ui/browser_command_controller.cc

@@ -113,6 +113,12 @@
 #include "components/user_manager/user_manager.h"
 #endif
 
+// TODO(crbug.com/1424800): Remove once the restore issue has been resolved.
+#if BUILDFLAG(IS_CHROMEOS_LACROS)
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+#endif
+
 #if BUILDFLAG(IS_LINUX)
 #include "ui/linux/linux_ui.h"
 #endif
@@ -241,8 +247,11 @@ BrowserCommandController::BrowserCommandController(Browser* browser)
       TabRestoreServiceFactory::GetForProfile(profile());
   if (tab_restore_service) {
     tab_restore_service->AddObserver(this);
-    if (!tab_restore_service->IsLoaded())
+    if (!tab_restore_service->IsLoaded()) {
+      VLOG(1) << "BrowserCommandController::BrowserCommandController, loading "
+                 "tabs from last session.";
       tab_restore_service->LoadTabsFromLastSession();
+    }
   }
 }
 

chrome/browser/ui/browser_tab_restorer.cc

@@ -17,6 +17,12 @@
 #include "components/sessions/core/tab_restore_service.h"
 #include "components/sessions/core/tab_restore_service_observer.h"
 
+// TODO(crbug.com/1424800): Remove once the restore issue has been resolved.
+#if BUILDFLAG(IS_CHROMEOS_LACROS)
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+#endif
+
 namespace chrome {
 namespace {
 
@@ -79,6 +85,8 @@ BrowserTabRestorer::BrowserTabRestorer(Browser* browser)
   BrowserList::AddObserver(this);
   browser_->profile()->SetUserData(kBrowserTabRestorerKey,
                                    base::WrapUnique(this));
+  VLOG(1) << "BrowserTabRestorer::BrowserTabRestorer, loading tabs from last "
+             "session.";
   tab_restore_service_->LoadTabsFromLastSession();
 }
 

components/sessions/core/command_storage_backend.cc

@@ -174,6 +174,9 @@ class SessionFileReader {
   // The file.
   std::unique_ptr<base::File> file_;
 
+  // The number of bytes successfully read from `file_`.
+  int bytes_read_ = 0;
+
   // Position in buffer_ of the data.
   size_t buffer_position_ = 0;
 
@@ -205,7 +208,8 @@ CommandStorageBackend::ReadCommandsResult SessionFileReader::Read() {
 
   LOG_IF(ERROR, result.error_reading)
       << "Commands successfully read before error: "
-      << commands_result.commands.size();
+      << commands_result.commands.size()
+      << ", bytes successfully read from file before error: " << bytes_read_;
 
   // `error_reading` is only set if `command` is null.
   commands_result.error_reading = result.error_reading;
@@ -220,10 +224,23 @@ bool SessionFileReader::ReadHeader() {
   if (!file_->IsValid())
     return false;
   FileHeader header;
-  const int read_count =
+  CHECK_EQ(0, bytes_read_);
+  bytes_read_ =
       file_->ReadAtCurrentPos(reinterpret_cast<char*>(&header), sizeof(header));
-  if (read_count != sizeof(header) || header.signature != kFileSignature)
+  if (bytes_read_ < 0) {
+    VLOG(1) << "SessionFileReader::ReadHeader, failed to read header. "
+               "Attempted to read "
+            << sizeof(header)
+            << " bytes into buffer but encountered file read error: "
+            << base::File::ErrorToString(base::File::GetLastFileError());
+  }
+  if (bytes_read_ != sizeof(header) || header.signature != kFileSignature) {
+    VLOG(1) << "SessionFileReader::ReadHeader, failed to read header. "
+               "Attempted to read "
+            << sizeof(header) << " bytes into buffer but got " << bytes_read_
+            << " bytes instead.";
     return false;
+  }
   version_ = header.version;
   const bool encrypt = aead_.get() != nullptr;
   return (encrypt && (version_ == kEncryptedFileVersion ||
@@ -345,15 +362,21 @@ bool SessionFileReader::FillBuffer() {
   }
   buffer_position_ = 0;
   DCHECK(buffer_position_ + available_count_ < buffer_.size());
-  int to_read = static_cast<int>(buffer_.size() - available_count_);
-  int read_count =
+  const int to_read = static_cast<int>(buffer_.size() - available_count_);
+  const int read_count =
       file_->ReadAtCurrentPos(&(buffer_[available_count_]), to_read);
   if (read_count < 0) {
-    // TODO(sky): communicate/log an error here.
+    VLOG(1) << "SessionFileReader::FillBuffer, failed to read header. "
+               "Attempted to read "
+            << to_read << " bytes into buffer but encountered file read error: "
+            << base::File::ErrorToString(base::File::GetLastFileError())
+            << "\nRead " << bytes_read_
+            << " bytes successfully from file before error.";
     return false;
   }
   if (read_count == 0)
     return false;
+  bytes_read_ += read_count;
   available_count_ += read_count;
   return true;
 }
@@ -564,15 +587,22 @@ CommandStorageBackend::ReadCommandsResult
 CommandStorageBackend::ReadLastSessionCommands() {
   InitIfNecessary();
 
-  if (last_session_info_)
+  if (last_session_info_) {
+    VLOG(1) << "CommandStorageBackend::ReadLastSessionCommands, reading "
+               "commands from: "
+            << last_session_info_->path;
     return ReadCommandsFromFile(last_session_info_->path,
                                 initial_decryption_key_);
+  }
   return {};
 }
 
 void CommandStorageBackend::DeleteLastSession() {
   InitIfNecessary();
   if (last_session_info_) {
+    VLOG(1)
+        << "CommandStorageBackend::DeleteLastSession, deleting session file: "
+        << last_session_info_->path;
     base::DeleteFile(last_session_info_->path);
     last_session_info_.reset();
   }
@@ -594,6 +624,9 @@ void CommandStorageBackend::MoveCurrentSessionToLastSession() {
     last_or_current_path_with_valid_marker_.reset();
   }
   last_session_info_ = new_last_session_info;
+  VLOG(1) << "CommandStorageBackend::MoveCurrentSessionToLastSession, moved "
+             "current session to: "
+          << (last_session_info_ ? last_session_info_->path : base::FilePath());
 
   TruncateOrOpenFile();
 }

components/sessions/core/tab_restore_service_impl.cc

@@ -34,6 +34,12 @@
 #include "components/tab_groups/tab_group_id.h"
 #include "components/tab_groups/tab_group_visual_data.h"
 
+// TODO(crbug.com/1424800): Remove once the restore issue has been resolved.
+#if BUILDFLAG(IS_CHROMEOS_LACROS)
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+#endif
+
 #undef LoadBitmap
 
 namespace sessions {
@@ -754,6 +760,8 @@ void TabRestoreServiceImpl::PersistenceDelegate::LoadTabsFromLastSession() {
   // Request the tabs closed in the last session. If the last session crashed,
   // this won't contain the tabs/window that were open at the point of the
   // crash (the call to GetLastSession above requests those).
+  VLOG(1) << "PersistenceDelegate::LoadTabsFromLastSession, getting tab "
+             "restore commands.";
   command_storage_manager_->GetLastSessionCommands(
       base::BindOnce(&PersistenceDelegate::OnGotLastSessionCommands,
                      weak_factory_.GetWeakPtr()));