ash: CalendarModel debug mode

Passing --enable-features=CalendarModelDebugMode on startup enables
logging that's helpful for diagnosing event fetch/cache issues.

Also, if CalendarModelDebugMode and debug
shortcuts (--ash-debug-shortcuts) are enabled, SHIFT+CTRL+ALT+C will
dump CalendarModel's event/cache data to the logs.

Bug: 1322952
Change-Id: I26bbbdb6dc58f5094fa12b31fb40580fbfefa75b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3630963
Commit-Queue: Roger Tinkoff <rtinkoff@google.com>
Reviewed-by: Xiyuan Xia <xiyuan@chromium.org>
Reviewed-by: Toni Barzic <tbarzic@chromium.org>
Reviewed-by: Jiaming Cheng <jiamingc@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1002473}

ash/accelerators/accelerator_commands.cc

@@ -17,8 +17,10 @@
 #include "ash/shelf/shelf.h"
 #include "ash/shell.h"
 #include "ash/system/keyboard_brightness_control_delegate.h"
+#include "ash/system/model/system_tray_model.h"
 #include "ash/system/status_area_widget.h"
 #include "ash/system/time/calendar_metrics.h"
+#include "ash/system/time/calendar_model.h"
 #include "ash/system/unified/unified_system_tray.h"
 #include "ash/system/unified/unified_system_tray_bubble.h"
 #include "ash/wm/float/float_controller.h"
@@ -55,6 +57,10 @@ views::Widget* FindPipWidget() {
 
 }  // namespace
 
+void DumpCalendarModel() {
+  Shell::Get()->system_tray_model()->calendar_model()->DebugDump();
+}
+
 void CycleBackwardMru() {
   Shell::Get()->window_cycle_controller()->HandleCycleWindow(
       WindowCycleController::WindowCyclingDirection::kBackward);

ash/accelerators/accelerator_commands.h

@@ -14,6 +14,9 @@
 namespace ash {
 namespace accelerators {
 
+// Logs a dump of CalendarModel internal data.
+ASH_EXPORT void DumpCalendarModel();
+
 // Cycle backwards in the MRU window list. Usually Alt-Shift-Tab.
 ASH_EXPORT void CycleBackwardMru();
 

ash/accelerators/accelerator_controller_impl.cc

@@ -1891,6 +1891,7 @@ bool AcceleratorControllerImpl::CanPerformAction(
     case DESKS_ACTIVATE_7:
     case DESKS_TOGGLE_ASSIGN_TO_ALL_DESKS:
       return true;
+    case DEBUG_DUMP_CALENDAR_MODEL:
     case DEBUG_KEYBOARD_BACKLIGHT_TOGGLE:
     case DEBUG_MICROPHONE_MUTE_TOGGLE:
     case DEBUG_PRINT_LAYER_HIERARCHY:
@@ -2132,6 +2133,7 @@ void AcceleratorControllerImpl::PerformAction(
     case DESKS_TOGGLE_ASSIGN_TO_ALL_DESKS:
       HandleToggleAssignToAllDesks();
       break;
+    case DEBUG_DUMP_CALENDAR_MODEL:
     case DEBUG_KEYBOARD_BACKLIGHT_TOGGLE:
     case DEBUG_MICROPHONE_MUTE_TOGGLE:
     case DEBUG_PRINT_LAYER_HIERARCHY:

ash/accelerators/accelerator_table.cc

@@ -63,6 +63,7 @@ static_assert(kDeprecatedAcceleratorsLength ==
 
 const AcceleratorData kDebugAcceleratorData[] = {
     {true, ui::VKEY_N, kDebugModifier, TOGGLE_WIFI},
+    {true, ui::VKEY_C, kDebugModifier, DEBUG_DUMP_CALENDAR_MODEL},
     {true, ui::VKEY_X, kDebugModifier, DEBUG_KEYBOARD_BACKLIGHT_TOGGLE},
     {true, ui::VKEY_M, kDebugModifier, DEBUG_MICROPHONE_MUTE_TOGGLE},
     {true, ui::VKEY_O, kDebugModifier, DEBUG_SHOW_TOAST},
@@ -216,6 +217,7 @@ const size_t kActionsAllowedAtPowerMenuLength =
 const AcceleratorAction kActionsAllowedAtModalWindow[] = {
     BRIGHTNESS_DOWN,
     BRIGHTNESS_UP,
+    DEBUG_DUMP_CALENDAR_MODEL,
     DEBUG_KEYBOARD_BACKLIGHT_TOGGLE,
     DEBUG_MICROPHONE_MUTE_TOGGLE,
     DEBUG_TOGGLE_TOUCH_PAD,
@@ -296,6 +298,7 @@ const size_t kRepeatableActionsLength = std::size(kRepeatableActions);
 const AcceleratorAction kActionsAllowedInAppModeOrPinnedMode[] = {
     BRIGHTNESS_DOWN,
     BRIGHTNESS_UP,
+    DEBUG_DUMP_CALENDAR_MODEL,
     DEBUG_KEYBOARD_BACKLIGHT_TOGGLE,
     DEBUG_MICROPHONE_MUTE_TOGGLE,
     DEBUG_PRINT_LAYER_HIERARCHY,
@@ -388,6 +391,7 @@ const size_t kActionsNeedingWindowLength = std::size(kActionsNeedingWindow);
 const AcceleratorAction kActionsKeepingMenuOpen[] = {
     BRIGHTNESS_DOWN,
     BRIGHTNESS_UP,
+    DEBUG_DUMP_CALENDAR_MODEL,
     DEBUG_KEYBOARD_BACKLIGHT_TOGGLE,
     DEBUG_MICROPHONE_MUTE_TOGGLE,
     DEBUG_TOGGLE_TOUCH_PAD,

ash/accelerators/debug_commands.cc

@@ -102,6 +102,10 @@ void HandleToggleWallpaperMode() {
   }
 }
 
+void HandleDumpCalendarModel() {
+  accelerators::DumpCalendarModel();
+}
+
 void HandleToggleKeyboardBacklight() {
   if (ash::features::IsKeyboardBacklightToggleEnabled()) {
     base::RecordAction(base::UserMetricsAction("Accel_Keyboard_Backlight"));
@@ -166,6 +170,9 @@ void PerformDebugActionIfEnabled(AcceleratorAction action) {
     return;
 
   switch (action) {
+    case DEBUG_DUMP_CALENDAR_MODEL:
+      HandleDumpCalendarModel();
+      break;
     case DEBUG_KEYBOARD_BACKLIGHT_TOGGLE:
       HandleToggleKeyboardBacklight();
       break;

ash/constants/ash_features.cc

@@ -252,6 +252,10 @@ const base::Feature kManagedTermsOfService{"ManagedTermsOfService",
 const base::Feature kCalendarView{"CalendarView",
                                   base::FEATURE_DISABLED_BY_DEFAULT};
 
+// Enable or disable debug mode for CalendarModel.
+const base::Feature kCalendarModelDebugMode{"CalendarModelDebugMode",
+                                            base::FEATURE_DISABLED_BY_DEFAULT};
+
 // Controls whether the camera privacy switch toasts and notification should be
 // displayed.
 const base::Feature kCameraPrivacySwitchNotifications{
@@ -1645,6 +1649,10 @@ bool IsCalendarViewEnabled() {
   return base::FeatureList::IsEnabled(kCalendarView);
 }
 
+bool IsCalendarModelDebugModeEnabled() {
+  return base::FeatureList::IsEnabled(kCalendarModelDebugMode);
+}
+
 bool IsCaptureModeSelfieCameraEnabled() {
   return base::FeatureList::IsEnabled(kCaptureModeSelfieCamera);
 }

ash/constants/ash_features.h

@@ -109,6 +109,8 @@ extern const base::Feature kBorealisPermitted;
 COMPONENT_EXPORT(ASH_CONSTANTS)
 extern const base::Feature kCalendarView;
 COMPONENT_EXPORT(ASH_CONSTANTS)
+extern const base::Feature kCalendarModelDebugMode;
+COMPONENT_EXPORT(ASH_CONSTANTS)
 extern const base::Feature kCameraPrivacySwitchNotifications;
 COMPONENT_EXPORT(ASH_CONSTANTS)
 extern const base::Feature kCaptureModeSelfieCamera;
@@ -612,6 +614,7 @@ COMPONENT_EXPORT(ASH_CONSTANTS) bool IsBackgroundBlurEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsBentoBarEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsBluetoothRevampEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsCalendarViewEnabled();
+COMPONENT_EXPORT(ASH_CONSTANTS) bool IsCalendarModelDebugModeEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsCaptureModeSelfieCameraEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsCheckPasswordsAgainstCryptohomeHelperEnabled();
 COMPONENT_EXPORT(ASH_CONSTANTS) bool IsLauncherItemColorSyncEnabled();

ash/public/cpp/accelerators.h

@@ -144,6 +144,7 @@ enum AcceleratorAction {
 
   // Debug accelerators are intentionally at the end, so that if you remove one
   // you don't need to update tests which check hashes of the ids.
+  DEBUG_DUMP_CALENDAR_MODEL,
   DEBUG_KEYBOARD_BACKLIGHT_TOGGLE,
   DEBUG_MICROPHONE_MUTE_TOGGLE,
   DEBUG_PRINT_LAYER_HIERARCHY,

ash/system/time/calendar_event_fetch.cc

@@ -14,6 +14,9 @@
 #include "base/time/tick_clock.h"
 #include "base/time/time.h"
 
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+
 namespace ash {
 
 CalendarEventFetch::CalendarEventFetch(
@@ -31,6 +34,10 @@ CalendarEventFetch::CalendarEventFetch(
 
   const base::Time start_of_next_month =
       calendar_utils::GetStartOfNextMonthUTC(start_of_month);
+
+  if (ash::features::IsCalendarModelDebugModeEnabled())
+    VLOG(1) << "Fetching: " << start_of_month << " => " << start_of_next_month;
+
   client->GetEventList(base::BindOnce(&CalendarEventFetch::OnResultReceived,
                                       weak_factory_.GetWeakPtr()),
                        start_of_month, start_of_next_month);

ash/system/time/calendar_model.cc

@@ -10,6 +10,7 @@
 
 #include "ash/calendar/calendar_client.h"
 #include "ash/calendar/calendar_controller.h"
+#include "ash/constants/ash_features.h"
 #include "ash/shell.h"
 #include "ash/system/time/calendar_event_fetch.h"
 #include "ash/system/time/calendar_utils.h"
@@ -23,6 +24,9 @@
 #include "google_apis/calendar/calendar_api_response_types.h"
 #include "google_apis/common/api_error_codes.h"
 
+#undef ENABLED_VLOG_LEVEL
+#define ENABLED_VLOG_LEVEL 1
+
 namespace {
 
 using ::google_apis::calendar::CalendarEvent;
@@ -255,6 +259,37 @@ void CalendarModel::OnEventsFetched(
     return;
   }
 
+  if (ash::features::IsCalendarModelDebugModeEnabled() && events) {
+    VLOG(1) << __FUNCTION__ << " month " << start_of_month << " num events "
+            << events->items().size();
+
+    // It is possible for incoming events to have a start date (adjusted for
+    // timezone differences) that's not in `start_of_month`. The code below
+    // outputs a breakdown of the events by month.
+    if (events->items().size() > 0) {
+      std::map<base::Time, int> included_months;
+      for (auto& event : events->items()) {
+        base::Time adjusted_start = GetStartTimeAdjusted(event.get());
+        base::Time adjusted_start_of_month =
+            calendar_utils::GetStartOfMonthUTC(adjusted_start);
+        if (included_months.find(adjusted_start_of_month) ==
+            included_months.end()) {
+          included_months[adjusted_start_of_month] = 1;
+        } else {
+          included_months[adjusted_start_of_month]++;
+        }
+      }
+
+      if (included_months.size() > 1) {
+        VLOG(1) << __FUNCTION__ << " breakdown:";
+        for (auto& included_month : included_months) {
+          VLOG(1) << __FUNCTION__ << "   " << included_month.first << " ("
+                  << included_month.second << ")";
+        }
+      }
+    }
+  }
+
   // Keep us within storage limits.
   PruneEventCache();
 
@@ -326,6 +361,11 @@ void CalendarModel::InsertEvent(
   base::Time start_of_month =
       calendar_utils::GetStartOfMonthUTC(GetStartTimeMidnightAdjusted(event));
 
+  if (ash::features::IsCalendarModelDebugModeEnabled()) {
+    VLOG(1) << __FUNCTION__ << " start_of_month " << start_of_month;
+    DebugDumpEventLarge(__FUNCTION__, event);
+  }
+
   auto it = event_months_.find(start_of_month);
   if (it == event_months_.end()) {
     // No events for this month, so add a map for it and insert.
@@ -364,14 +404,27 @@ void CalendarModel::InsertEventInMonth(
   }
 }
 
-base::Time CalendarModel::GetStartTimeMidnightAdjusted(
+base::Time CalendarModel::GetStartTimeAdjusted(
+    const google_apis::calendar::CalendarEvent* event) const {
+  if (time_difference_minutes_.has_value()) {
+    return event->start_time().date_time() +
+           base::Minutes(time_difference_minutes_.value());
+  }
+  return event->start_time().date_time();
+}
+
+base::Time CalendarModel::GetEndTimeAdjusted(
     const google_apis::calendar::CalendarEvent* event) const {
   if (time_difference_minutes_.has_value()) {
-    return (event->start_time().date_time() +
-            base::Minutes(time_difference_minutes_.value()))
-        .UTCMidnight();
+    return event->end_time().date_time() +
+           base::Minutes(time_difference_minutes_.value());
   }
-  return event->start_time().date_time().UTCMidnight();
+  return event->start_time().date_time();
+}
+
+base::Time CalendarModel::GetStartTimeMidnightAdjusted(
+    const google_apis::calendar::CalendarEvent* event) const {
+  return GetStartTimeAdjusted(event).UTCMidnight();
 }
 
 void CalendarModel::InsertEvents(
@@ -431,6 +484,102 @@ CalendarModel::FetchingStatus CalendarModel::FindFetchingStatus(
   return kNever;
 }
 
+void CalendarModel::DebugDumpEventSmall(
+    std::ostringstream* out,
+    const char* prefix,
+    const google_apis::calendar::CalendarEvent* event) {
+  if (!event)
+    return;
+
+  *out << prefix << "      "
+       << calendar_utils::GetTwelveHourClockTime(
+              event->start_time().date_time())
+       << " -> "
+       << calendar_utils::GetTwelveHourClockTime(event->end_time().date_time())
+       << " (" << event->summary().substr(0, 6) << "...)"
+       << "\n";
+}
+
+void CalendarModel::DebugDumpEventLarge(
+    const char* prefix,
+    const google_apis::calendar::CalendarEvent* event) {
+  if (!event)
+    return;
+
+  VLOG(1) << prefix << " ID: " << event->id();
+  VLOG(1) << prefix << "  summary: \"" << event->summary().substr(0, 6)
+          << "...\"";
+  VLOG(1) << prefix << "  st/et: " << event->start_time().date_time() << " => "
+          << event->end_time().date_time();
+  VLOG(1) << prefix << "  (adj): " << GetStartTimeAdjusted(event) << " => "
+          << GetEndTimeAdjusted(event);
+}
+
+void CalendarModel::DebugDumpEvents(std::ostringstream* out,
+                                    const char* prefix) {
+  *out << prefix << " event_months_ START size: " << event_months_.size()
+       << "\n";
+  for (auto& month : event_months_) {
+    *out << prefix << " month: " << month.first << "\n";
+    for (auto& day : month.second) {
+      *out << prefix << "   day: " << day.first << "\n";
+      for (auto it = day.second.begin(); it != day.second.end(); ++it) {
+        google_apis::calendar::CalendarEvent event = *it;
+        DebugDumpEventSmall(out, prefix, &event);
+      }
+    }
+  }
+  *out << prefix << " event_months_ END"
+       << "\n";
+}
+
+void CalendarModel::DebugDumpMruMonths(std::ostringstream* out,
+                                       const char* prefix) {
+  *out << prefix << " mru_months_ START size: " << mru_months_.size() << "\n";
+  for (auto& month : mru_months_) {
+    *out << prefix << "   " << month << "\n";
+  }
+  *out << prefix << " mru_months_ END"
+       << "\n";
+}
+
+void CalendarModel::DebugDumpNonPrunableMonths(std::ostringstream* out,
+                                               const char* prefix) {
+  *out << prefix
+       << " non_prunable_months_ START size: " << non_prunable_months_.size()
+       << "\n";
+  for (auto& month : non_prunable_months_) {
+    *out << prefix << "   " << month << "\n";
+  }
+  *out << prefix << " non_prunable_months_ END"
+       << "\n";
+}
+
+void CalendarModel::DebugDumpMonthsFetched(std::ostringstream* out,
+                                           const char* prefix) {
+  *out << prefix << " months_fetched_ START size: " << months_fetched_.size()
+       << "\n";
+  for (auto& month : months_fetched_) {
+    *out << prefix << "   " << month << "\n";
+  }
+  *out << prefix << " months_fetched_ END"
+       << "\n";
+}
+
+void CalendarModel::DebugDump() {
+  std::ostringstream out;
+  const char* kDebugDumpPrefix = "CalendarModelDump: ";
+  out << __FUNCTION__ << " START"
+      << "\n";
+  DebugDumpEvents(&out, kDebugDumpPrefix);
+  DebugDumpMruMonths(&out, kDebugDumpPrefix);
+  DebugDumpNonPrunableMonths(&out, kDebugDumpPrefix);
+  DebugDumpMonthsFetched(&out, kDebugDumpPrefix);
+  out << __FUNCTION__ << " END"
+      << "\n";
+  VLOG(1) << out.str();
+}
+
 void CalendarModel::RedistributeEvents(int time_difference_minutes) {
   // Early returns if the time difference is not changed.
   if (time_difference_minutes_.has_value() &&