sessions: adds tracking interesting session events to prefs

I'm hoping to use this as a debugging aid for folks that encounter
problems. Specifically I'm planning on creating a page that shows
this information, so that if a user thinks restore should have
happened they can open this page for some diagnostic information.

This is just the persistence part.

BUG=1167296
TEST=SessionServiceLogTest*

Change-Id: I0385c45e4b2913bcf7e601a3caf9c8f26ca15546
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2633072Reviewed-by: David Bienvenu <davidbienvenu@chromium.org>
Commit-Queue: Scott Violet <sky@chromium.org>
Cr-Commit-Position: refs/heads/master@{#844288}

chrome/browser/BUILD.gn

@@ -6158,6 +6158,8 @@ static_library("browser") {
       "sessions/session_service.h",
       "sessions/session_service_factory.cc",
       "sessions/session_service_factory.h",
+      "sessions/session_service_log.cc",
+      "sessions/session_service_log.h",
       "sessions/session_service_utils.cc",
       "sessions/session_service_utils.h",
       "sessions/tab_loader.cc",

chrome/browser/prefs/browser_prefs.cc

@@ -410,6 +410,9 @@
 #include "chrome/browser/media/feeds/media_feeds_service.h"
 #endif
 
+#if BUILDFLAG(ENABLE_SESSION_SERVICE)
+#include "chrome/browser/sessions/session_service_log.h"
+#endif
 namespace {
 
 #if BUILDFLAG(IS_CHROMEOS_ASH)
@@ -908,6 +911,10 @@ void RegisterProfilePrefs(user_prefs::PrefRegistrySyncable* registry,
   omnibox::RegisterProfilePrefs(registry);
   ZeroSuggestProvider::RegisterProfilePrefs(registry);
 
+#if BUILDFLAG(ENABLE_SESSION_SERVICE)
+  RegisterSessionServiceLogProfilePrefs(registry);
+#endif
+
 #if BUILDFLAG(ENABLE_EXTENSIONS)
   ExtensionWebUI::RegisterProfilePrefs(registry);
   RegisterAnimationPolicyPrefs(registry);

chrome/browser/sessions/session_service_log.cc

+// Copyright 2021 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/browser/sessions/session_service_log.h"
+
+#include "base/strings/string_number_conversions.h"
+#include "base/values.h"
+#include "chrome/browser/profiles/profile.h"
+#include "components/pref_registry/pref_registry_syncable.h"
+#include "components/prefs/pref_service.h"
+
+namespace {
+
+// The value is a list.
+constexpr char kEventPrefKey[] = "sessions.event_log";
+constexpr char kEventTypeKey[] = "type";
+constexpr char kEventTimeKey[] = "time";
+constexpr char kStartEventDidLastSessionCrashKey[] = "crashed";
+constexpr char kRestoreEventWindowCountKey[] = "window_count";
+constexpr char kRestoreEventTabCountKey[] = "tab_count";
+constexpr char kRestoreEventErroredReadingKey[] = "errored_reading";
+constexpr char kExitEventWindowCountKey[] = "window_count";
+constexpr char kExitEventTabCountKey[] = "tab_count";
+constexpr char kWriteErrorEventErrorCountKey[] = "error_count";
+
+// This value is a balance between keeping too much in prefs, and the
+// ability to see the last few restarts.
+constexpr size_t kMaxEventCount = 12;
+
+base::Value SerializeEvent(const SessionServiceEvent& event) {
+  base::Value serialized_event(base::Value::Type::DICTIONARY);
+  serialized_event.SetIntPath(kEventTypeKey, static_cast<int>(event.type));
+  serialized_event.SetStringPath(
+      kEventTimeKey,
+      base::NumberToString(event.time.since_origin().InMicroseconds()));
+  switch (event.type) {
+    case SessionServiceEventLogType::kStart:
+      serialized_event.SetBoolKey(kStartEventDidLastSessionCrashKey,
+                                  event.data.start.did_last_session_crash);
+      break;
+    case SessionServiceEventLogType::kRestore:
+      serialized_event.SetIntKey(kRestoreEventWindowCountKey,
+                                 event.data.restore.window_count);
+      serialized_event.SetIntKey(kRestoreEventTabCountKey,
+                                 event.data.restore.tab_count);
+      serialized_event.SetBoolKey(kRestoreEventErroredReadingKey,
+                                  event.data.restore.encountered_error_reading);
+      break;
+    case SessionServiceEventLogType::kExit:
+      serialized_event.SetIntKey(kExitEventWindowCountKey,
+                                 event.data.exit.window_count);
+      serialized_event.SetIntKey(kExitEventTabCountKey,
+                                 event.data.exit.tab_count);
+      break;
+    case SessionServiceEventLogType::kWriteError:
+      serialized_event.SetIntKey(kWriteErrorEventErrorCountKey,
+                                 event.data.write_error.error_count);
+      break;
+  }
+  return serialized_event;
+}
+
+bool DeserializeEvent(const base::Value& serialized_event,
+                      SessionServiceEvent& event) {
+  if (!serialized_event.is_dict())
+    return false;
+  auto type = serialized_event.FindIntKey(kEventTypeKey);
+  if (!type)
+    return false;
+  if (*type < SessionServiceEventLogType::kMinValue ||
+      *type > SessionServiceEventLogType::kMaxValue) {
+    return false;
+  }
+  event.type = static_cast<SessionServiceEventLogType>(*type);
+
+  const std::string* time_value = serialized_event.FindStringKey(kEventTimeKey);
+  if (!time_value)
+    return false;
+  int64_t time_int;
+  if (!base::StringToInt64(*time_value, &time_int))
+    return false;
+  event.time = base::Time() + base::TimeDelta::FromMicroseconds(time_int);
+
+  switch (event.type) {
+    case SessionServiceEventLogType::kStart: {
+      auto crash_value =
+          serialized_event.FindBoolKey(kStartEventDidLastSessionCrashKey);
+      if (!crash_value)
+        return false;
+      event.data.start.did_last_session_crash = *crash_value;
+      break;
+    }
+    case SessionServiceEventLogType::kRestore: {
+      auto window_count =
+          serialized_event.FindIntKey(kRestoreEventWindowCountKey);
+      if (!window_count)
+        return false;
+      event.data.restore.window_count = *window_count;
+
+      auto tab_count = serialized_event.FindIntKey(kRestoreEventTabCountKey);
+      if (!tab_count)
+        return false;
+      event.data.restore.tab_count = *tab_count;
+
+      auto error_reading =
+          serialized_event.FindBoolKey(kRestoreEventErroredReadingKey);
+      if (!error_reading)
+        return false;
+      event.data.restore.encountered_error_reading = *error_reading;
+      break;
+    }
+    case SessionServiceEventLogType::kExit: {
+      auto window_count = serialized_event.FindIntKey(kExitEventWindowCountKey);
+      if (!window_count)
+        return false;
+      event.data.exit.window_count = *window_count;
+
+      auto tab_count = serialized_event.FindIntKey(kExitEventTabCountKey);
+      if (!tab_count)
+        return false;
+      event.data.exit.tab_count = *tab_count;
+      break;
+    }
+    case SessionServiceEventLogType::kWriteError: {
+      auto error_count =
+          serialized_event.FindIntKey(kWriteErrorEventErrorCountKey);
+      if (!error_count)
+        return false;
+      event.data.write_error.error_count = *error_count;
+      break;
+    }
+  }
+  return true;
+}
+
+void SaveEventsToPrefs(Profile* profile,
+                       const std::list<SessionServiceEvent>& events) {
+  base::Value serialized_events(base::Value::Type::LIST);
+  for (const SessionServiceEvent& event : events)
+    serialized_events.Append(SerializeEvent(event));
+  profile->GetPrefs()->Set(kEventPrefKey, serialized_events);
+}
+
+}  // namespace
+
+std::list<SessionServiceEvent> GetSessionServiceEvents(Profile* profile) {
+  const base::ListValue* serialized_events =
+      profile->GetPrefs()->GetList(kEventPrefKey);
+  if (!serialized_events)
+    return {};
+  std::list<SessionServiceEvent> events;
+  for (const auto& serialized_event : serialized_events->GetList()) {
+    SessionServiceEvent event;
+    if (DeserializeEvent(serialized_event, event))
+      events.push_back(std::move(event));
+  }
+  return events;
+}
+
+void LogSessionServiceStartEvent(Profile* profile, bool after_crash) {
+  SessionServiceEvent event;
+  event.type = SessionServiceEventLogType::kStart;
+  event.time = base::Time::Now();
+  event.data.start.did_last_session_crash = after_crash;
+  LogSessionServiceEvent(profile, event);
+}
+
+void LogSessionServiceExitEvent(Profile* profile,
+                                int window_count,
+                                int tab_count) {
+  SessionServiceEvent event;
+  event.type = SessionServiceEventLogType::kExit;
+  event.time = base::Time::Now();
+  event.data.exit.window_count = window_count;
+  event.data.exit.tab_count = tab_count;
+  LogSessionServiceEvent(profile, event);
+}
+
+void LogSessionServiceRestoreEvent(Profile* profile,
+                                   int window_count,
+                                   int tab_count,
+                                   bool encountered_error_reading) {
+  SessionServiceEvent event;
+  event.type = SessionServiceEventLogType::kRestore;
+  event.time = base::Time::Now();
+  event.data.restore.window_count = window_count;
+  event.data.restore.tab_count = tab_count;
+  event.data.restore.encountered_error_reading = encountered_error_reading;
+  LogSessionServiceEvent(profile, event);
+}
+
+void LogSessionServiceWriteErrorEvent(Profile* profile) {
+  SessionServiceEvent event;
+  event.type = SessionServiceEventLogType::kWriteError;
+  event.time = base::Time::Now();
+  event.data.write_error.error_count = 1;
+  LogSessionServiceEvent(profile, event);
+}
+
+void RegisterSessionServiceLogProfilePrefs(
+    user_prefs::PrefRegistrySyncable* registry) {
+  registry->RegisterListPref(kEventPrefKey);
+}
+
+void LogSessionServiceEvent(Profile* profile,
+                            const SessionServiceEvent& event) {
+  std::list<SessionServiceEvent> events = GetSessionServiceEvents(profile);
+  if (event.type == SessionServiceEventLogType::kWriteError &&
+      !events.empty() &&
+      events.back().type == SessionServiceEventLogType::kWriteError) {
+    events.back().data.write_error.error_count += 1;
+  } else {
+    events.push_back(std::move(event));
+    if (events.size() >= kMaxEventCount)
+      events.erase(events.begin());
+  }
+  SaveEventsToPrefs(profile, events);
+}

chrome/browser/sessions/session_service_log.h

+// Copyright 2021 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef CHROME_BROWSER_SESSIONS_SESSION_SERVICE_LOG_H_
+#define CHROME_BROWSER_SESSIONS_SESSION_SERVICE_LOG_H_
+
+#include <list>
+
+#include "base/time/time.h"
+
+class Profile;
+
+namespace user_prefs {
+class PrefRegistrySyncable;
+}
+
+// This file contains functionality used to track interesting session restore
+// events. This is primarily aimed at helping understand whether session
+// restore is failing.
+//
+// The appropriate code calls to the various log functions. This data is
+// tracked in prefs, and only a limited amount of data is kept around.
+
+// WARNING: these values are persisted to disk, do not change.
+enum SessionServiceEventLogType {
+  // The profile was started.
+  kStart = 0,
+
+  // A restore was triggered. Restore may be triggered more than once after
+  // a start.
+  kRestore = 1,
+
+  // The profile was shut down. It's still possible for a crash to happen
+  // after this. This is not logged if a crash happens before exit is attempted.
+  kExit = 2,
+
+  // An error in writing the file occurred. Multiple calls to AddEvent()
+  // when the last event is a error result in combining the event (this is
+  // done to ensure lots of write error don't spam the event log).
+  kWriteError = 3,
+
+  kMinValue = kStart,
+  kMaxValue = kWriteError,
+};
+
+struct StartData {
+  // Whether the last run of chrome crashed.
+  bool did_last_session_crash;
+};
+
+struct RestoreData {
+  // The number of windows restored.
+  int window_count;
+
+  // The number of tabs restored.
+  int tab_count;
+
+  // Whether there was an error in reading the file contents.
+  bool encountered_error_reading;
+};
+
+struct ExitData {
+  // The number of windows open at the time of exit.
+  int window_count;
+
+  // The total number of tabs open at the time of exit.
+  int tab_count;
+};
+
+struct WriteErrorData {
+  // Number of write errors that occurred.
+  int error_count;
+};
+
+union EventData {
+  StartData start;
+  RestoreData restore;
+  ExitData exit;
+  WriteErrorData write_error;
+};
+
+struct SessionServiceEvent {
+  SessionServiceEventLogType type;
+  base::Time time;
+  EventData data;
+};
+
+// Returns the most recent events, ordered with oldest event first. In general
+// the times shouldn't be compared, as it's possible for bad clocks and/or
+// timezone changse to cause an earlier event to have a later time.
+std::list<SessionServiceEvent> GetSessionServiceEvents(Profile* profile);
+
+void LogSessionServiceStartEvent(Profile* profile, bool after_crash);
+void LogSessionServiceExitEvent(Profile* profile,
+                                int window_count,
+                                int tab_count);
+void LogSessionServiceRestoreEvent(Profile* profile,
+                                   int window_count,
+                                   int tab_count,
+                                   bool encountered_error_reading);
+void LogSessionServiceWriteErrorEvent(Profile* profile);
+
+void RegisterSessionServiceLogProfilePrefs(
+    user_prefs::PrefRegistrySyncable* registry);
+
+// This function is used internally, and is generally only exposed for testing.
+void LogSessionServiceEvent(Profile* profile, const SessionServiceEvent& event);
+
+#endif  // CHROME_BROWSER_SESSIONS_SESSION_SERVICE_LOG_H_

chrome/browser/sessions/session_service_log_unittest.cc

+// Copyright 2021 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/browser/sessions/session_service_log.h"
+
+#include "base/time/time.h"
+#include "chrome/test/base/testing_profile.h"
+#include "content/public/test/browser_task_environment.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+class SessionServiceLogTest : public testing::Test {
+ public:
+ protected:
+  content::BrowserTaskEnvironment task_environment_;
+  // |task_environment_| needs to still be alive when
+  // |testing_profile_| is destroyed.
+  TestingProfile testing_profile_;
+};
+
+TEST_F(SessionServiceLogTest, LogSessionServiceEvent) {
+  SessionServiceEvent start_event;
+  start_event.type = SessionServiceEventLogType::kStart;
+  start_event.time = base::Time::Now();
+  start_event.data.start.did_last_session_crash = true;
+  LogSessionServiceEvent(&testing_profile_, start_event);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kStart, restored_event.type);
+  EXPECT_EQ(start_event.time, restored_event.time);
+  EXPECT_EQ(start_event.data.start.did_last_session_crash,
+            restored_event.data.start.did_last_session_crash);
+}
+
+TEST_F(SessionServiceLogTest, LogSessionServiceStartEvent) {
+  const base::Time start_time = base::Time::Now();
+  LogSessionServiceStartEvent(&testing_profile_, false);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kStart, restored_event.type);
+  EXPECT_LE(start_time, restored_event.time);
+  EXPECT_FALSE(restored_event.data.start.did_last_session_crash);
+}
+
+TEST_F(SessionServiceLogTest, LogSessionServiceExitEvent) {
+  const base::Time start_time = base::Time::Now();
+  LogSessionServiceExitEvent(&testing_profile_, 1, 2);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kExit, restored_event.type);
+  EXPECT_LE(start_time, restored_event.time);
+  EXPECT_EQ(1, restored_event.data.exit.window_count);
+  EXPECT_EQ(2, restored_event.data.exit.tab_count);
+}
+
+TEST_F(SessionServiceLogTest, LogSessionServiceRestoreEvent) {
+  const base::Time start_time = base::Time::Now();
+  LogSessionServiceRestoreEvent(&testing_profile_, 1, 2, true);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kRestore, restored_event.type);
+  EXPECT_LE(start_time, restored_event.time);
+  EXPECT_EQ(1, restored_event.data.restore.window_count);
+  EXPECT_EQ(2, restored_event.data.restore.tab_count);
+  EXPECT_TRUE(restored_event.data.restore.encountered_error_reading);
+}
+
+TEST_F(SessionServiceLogTest, LogSessionServiceWriteErrorEvent) {
+  const base::Time start_time = base::Time::Now();
+  LogSessionServiceWriteErrorEvent(&testing_profile_);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kWriteError, restored_event.type);
+  EXPECT_LE(start_time, restored_event.time);
+  EXPECT_EQ(1, restored_event.data.write_error.error_count);
+}
+
+TEST_F(SessionServiceLogTest, WriteErrorEventsCoalesce) {
+  const base::Time start_time = base::Time::Now();
+  LogSessionServiceWriteErrorEvent(&testing_profile_);
+  LogSessionServiceWriteErrorEvent(&testing_profile_);
+  auto events = GetSessionServiceEvents(&testing_profile_);
+  ASSERT_EQ(1u, events.size());
+  auto restored_event = *events.begin();
+  EXPECT_EQ(SessionServiceEventLogType::kWriteError, restored_event.type);
+  EXPECT_LE(start_time, restored_event.time);
+  EXPECT_EQ(2, restored_event.data.write_error.error_count);
+}

chrome/test/BUILD.gn

@@ -5865,6 +5865,7 @@ test("unit_tests") {
     sources += [
       "../browser/sessions/session_restore_observer_unittest.cc",
       "../browser/sessions/session_restore_stats_collector_unittest.cc",
+      "../browser/sessions/session_service_log_unittest.cc",
       "../browser/sessions/session_service_unittest.cc",
       "../browser/sessions/tab_loader_unittest.cc",
     ]