Add more instrumentation to BackupManager.

This CL continues work of: ag/1835775 and ag/1870141 adding a few more
logging constans described here:
https://docs.google.com/document/d/1sUboR28LjkT1wRXOwVOV3tLo0qisiCvzxIGmzCVEjbI/edit#

Test: manual

BUG: 34873525
Change-Id: I8c81d8cfea5538e89de94919062eeff6ae09dce4

3 files changed, 85 insertions, 10 deletions

diff --git a/api/system-current.txt b/api/system-current.txt
index e0e2c3570cc8..3e7ef7892fd0 100644
--- a/api/system-current.txt
+++ b/api/system-current.txt
@@ -6942,14 +6942,22 @@ package android.app.backup {
     field public static final java.lang.String EXTRA_LOG_EVENT_ID = "android.app.backup.extra.LOG_EVENT_ID";
     field public static final java.lang.String EXTRA_LOG_EVENT_PACKAGE_NAME = "android.app.backup.extra.LOG_EVENT_PACKAGE_NAME";
     field public static final java.lang.String EXTRA_LOG_EVENT_PACKAGE_VERSION = "android.app.backup.extra.LOG_EVENT_PACKAGE_VERSION";
+    field public static final java.lang.String EXTRA_LOG_OLD_VERSION = "android.app.backup.extra.LOG_OLD_VERSION";
     field public static final int LOG_EVENT_CATEGORY_AGENT = 2; // 0x2
     field public static final int LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY = 3; // 0x3
     field public static final int LOG_EVENT_CATEGORY_TRANSPORT = 1; // 0x1
+    field public static final int LOG_EVENT_ID_APP_HAS_NO_AGENT = 28; // 0x1c
+    field public static final int LOG_EVENT_ID_CANT_FIND_AGENT = 30; // 0x1e
     field public static final int LOG_EVENT_ID_FULL_BACKUP_TIMEOUT = 4; // 0x4
     field public static final int LOG_EVENT_ID_FULL_RESTORE_TIMEOUT = 45; // 0x2d
     field public static final int LOG_EVENT_ID_KEY_VALUE_BACKUP_TIMEOUT = 21; // 0x15
     field public static final int LOG_EVENT_ID_KEY_VALUE_RESTORE_TIMEOUT = 31; // 0x1f
     field public static final int LOG_EVENT_ID_NO_PACKAGES = 49; // 0x31
+    field public static final int LOG_EVENT_ID_NO_RESTORE_METADATA_AVAILABLE = 22; // 0x16
+    field public static final int LOG_EVENT_ID_PACKAGE_NOT_FOUND = 12; // 0xc
+    field public static final int LOG_EVENT_ID_PACKAGE_NOT_PRESENT = 26; // 0x1a
+    field public static final int LOG_EVENT_ID_PACKAGE_TRANSPORT_NOT_PRESENT = 15; // 0xf
+    field public static final int LOG_EVENT_ID_VERSION_OF_BACKUP_OLDER = 36; // 0x24
   }
 
   public abstract class BackupObserver {
diff --git a/core/java/android/app/backup/BackupManagerMonitor.java b/core/java/android/app/backup/BackupManagerMonitor.java
index 099878b310c5..d2a623e0b13a 100644
--- a/core/java/android/app/backup/BackupManagerMonitor.java
+++ b/core/java/android/app/backup/BackupManagerMonitor.java
@@ -54,15 +54,31 @@ public class BackupManagerMonitor {
   public static final String EXTRA_LOG_EVENT_CATEGORY =
           "android.app.backup.extra.LOG_EVENT_CATEGORY";
 
+  /**
+   * string: when we have event of id LOG_EVENT_ID_VERSION_OF_BACKUP_OLDER we send the version
+   * of the backup.
+   */
+  public static final String EXTRA_LOG_OLD_VERSION =
+          "android.app.backup.extra.LOG_OLD_VERSION";
+
   // TODO complete this list with all log messages. And document properly.
   public static final int LOG_EVENT_ID_FULL_BACKUP_TIMEOUT = 4;
+  public static final int LOG_EVENT_ID_PACKAGE_NOT_FOUND = 12;
+  public static final int LOG_EVENT_ID_PACKAGE_TRANSPORT_NOT_PRESENT = 15;
   public static final int LOG_EVENT_ID_KEY_VALUE_BACKUP_TIMEOUT = 21;
+  public static final int LOG_EVENT_ID_NO_RESTORE_METADATA_AVAILABLE = 22;
+  public static final int LOG_EVENT_ID_PACKAGE_NOT_PRESENT = 26;
+  public static final int LOG_EVENT_ID_APP_HAS_NO_AGENT = 28;
+  public static final int LOG_EVENT_ID_CANT_FIND_AGENT = 30;
   public static final int LOG_EVENT_ID_KEY_VALUE_RESTORE_TIMEOUT = 31;
+  public static final int LOG_EVENT_ID_VERSION_OF_BACKUP_OLDER = 36;
   public static final int LOG_EVENT_ID_FULL_RESTORE_TIMEOUT = 45;
   public static final int LOG_EVENT_ID_NO_PACKAGES = 49;
 
 
 
+
+
   /**
    * This method will be called each time something important happens on BackupManager.
    *
diff --git a/services/backup/java/com/android/server/backup/BackupManagerService.java b/services/backup/java/com/android/server/backup/BackupManagerService.java
index 9b55c7acab3a..b459f74eae6c 100644
--- a/services/backup/java/com/android/server/backup/BackupManagerService.java
+++ b/services/backup/java/com/android/server/backup/BackupManagerService.java
@@ -16,6 +16,9 @@
 
 package com.android.server.backup;
 
+import static android.app.backup.BackupManagerMonitor.LOG_EVENT_ID_VERSION_OF_BACKUP_OLDER;
+import static android.app.backup.BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY;
+import static android.app.backup.BackupManagerMonitor.EXTRA_LOG_OLD_VERSION;
 import static android.content.pm.ApplicationInfo.PRIVATE_FLAG_BACKUP_IN_FOREGROUND;
 
 import android.app.ActivityManager;
@@ -2340,7 +2343,7 @@ public class BackupManagerService {
             Slog.e(TAG, "No packages named for backup request");
             sendBackupFinished(observer, BackupManager.ERROR_TRANSPORT_ABORTED);
             monitor = monitorEvent(monitor, BackupManagerMonitor.LOG_EVENT_ID_NO_PACKAGES,
-                    null, BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT);
+                    null, BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT, null);
             throw new IllegalArgumentException("No packages are provided for backup");
         }
 
@@ -3459,6 +3462,9 @@ public class BackupManagerService {
                 // fail repeatedly (i.e. have proved themselves to be buggy).
                 Slog.e(TAG, "Cancel backing up " + mCurrentPackage.packageName);
                 EventLog.writeEvent(EventLogTags.BACKUP_AGENT_FAILURE, mCurrentPackage.packageName);
+                mMonitor = monitorEvent(mMonitor,
+                    BackupManagerMonitor.LOG_EVENT_ID_KEY_VALUE_BACKUP_TIMEOUT,
+                    mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, null);
                 addBackupTrace(
                         "cancel of " + mCurrentPackage.packageName + ", cancelAll=" + cancelAll);
                 errorCleanup();
@@ -4555,6 +4561,11 @@ public class BackupManagerService {
                     mPackages.add(info);
                 } catch (NameNotFoundException e) {
                     Slog.i(TAG, "Requested package " + pkg + " not found; ignoring");
+                    monitor = monitorEvent(monitor,
+                            BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_NOT_FOUND,
+                            mCurrentPackage,
+                            BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY,
+                            null);
                 }
             }
         }
@@ -4638,6 +4649,10 @@ public class BackupManagerService {
                 if (mTransport == null) {
                     Slog.w(TAG, "Transport not present; full data backup not performed");
                     backupRunStatus = BackupManager.ERROR_TRANSPORT_ABORTED;
+                    mMonitor = monitorEvent(mMonitor,
+                            BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_TRANSPORT_NOT_PRESENT,
+                            mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_TRANSPORT,
+                            null);
                     return;
                 }
 
@@ -5148,7 +5163,7 @@ public class BackupManagerService {
 
                 mMonitor = monitorEvent(mMonitor,
                         BackupManagerMonitor.LOG_EVENT_ID_FULL_BACKUP_TIMEOUT,
-                        mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT);
+                        mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, null);
                 mIsCancelled = true;
                 // Cancel tasks spun off by this task.
                 BackupManagerService.this.handleCancel(mEphemeralToken, cancelAll);
@@ -5525,6 +5540,8 @@ public class BackupManagerService {
         // Dedicated observer, if any
         IFullBackupRestoreObserver mObserver;
 
+        IBackupManagerMonitor mMonitor;
+
         // Where we're delivering the file data as we go
         IBackupAgent mAgent;
 
@@ -5606,11 +5623,12 @@ public class BackupManagerService {
         }
 
         public FullRestoreEngine(BackupRestoreTask monitorTask, IFullBackupRestoreObserver observer,
-                PackageInfo onlyPackage, boolean allowApks, boolean allowObbs,
-                int ephemeralOpToken) {
+                IBackupManagerMonitor monitor, PackageInfo onlyPackage, boolean allowApks,
+                boolean allowObbs, int ephemeralOpToken) {
             mEphemeralOpToken = ephemeralOpToken;
             mMonitorTask = monitorTask;
             mObserver = observer;
+            mMonitor = monitor;
             mOnlyPackage = onlyPackage;
             mAllowApks = allowApks;
             mAllowObbs = allowObbs;
@@ -6326,6 +6344,16 @@ public class BackupManagerService {
                                                 } else {
                                                     Slog.i(TAG, "Data requires newer version "
                                                             + version + "; ignoring");
+                                                    ArrayList<Pair<String, String>> list =
+                                                            new ArrayList<>();
+                                                    list.add(new Pair<String, String>(
+                                                            EXTRA_LOG_OLD_VERSION,
+                                                            Integer.toString(version)));
+                                                    mMonitor = monitorEvent(mMonitor,
+                                                            LOG_EVENT_ID_VERSION_OF_BACKUP_OLDER,
+                                                            pkgInfo,
+                                                            LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY,
+                                                            list);
                                                     policy = RestorePolicy.IGNORE;
                                                 }
                                             }
@@ -8461,6 +8489,10 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                 RestoreDescription desc = mTransport.nextRestorePackage();
                 if (desc == null) {
                     Slog.e(TAG, "No restore metadata available; halting");
+                    mMonitor = monitorEvent(mMonitor,
+                            BackupManagerMonitor.LOG_EVENT_ID_NO_RESTORE_METADATA_AVAILABLE,
+                            mCurrentPackage,
+                            BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, null);
                     mStatus = BackupTransport.TRANSPORT_ERROR;
                     executeNextState(UnifiedRestoreState.FINAL);
                     return;
@@ -8562,6 +8594,11 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                     // Whoops, we thought we could restore this package but it
                     // turns out not to be present.  Skip it.
                     Slog.e(TAG, "Package not present: " + pkgName);
+                    mMonitor = monitorEvent(mMonitor,
+                            BackupManagerMonitor.LOG_EVENT_ID_PACKAGE_NOT_PRESENT,
+                            mCurrentPackage,
+                            BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY,
+                            null);
                     EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, pkgName,
                             "Package missing on device");
                     nextState = UnifiedRestoreState.RUNNING_QUEUE;
@@ -8631,6 +8668,9 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                     Slog.i(TAG, "Data exists for package " + packageName
                             + " but app has no agent; skipping");
                 }
+                mMonitor = monitorEvent(mMonitor,
+                        BackupManagerMonitor.LOG_EVENT_ID_APP_HAS_NO_AGENT, mCurrentPackage,
+                        BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, null);
                 EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, packageName,
                         "Package has no agent");
                 executeNextState(UnifiedRestoreState.RUNNING_QUEUE);
@@ -8652,6 +8692,9 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                     ApplicationThreadConstants.BACKUP_MODE_INCREMENTAL);
             if (mAgent == null) {
                 Slog.w(TAG, "Can't find backup agent for " + packageName);
+                mMonitor = monitorEvent(mMonitor,
+                        BackupManagerMonitor.LOG_EVENT_ID_CANT_FIND_AGENT, mCurrentPackage,
+                        BackupManagerMonitor.LOG_EVENT_CATEGORY_BACKUP_MANAGER_POLICY, null);
                 EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE, packageName,
                         "Restore agent missing");
                 executeNextState(UnifiedRestoreState.RUNNING_QUEUE);
@@ -8857,7 +8900,7 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                 EventLog.writeEvent(EventLogTags.FULL_RESTORE_PACKAGE,
                         mCurrentPackage.packageName);
 
-                mEngine = new FullRestoreEngine(this, null, mCurrentPackage, false, false, mEphemeralOpToken);
+                mEngine = new FullRestoreEngine(this, null, mMonitor, mCurrentPackage, false, false, mEphemeralOpToken);
                 mEngineThread = new EngineThread(mEngine, mEnginePipes[0]);
 
                 ParcelFileDescriptor eWriteEnd = mEnginePipes[1];
@@ -9001,8 +9044,10 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                 if (DEBUG) {
                     Slog.w(TAG, "Full-data restore target timed out; shutting down");
                 }
-                mMonitor = monitorEvent(mMonitor, BackupManagerMonitor.LOG_EVENT_ID_FULL_RESTORE_TIMEOUT,
-                        mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT);
+
+                mMonitor = monitorEvent(mMonitor,
+                        BackupManagerMonitor.LOG_EVENT_ID_FULL_RESTORE_TIMEOUT,
+                        mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, null);
                 mEngineThread.handleTimeout();
 
                 IoUtils.closeQuietly(mEnginePipes[1]);
@@ -9245,8 +9290,9 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
         public void handleCancel(boolean cancelAll) {
             removeOperation(mEphemeralOpToken);
             Slog.e(TAG, "Timeout restoring application " + mCurrentPackage.packageName);
-            mMonitor = monitorEvent(mMonitor, BackupManagerMonitor.LOG_EVENT_ID_KEY_VALUE_RESTORE_TIMEOUT,
-                    mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT);
+            mMonitor = monitorEvent(mMonitor,
+                    BackupManagerMonitor.LOG_EVENT_ID_KEY_VALUE_RESTORE_TIMEOUT,
+                    mCurrentPackage, BackupManagerMonitor.LOG_EVENT_CATEGORY_AGENT, null);
             EventLog.writeEvent(EventLogTags.RESTORE_AGENT_FAILURE,
                     mCurrentPackage.packageName, "restore timeout");
             // Handle like an agent that threw on invocation: wipe it and go on to the next
@@ -10913,7 +10959,7 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
     }
 
     private static IBackupManagerMonitor monitorEvent(IBackupManagerMonitor monitor, int id,
-            PackageInfo pkg, int category) {
+            PackageInfo pkg, int category, ArrayList<Pair<String, String>> extras) {
         if (monitor != null) {
             try {
                 Bundle bundle = new Bundle();
@@ -10925,6 +10971,11 @@ if (MORE_DEBUG) Slog.v(TAG, "   + got " + nRead + "; now wanting " + (size - soF
                     bundle.putInt(BackupManagerMonitor.EXTRA_LOG_EVENT_PACKAGE_VERSION,
                             pkg.versionCode);
                 }
+                if (extras != null) {
+                    for (Pair<String,String> pair : extras) {
+                        bundle.putString(pair.first, pair.second);
+                    }
+                }
                 monitor.onEvent(bundle);
                 return monitor;
             } catch(RemoteException e) {