From 112e3c2d049d304b0aa57750fcaa6415ea2b6fef Mon Sep 17 00:00:00 2001
From: Tom Cherry <tomcherry@google.com>
Date: Thu, 23 Jul 2020 09:40:51 -0700
Subject: [PATCH] Log only a summary 'Found stale backup journal' message.

With the goal of reducing log spam, print only a summary 'Found stale
backup journal' messages instead of logging within the inner loop.
Previously, over 12k messages could be printed at a time from this
function.

Before this CL:
 - a backup was scheduled for each packageName from each stale
   journal
 - one (or two, if MORE_DEBUG) message was logged for each
   packageName in each journal file.

After this CL:

 - packageNames are de-duplicated before scheduling backups or logging
   (it's not clear to me whether duplicate packageNames previously
   occurred, in practice).
 - one message is logged for the number (if > 0) of stale journals.
 - one message is logged for the number (including their names, if
   MORE_DEBUG) of packages.

Bug: 161940947
Test: fewer 'Found state backup journal' messages printed
Change-Id: Ia1343e4cea31feb1eba9da561d20736eb5df0a14
---
 .../backup/UserBackupManagerService.java      | 37 ++++++++++++-------
 1 file changed, 23 insertions(+), 14 deletions(-)

diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java
index ff21a733223c0..8c914391d677c 100644
--- a/services/backup/java/com/android/server/backup/UserBackupManagerService.java
+++ b/services/backup/java/com/android/server/backup/UserBackupManagerService.java
@@ -156,6 +156,7 @@ import java.util.Collections;
 import java.util.Date;
 import java.util.HashMap;
 import java.util.HashSet;
+import java.util.LinkedHashSet;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.Objects;
@@ -1154,24 +1155,32 @@ public class UserBackupManagerService {
 
     private void parseLeftoverJournals() {
         ArrayList<DataChangedJournal> journals = DataChangedJournal.listJournals(mJournalDir);
+        // TODO(b/162022005): Fix DataChangedJournal implementing equals() but not hashCode().
+        journals.removeAll(Collections.singletonList(mJournal));
+        if (!journals.isEmpty()) {
+            Slog.i(TAG, addUserIdToLogMessage(mUserId,
+                    "Found " + journals.size() + " stale backup journal(s), scheduling."));
+        }
+        Set<String> packageNames = new LinkedHashSet<>();
         for (DataChangedJournal journal : journals) {
-            if (!journal.equals(mJournal)) {
-                try {
-                    journal.forEach(packageName -> {
-                        Slog.i(
-                                TAG,
-                                addUserIdToLogMessage(
-                                        mUserId, "Found stale backup journal, scheduling"));
-                        if (MORE_DEBUG) {
-                            Slog.i(TAG, addUserIdToLogMessage(mUserId, "  " + packageName));
-                        }
+            try {
+                journal.forEach(packageName -> {
+                    if (packageNames.add(packageName)) {
                         dataChangedImpl(packageName);
-                    });
-                } catch (IOException e) {
-                    Slog.e(TAG, addUserIdToLogMessage(mUserId, "Can't read " + journal), e);
-                }
+                    }
+                });
+            } catch (IOException e) {
+                Slog.e(TAG, addUserIdToLogMessage(mUserId, "Can't read " + journal), e);
             }
         }
+        if (!packageNames.isEmpty()) {
+            String msg = "Stale backup journals: Scheduled " + packageNames.size()
+                    + " package(s) total";
+            if (MORE_DEBUG) {
+                msg += ": " + packageNames;
+            }
+            Slog.i(TAG, addUserIdToLogMessage(mUserId, msg));
+        }
     }
 
     public Set<String> getExcludedRestoreKeys(String packageName) {