diff options
author | Al Sutton <alsutton@google.com> | 2020-03-17 16:47:35 +0000 |
---|---|---|
committer | Al Sutton <alsutton@google.com> | 2020-03-18 11:59:47 +0000 |
commit | c4d9e91f85cd48fc8c6f0446e0703f40e23cd5d8 (patch) | |
tree | c7a1118a2aea3f90a493fdb7dbcf08ed300a6346 | |
parent | a8a123c1eac5efd372d08084e95dada5a9cf0a97 (diff) |
Add userId to log messages - DO NOT MERGE
Add the user ID so it's easier to see which user log messages refer to.
There's a bit of churn around conditionals in this to ensure that the
code complies with the style guidelines.
Fixes: 148376687
Test: make RunBackupFrameworksServicesRoboTests
Change-Id: I3ca92d21492fae4b89cb73fb39db1a490c796f5d
-rw-r--r-- | services/backup/java/com/android/server/backup/UserBackupManagerService.java | 964 | ||||
-rw-r--r-- | services/robotests/backup/src/com/android/server/backup/testing/BackupManagerServiceTestUtils.java | 2 |
2 files changed, 743 insertions, 223 deletions
diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java index 6247a635233a..69154b49c96f 100644 --- a/services/backup/java/com/android/server/backup/UserBackupManagerService.java +++ b/services/backup/java/com/android/server/backup/UserBackupManagerService.java @@ -157,7 +157,6 @@ import java.util.HashMap; import java.util.HashSet; import java.util.LinkedList; import java.util.List; -import java.util.Map; import java.util.Objects; import java.util.Queue; import java.util.Random; @@ -174,29 +173,47 @@ public class UserBackupManagerService { public static class BackupWakeLock { private final PowerManager.WakeLock mPowerManagerWakeLock; private boolean mHasQuit = false; + private int mUserId; - public BackupWakeLock(PowerManager.WakeLock powerManagerWakeLock) { + public BackupWakeLock(PowerManager.WakeLock powerManagerWakeLock, int userId) { mPowerManagerWakeLock = powerManagerWakeLock; + mUserId = userId; } /** Acquires the {@link PowerManager.WakeLock} if hasn't been quit. */ public synchronized void acquire() { if (mHasQuit) { - Slog.v(TAG, "Ignore wakelock acquire after quit: " + mPowerManagerWakeLock.getTag()); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "Ignore wakelock acquire after quit: " + + mPowerManagerWakeLock.getTag())); return; } mPowerManagerWakeLock.acquire(); - Slog.v(TAG, "Acquired wakelock:" + mPowerManagerWakeLock.getTag()); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Acquired wakelock:" + mPowerManagerWakeLock.getTag())); } /** Releases the {@link PowerManager.WakeLock} if hasn't been quit. */ public synchronized void release() { if (mHasQuit) { - Slog.v(TAG, "Ignore wakelock release after quit: " + mPowerManagerWakeLock.getTag()); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "Ignore wakelock release after quit: " + + mPowerManagerWakeLock.getTag())); return; } mPowerManagerWakeLock.release(); - Slog.v(TAG, "Released wakelock:" + mPowerManagerWakeLock.getTag()); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Released wakelock:" + mPowerManagerWakeLock.getTag())); } /** @@ -209,7 +226,10 @@ public class UserBackupManagerService { /** Release the {@link PowerManager.WakeLock} till it isn't held. */ public synchronized void quit() { while (mPowerManagerWakeLock.isHeld()) { - Slog.v(TAG, "Releasing wakelock: " + mPowerManagerWakeLock.getTag()); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Releasing wakelock: " + mPowerManagerWakeLock.getTag())); mPowerManagerWakeLock.release(); } mHasQuit = true; @@ -439,7 +459,9 @@ public class UserBackupManagerService { } if (DEBUG) { - Slog.v(TAG, "Starting with transport " + currentTransport); + Slog.v( + TAG, + addUserIdToLogMessage(userId, "Starting with transport " + currentTransport)); } TransportManager transportManager = new TransportManager(userId, context, transportWhitelist, currentTransport); @@ -451,7 +473,9 @@ public class UserBackupManagerService { new HandlerThread("backup-" + userId, Process.THREAD_PRIORITY_BACKGROUND); userBackupThread.start(); if (DEBUG) { - Slog.d(TAG, "Started thread " + userBackupThread.getName() + " for user " + userId); + Slog.d( + TAG, + addUserIdToLogMessage(userId, "Started thread " + userBackupThread.getName())); } return createAndInitializeService( @@ -556,7 +580,10 @@ public class UserBackupManagerService { if (userId == UserHandle.USER_SYSTEM) { mBaseStateDir.mkdirs(); if (!SELinux.restorecon(mBaseStateDir)) { - Slog.w(TAG, "SELinux restorecon failed on " + mBaseStateDir); + Slog.w( + TAG, + addUserIdToLogMessage( + userId, "SELinux restorecon failed on " + mBaseStateDir)); } } @@ -604,7 +631,8 @@ public class UserBackupManagerService { addPackageParticipantsLocked(null); } - mTransportManager = Objects.requireNonNull(transportManager, "transportManager cannot be null"); + mTransportManager = + Objects.requireNonNull(transportManager, "transportManager cannot be null"); mTransportManager.setOnTransportRegisteredListener(this::onTransportRegistered); mRegisterTransportsRequestedTime = SystemClock.elapsedRealtime(); mBackupHandler.postDelayed( @@ -620,7 +648,7 @@ public class UserBackupManagerService { mWakelock = new BackupWakeLock( mPowerManager.newWakeLock( PowerManager.PARTIAL_WAKE_LOCK, - "*backup*-" + userId + "-" + userBackupThread.getThreadId())); + "*backup*-" + userId + "-" + userBackupThread.getThreadId()), userId); // Set up the various sorts of package tracking we do mFullBackupScheduleFile = new File(mBaseStateDir, "fb-schedule"); @@ -869,7 +897,7 @@ public class UserBackupManagerService { } private void initPackageTracking() { - if (MORE_DEBUG) Slog.v(TAG, "` tracking"); + if (MORE_DEBUG) Slog.v(TAG, addUserIdToLogMessage(mUserId, "` tracking")); // Remember our ancestral dataset mTokenFile = new File(mBaseStateDir, "ancestral"); @@ -891,9 +919,9 @@ public class UserBackupManagerService { } } catch (FileNotFoundException fnf) { // Probably innocuous - Slog.v(TAG, "No ancestral data"); + Slog.v(TAG, addUserIdToLogMessage(mUserId, "No ancestral data")); } catch (IOException e) { - Slog.w(TAG, "Unable to read token file", e); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "Unable to read token file"), e); } mProcessedPackagesJournal = new ProcessedPackagesJournal(mBaseStateDir); @@ -941,7 +969,10 @@ public class UserBackupManagerService { DataInputStream in = new DataInputStream(bufStream)) { int version = in.readInt(); if (version != SCHEDULE_FILE_VERSION) { - Slog.e(TAG, "Unknown backup schedule version " + version); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, "Unknown backup schedule version " + version)); return null; } @@ -966,14 +997,14 @@ public class UserBackupManagerService { schedule.add(new FullBackupEntry(pkgName, lastBackup)); } else { if (DEBUG) { - Slog.i(TAG, "Package " + pkgName - + " no longer eligible for full backup"); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Package " + pkgName + + " no longer eligible for full backup")); } } } catch (NameNotFoundException e) { if (DEBUG) { - Slog.i(TAG, "Package " + pkgName - + " not installed; dropping from full backup"); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Package " + pkgName + + " not installed; dropping from full backup")); } } } @@ -986,7 +1017,13 @@ public class UserBackupManagerService { mUserId)) { if (!foundApps.contains(app.packageName)) { if (MORE_DEBUG) { - Slog.i(TAG, "New full backup app " + app.packageName + " found"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "New full backup app " + + app.packageName + + " found")); } schedule.add(new FullBackupEntry(app.packageName, 0)); changed = true; @@ -996,7 +1033,7 @@ public class UserBackupManagerService { Collections.sort(schedule); } catch (Exception e) { - Slog.e(TAG, "Unable to read backup schedule", e); + Slog.e(TAG, addUserIdToLogMessage(mUserId, "Unable to read backup schedule"), e); mFullBackupScheduleFile.delete(); schedule = null; } @@ -1052,7 +1089,11 @@ public class UserBackupManagerService { out.write(bufStream.toByteArray()); af.finishWrite(out); } catch (Exception e) { - Slog.e(TAG, "Unable to write backup schedule!", e); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, "Unable to write backup schedule!"), + e); } } } @@ -1069,12 +1110,17 @@ public class UserBackupManagerService { if (!journal.equals(mJournal)) { try { journal.forEach(packageName -> { - Slog.i(TAG, "Found stale backup journal, scheduling"); - if (MORE_DEBUG) Slog.i(TAG, " " + packageName); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Found stale backup journal, scheduling")); + if (MORE_DEBUG) { + Slog.i(TAG, addUserIdToLogMessage(mUserId, " " + packageName)); + } dataChangedImpl(packageName); }); } catch (IOException e) { - Slog.e(TAG, "Can't read " + journal, e); + Slog.e(TAG, addUserIdToLogMessage(mUserId, "Can't read " + journal), e); } } } @@ -1114,7 +1160,14 @@ public class UserBackupManagerService { boolean isPending, String transportName, String transportDirName) { synchronized (mQueueLock) { if (MORE_DEBUG) { - Slog.i(TAG, "recordInitPending(" + isPending + ") on transport " + transportName); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "recordInitPending(" + + isPending + + ") on transport " + + transportName)); } File stateDir = new File(mBaseStateDir, transportDirName); @@ -1175,8 +1228,17 @@ public class UserBackupManagerService { private void onTransportRegistered(String transportName, String transportDirName) { if (DEBUG) { long timeMs = SystemClock.elapsedRealtime() - mRegisterTransportsRequestedTime; - Slog.d(TAG, "Transport " + transportName + " registered " + timeMs - + "ms after first request (delay = " + INITIALIZATION_DELAY_MILLIS + "ms)"); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "Transport " + + transportName + + " registered " + + timeMs + + "ms after first request (delay = " + + INITIALIZATION_DELAY_MILLIS + + "ms)")); } File stateDir = new File(mBaseStateDir, transportDirName); @@ -1202,7 +1264,7 @@ public class UserBackupManagerService { private BroadcastReceiver mPackageTrackingReceiver = new BroadcastReceiver() { public void onReceive(Context context, Intent intent) { if (MORE_DEBUG) { - Slog.d(TAG, "Received broadcast " + intent); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Received broadcast " + intent)); } String action = intent.getAction(); @@ -1222,24 +1284,33 @@ public class UserBackupManagerService { String packageName = uri.getSchemeSpecificPart(); if (packageName != null) { - packageList = new String[]{packageName}; + packageList = new String[] {packageName}; } changed = Intent.ACTION_PACKAGE_CHANGED.equals(action); if (changed) { // Look at new transport states for package changed events. String[] components = - intent.getStringArrayExtra(Intent.EXTRA_CHANGED_COMPONENT_NAME_LIST); + intent.getStringArrayExtra( + Intent.EXTRA_CHANGED_COMPONENT_NAME_LIST); if (MORE_DEBUG) { - Slog.i(TAG, "Package " + packageName + " changed"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Package " + packageName + " changed")); for (int i = 0; i < components.length; i++) { - Slog.i(TAG, " * " + components[i]); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, " * " + components[i])); } } mBackupHandler.post( - () -> mTransportManager.onPackageChanged(packageName, components)); + () -> + mTransportManager.onPackageChanged( + packageName, components)); return; } @@ -1261,7 +1332,8 @@ public class UserBackupManagerService { if (added) { synchronized (mBackupParticipants) { if (replacing) { - // Remove the entry under the old uid and fall through to re-add. If an app + // Remove the entry under the old uid and fall through to re-add. If + // an app // just opted into key/value backup, add it as a known participant. removePackageParticipantsLocked(packageList, uid); } @@ -1275,13 +1347,15 @@ public class UserBackupManagerService { mPackageManager.getPackageInfoAsUser( packageName, /* flags */ 0, mUserId); if (AppBackupUtils.appGetsFullBackup(app) - && AppBackupUtils.appIsEligibleForBackup(app.applicationInfo, - mUserId)) { + && AppBackupUtils.appIsEligibleForBackup( + app.applicationInfo, mUserId)) { enqueueFullBackup(packageName, now); scheduleNextFullBackupJob(0); } else { - // The app might have just transitioned out of full-data into doing - // key/value backups, or might have just disabled backups entirely. Make + // The app might have just transitioned out of full-data into + // doing + // key/value backups, or might have just disabled backups + // entirely. Make // sure it is no longer in the full-data queue. synchronized (mQueueLock) { dequeueFullBackupLocked(packageName); @@ -1293,17 +1367,23 @@ public class UserBackupManagerService { () -> mTransportManager.onPackageAdded(packageName)); } catch (NameNotFoundException e) { if (DEBUG) { - Slog.w(TAG, "Can't resolve new app " + packageName); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Can't resolve new app " + packageName)); } } } - // Whenever a package is added or updated we need to update the package metadata + // Whenever a package is added or updated we need to update the package + // metadata // bookkeeping. dataChangedImpl(PACKAGE_MANAGER_SENTINEL); } else { if (!replacing) { - // Outright removal. In the full-data case, the app will be dropped from the + // Outright removal. In the full-data case, the app will be dropped from + // the // queue when its (now obsolete) name comes up again for backup. synchronized (mBackupParticipants) { removePackageParticipantsLocked(packageList, uid); @@ -1324,12 +1404,19 @@ public class UserBackupManagerService { // Look for apps that define the android:backupAgent attribute List<PackageInfo> targetApps = allAgentPackages(); if (packageNames != null) { - if (MORE_DEBUG) Slog.v(TAG, "addPackageParticipantsLocked: #" + packageNames.length); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "addPackageParticipantsLocked: #" + packageNames.length)); + } for (String packageName : packageNames) { addPackageParticipantsLockedInner(packageName, targetApps); } } else { - if (MORE_DEBUG) Slog.v(TAG, "addPackageParticipantsLocked: all"); + if (MORE_DEBUG) { + Slog.v(TAG, addUserIdToLogMessage(mUserId, "addPackageParticipantsLocked: all")); + } addPackageParticipantsLockedInner(null, targetApps); } } @@ -1337,7 +1424,10 @@ public class UserBackupManagerService { private void addPackageParticipantsLockedInner(String packageName, List<PackageInfo> targetPkgs) { if (MORE_DEBUG) { - Slog.v(TAG, "Examining " + packageName + " for backup agent"); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Examining " + packageName + " for backup agent")); } for (PackageInfo pkg : targetPkgs) { @@ -1349,10 +1439,15 @@ public class UserBackupManagerService { mBackupParticipants.put(uid, set); } set.add(pkg.packageName); - if (MORE_DEBUG) Slog.v(TAG, "Agent found; added"); + if (MORE_DEBUG) Slog.v(TAG, addUserIdToLogMessage(mUserId, "Agent found; added")); // Schedule a backup for it on general principles - if (MORE_DEBUG) Slog.i(TAG, "Scheduling backup for new app " + pkg.packageName); + if (MORE_DEBUG) { + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Scheduling backup for new app " + pkg.packageName)); + } Message msg = mBackupHandler .obtainMessage(MSG_SCHEDULE_BACKUP_PACKAGE, pkg.packageName); mBackupHandler.sendMessage(msg); @@ -1363,13 +1458,19 @@ public class UserBackupManagerService { // Remove the given packages' entries from our known active set. private void removePackageParticipantsLocked(String[] packageNames, int oldUid) { if (packageNames == null) { - Slog.w(TAG, "removePackageParticipants with null list"); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "removePackageParticipants with null list")); return; } if (MORE_DEBUG) { - Slog.v(TAG, "removePackageParticipantsLocked: uid=" + oldUid - + " #" + packageNames.length); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "removePackageParticipantsLocked: uid=" + + oldUid + + " #" + + packageNames.length)); } for (String pkg : packageNames) { // Known previous UID, so we know which package set to check @@ -1377,7 +1478,12 @@ public class UserBackupManagerService { if (set != null && set.contains(pkg)) { removePackageFromSetLocked(set, pkg); if (set.isEmpty()) { - if (MORE_DEBUG) Slog.v(TAG, " last one of this uid; purging set"); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, " last one of this uid; purging set")); + } mBackupParticipants.remove(oldUid); } } @@ -1393,7 +1499,11 @@ public class UserBackupManagerService { // Note that we deliberately leave it 'known' in the "ever backed up" // bookkeeping so that its current-dataset data will be retrieved // if the app is subsequently reinstalled - if (MORE_DEBUG) Slog.v(TAG, " removing participant " + packageName); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage(mUserId, " removing participant " + packageName)); + } set.remove(packageName); mPendingBackups.remove(packageName); } @@ -1467,14 +1577,19 @@ public class UserBackupManagerService { af.writeInt(-1); } else { af.writeInt(mAncestralPackages.size()); - if (DEBUG) Slog.v(TAG, "Ancestral packages: " + mAncestralPackages.size()); + if (DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Ancestral packages: " + mAncestralPackages.size())); + } for (String pkgName : mAncestralPackages) { af.writeUTF(pkgName); - if (MORE_DEBUG) Slog.v(TAG, " " + pkgName); + if (MORE_DEBUG) Slog.v(TAG, addUserIdToLogMessage(mUserId, " " + pkgName)); } } } catch (IOException e) { - Slog.w(TAG, "Unable to write token file:", e); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "Unable to write token file:"), e); } } @@ -1487,7 +1602,7 @@ public class UserBackupManagerService { mConnectedAgent = null; try { if (mActivityManager.bindBackupAgent(app.packageName, mode, mUserId)) { - Slog.d(TAG, "awaiting agent for " + app); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "awaiting agent for " + app)); // success; wait for the agent to arrive // only wait 10 seconds for the bind to happen @@ -1498,7 +1613,7 @@ public class UserBackupManagerService { mAgentConnectLock.wait(5000); } catch (InterruptedException e) { // just bail - Slog.w(TAG, "Interrupted: " + e); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "Interrupted: " + e)); mConnecting = false; mConnectedAgent = null; } @@ -1506,10 +1621,14 @@ public class UserBackupManagerService { // if we timed out with no connect, abort and move on if (mConnecting) { - Slog.w(TAG, "Timeout waiting for agent " + app); + Slog.w( + TAG, + addUserIdToLogMessage(mUserId, "Timeout waiting for agent " + app)); mConnectedAgent = null; } - if (DEBUG) Slog.i(TAG, "got agent " + mConnectedAgent); + if (DEBUG) { + Slog.i(TAG, addUserIdToLogMessage(mUserId, "got agent " + mConnectedAgent)); + } agent = mConnectedAgent; } } catch (RemoteException e) { @@ -1575,13 +1694,20 @@ public class UserBackupManagerService { if (!shouldClearData) { if (MORE_DEBUG) { - Slog.i(TAG, "Clearing app data is not allowed so not wiping " - + packageName); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Clearing app data is not allowed so not wiping " + + packageName)); } return; } } catch (NameNotFoundException e) { - Slog.w(TAG, "Tried to clear data for " + packageName + " but not found"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Tried to clear data for " + packageName + " but not found")); return; } @@ -1604,13 +1730,22 @@ public class UserBackupManagerService { } catch (InterruptedException e) { // won't happen, but still. mClearingData = false; - Slog.w(TAG, "Interrupted while waiting for " + packageName - + " data to be cleared", e); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Interrupted while waiting for " + + packageName + + " data to be cleared"), + e); } } if (mClearingData) { - Slog.w(TAG, "Clearing app data for " + packageName + " timed out"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Clearing app data for " + packageName + " timed out")); } } } @@ -1627,12 +1762,17 @@ public class UserBackupManagerService { synchronized (mQueueLock) { if (mCurrentToken != 0 && mProcessedPackagesJournal.hasBeenProcessed(packageName)) { if (MORE_DEBUG) { - Slog.i(TAG, "App in ever-stored, so using current token"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "App in ever-stored, so using current token")); } token = mCurrentToken; } } - if (MORE_DEBUG) Slog.i(TAG, "getAvailableRestoreToken() == " + token); + if (MORE_DEBUG) { + Slog.i(TAG, addUserIdToLogMessage(mUserId, "getAvailableRestoreToken() == " + token)); + } return token; } @@ -1654,7 +1794,7 @@ public class UserBackupManagerService { mContext.enforceCallingPermission(android.Manifest.permission.BACKUP, "requestBackup"); if (packages == null || packages.length < 1) { - Slog.e(TAG, "No packages named for backup request"); + Slog.e(TAG, addUserIdToLogMessage(mUserId, "No packages named for backup request")); BackupObserverUtils.sendBackupFinished(observer, BackupManager.ERROR_TRANSPORT_ABORTED); monitor = BackupManagerMonitorUtils.monitorEvent(monitor, BackupManagerMonitor.LOG_EVENT_ID_NO_PACKAGES, @@ -1665,10 +1805,10 @@ public class UserBackupManagerService { if (!mEnabled || !mSetupComplete) { Slog.i( TAG, - "Backup requested but enabled=" + addUserIdToLogMessage(mUserId, "Backup requested but enabled=" + mEnabled + " setupComplete=" - + mSetupComplete); + + mSetupComplete)); BackupObserverUtils.sendBackupFinished(observer, BackupManager.ERROR_BACKUP_NOT_ALLOWED); final int logTag = mSetupComplete @@ -1726,9 +1866,17 @@ public class UserBackupManagerService { EventLog.writeEvent(EventLogTags.BACKUP_REQUESTED, packages.length, kvBackupList.size(), fullBackupList.size()); if (MORE_DEBUG) { - Slog.i(TAG, "Backup requested for " + packages.length + " packages, of them: " - + fullBackupList.size() + " full backups, " + kvBackupList.size() - + " k/v backups"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Backup requested for " + + packages.length + + " packages, of them: " + + fullBackupList.size() + + " full backups, " + + kvBackupList.size() + + " k/v backups")); } boolean nonIncrementalBackup = (flags & BackupManager.FLAG_NON_INCREMENTAL_BACKUP) != 0; @@ -1744,7 +1892,7 @@ public class UserBackupManagerService { public void cancelBackups() { mContext.enforceCallingPermission(android.Manifest.permission.BACKUP, "cancelBackups"); if (MORE_DEBUG) { - Slog.i(TAG, "cancelBackups() called."); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "cancelBackups() called.")); } final long oldToken = Binder.clearCallingIdentity(); try { @@ -1774,13 +1922,27 @@ public class UserBackupManagerService { public void prepareOperationTimeout(int token, long interval, BackupRestoreTask callback, int operationType) { if (operationType != OP_TYPE_BACKUP_WAIT && operationType != OP_TYPE_RESTORE_WAIT) { - Slog.wtf(TAG, "prepareOperationTimeout() doesn't support operation " - + Integer.toHexString(token) + " of type " + operationType); + Slog.wtf( + TAG, + addUserIdToLogMessage( + mUserId, + "prepareOperationTimeout() doesn't support operation " + + Integer.toHexString(token) + + " of type " + + operationType)); return; } if (MORE_DEBUG) { - Slog.v(TAG, "starting timeout: token=" + Integer.toHexString(token) - + " interval=" + interval + " callback=" + callback); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "starting timeout: token=" + + Integer.toHexString(token) + + " interval=" + + interval + + " callback=" + + callback)); } synchronized (mCurrentOpLock) { @@ -1798,8 +1960,12 @@ public class UserBackupManagerService { case OP_TYPE_RESTORE_WAIT: return MSG_RESTORE_OPERATION_TIMEOUT; default: - Slog.wtf(TAG, "getMessageIdForOperationType called on invalid operation type: " - + operationType); + Slog.wtf( + TAG, + addUserIdToLogMessage( + mUserId, + "getMessageIdForOperationType called on invalid operation type: " + + operationType)); return -1; } } @@ -1810,8 +1976,14 @@ public class UserBackupManagerService { */ public void putOperation(int token, Operation operation) { if (MORE_DEBUG) { - Slog.d(TAG, "Adding operation token=" + Integer.toHexString(token) + ", operation type=" - + operation.type); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "Adding operation token=" + + Integer.toHexString(token) + + ", operation type=" + + operation.type)); } synchronized (mCurrentOpLock) { mCurrentOperations.put(token, operation); @@ -1824,12 +1996,15 @@ public class UserBackupManagerService { */ public void removeOperation(int token) { if (MORE_DEBUG) { - Slog.d(TAG, "Removing operation token=" + Integer.toHexString(token)); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Removing operation token=" + Integer.toHexString(token))); } synchronized (mCurrentOpLock) { if (mCurrentOperations.get(token) == null) { - Slog.w(TAG, "Duplicate remove for operation. token=" - + Integer.toHexString(token)); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "Duplicate remove for operation. token=" + + Integer.toHexString(token))); } mCurrentOperations.remove(token); } @@ -1838,8 +2013,8 @@ public class UserBackupManagerService { /** Block until we received an operation complete message (from the agent or cancellation). */ public boolean waitUntilOperationComplete(int token) { if (MORE_DEBUG) { - Slog.i(TAG, "Blocking until operation complete for " - + Integer.toHexString(token)); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Blocking until operation complete for " + + Integer.toHexString(token))); } int finalState = OP_PENDING; Operation op = null; @@ -1858,8 +2033,12 @@ public class UserBackupManagerService { // When the wait is notified we loop around and recheck the current state } else { if (MORE_DEBUG) { - Slog.d(TAG, "Unblocked waiting for operation token=" - + Integer.toHexString(token)); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "Unblocked waiting for operation token=" + + Integer.toHexString(token))); } // No longer pending; we're done finalState = op.state; @@ -1874,8 +2053,8 @@ public class UserBackupManagerService { mBackupHandler.removeMessages(getMessageIdForOperationType(op.type)); } if (MORE_DEBUG) { - Slog.v(TAG, "operation " + Integer.toHexString(token) - + " complete: finalState=" + finalState); + Slog.v(TAG, addUserIdToLogMessage(mUserId, "operation " + Integer.toHexString(token) + + " complete: finalState=" + finalState)); } return finalState == OP_ACKNOWLEDGED; } @@ -1888,21 +2067,31 @@ public class UserBackupManagerService { op = mCurrentOperations.get(token); if (MORE_DEBUG) { if (op == null) { - Slog.w(TAG, "Cancel of token " + Integer.toHexString(token) - + " but no op found"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Cancel of token " + + Integer.toHexString(token) + + " but no op found")); } } int state = (op != null) ? op.state : OP_TIMEOUT; if (state == OP_ACKNOWLEDGED) { // The operation finished cleanly, so we have nothing more to do. if (DEBUG) { - Slog.w(TAG, "Operation already got an ack." - + "Should have been removed from mCurrentOperations."); + Slog.w(TAG, addUserIdToLogMessage(mUserId, "Operation already got an ack." + + "Should have been removed from mCurrentOperations.")); } op = null; mCurrentOperations.delete(token); } else if (state == OP_PENDING) { - if (DEBUG) Slog.v(TAG, "Cancel: token=" + Integer.toHexString(token)); + if (DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Cancel: token=" + Integer.toHexString(token))); + } op.state = OP_TIMEOUT; // Can't delete op from mCurrentOperations here. waitUntilOperationComplete may be // called after we receive cancel here. We need this op's state there. @@ -1920,7 +2109,7 @@ public class UserBackupManagerService { // If there's a TimeoutHandler for this event, call it if (op != null && op.callback != null) { if (MORE_DEBUG) { - Slog.v(TAG, " Invoking cancel on " + op.callback); + Slog.v(TAG, addUserIdToLogMessage(mUserId, " Invoking cancel on " + op.callback)); } op.callback.handleCancel(cancelAll); } @@ -1955,13 +2144,20 @@ public class UserBackupManagerService { // manifest flag! TODO something less direct. if (!UserHandle.isCore(app.uid) && !app.packageName.equals("com.android.backupconfirm")) { - if (MORE_DEBUG) Slog.d(TAG, "Killing agent host process"); + if (MORE_DEBUG) { + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Killing agent host process")); + } mActivityManager.killApplicationProcess(app.processName, app.uid); } else { - if (MORE_DEBUG) Slog.d(TAG, "Not killing after operation: " + app.processName); + if (MORE_DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Not killing after operation: " + app.processName)); + } } } catch (RemoteException e) { - Slog.d(TAG, "Lost app trying to shut down"); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Lost app trying to shut down")); } } @@ -1975,7 +2171,12 @@ public class UserBackupManagerService { } catch (Exception e) { // If we can't talk to the storagemanager service we have a serious problem; fail // "secure" i.e. assuming that the device is encrypted. - Slog.e(TAG, "Unable to communicate with storagemanager service: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unable to communicate with storagemanager service: " + + e.getMessage())); return true; } } @@ -1999,7 +2200,10 @@ public class UserBackupManagerService { FullBackupJob.schedule(mUserId, mContext, latency, mConstants); } else { if (DEBUG_SCHEDULING) { - Slog.i(TAG, "Full backup queue empty; not scheduling"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Full backup queue empty; not scheduling")); } } } @@ -2054,7 +2258,10 @@ public class UserBackupManagerService { private boolean fullBackupAllowable(String transportName) { if (!mTransportManager.isTransportRegistered(transportName)) { - Slog.w(TAG, "Transport not registered; full data backup not performed"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Transport not registered; full data backup not performed")); return false; } @@ -2066,12 +2273,19 @@ public class UserBackupManagerService { File pmState = new File(stateDir, PACKAGE_MANAGER_SENTINEL); if (pmState.length() <= 0) { if (DEBUG) { - Slog.i(TAG, "Full backup requested but dataset not yet initialized"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Full backup requested but dataset not yet initialized")); } return false; } } catch (Exception e) { - Slog.w(TAG, "Unable to get transport name: " + e.getMessage()); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Unable to get transport name: " + e.getMessage())); return false; } @@ -2104,8 +2318,8 @@ public class UserBackupManagerService { // the job driving automatic backups; that job will be scheduled again when // the user enables backup. if (MORE_DEBUG) { - Slog.i(TAG, "beginFullBackup but enabled=" + mEnabled - + " setupComplete=" + mSetupComplete + "; ignoring"); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "beginFullBackup but enabled=" + mEnabled + + " setupComplete=" + mSetupComplete + "; ignoring")); } return false; } @@ -2115,19 +2329,29 @@ public class UserBackupManagerService { final PowerSaveState result = mPowerManager.getPowerSaveState(ServiceType.FULL_BACKUP); if (result.batterySaverEnabled) { - if (DEBUG) Slog.i(TAG, "Deferring scheduled full backups in battery saver mode"); + if (DEBUG) { + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Deferring scheduled full backups in battery saver mode")); + } FullBackupJob.schedule(mUserId, mContext, keyValueBackupInterval, mConstants); return false; } if (DEBUG_SCHEDULING) { - Slog.i(TAG, "Beginning scheduled full backup operation"); + Slog.i( + TAG, + addUserIdToLogMessage(mUserId, "Beginning scheduled full backup operation")); } // Great; we're able to run full backup jobs now. See if we have any work to do. synchronized (mQueueLock) { if (mRunningFullBackupTask != null) { - Slog.e(TAG, "Backup triggered but one already/still running!"); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, "Backup triggered but one already/still running!")); return false; } @@ -2143,7 +2367,10 @@ public class UserBackupManagerService { if (mFullBackupQueue.size() == 0) { // no work to do so just bow out if (DEBUG) { - Slog.i(TAG, "Backup queue empty; doing nothing"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Backup queue empty; doing nothing")); } runBackup = false; break; @@ -2154,7 +2381,10 @@ public class UserBackupManagerService { String transportName = mTransportManager.getCurrentTransportName(); if (!fullBackupAllowable(transportName)) { if (MORE_DEBUG) { - Slog.i(TAG, "Preconditions not met; not running full backup"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Preconditions not met; not running full backup")); } runBackup = false; // Typically this means we haven't run a key/value backup yet. Back off @@ -2170,7 +2400,11 @@ public class UserBackupManagerService { if (!runBackup) { // It's too early to back up the next thing in the queue, so bow out if (MORE_DEBUG) { - Slog.i(TAG, "Device ready but too early to back up next app"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Device ready but too early to back up next app")); } // Wait until the next app in the queue falls due for a full data backup latency = fullBackupInterval - timeSinceRun; @@ -2185,8 +2419,14 @@ public class UserBackupManagerService { // so we cull it and force a loop around to consider the new head // app. if (MORE_DEBUG) { - Slog.i(TAG, "Culling package " + entry.packageName - + " in full-backup queue but not eligible"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Culling package " + + entry.packageName + + " in full-backup queue but not" + + " eligible")); } mFullBackupQueue.remove(0); headBusy = true; // force the while() condition @@ -2204,9 +2444,14 @@ public class UserBackupManagerService { + mTokenGenerator.nextInt(BUSY_BACKOFF_FUZZ); if (DEBUG_SCHEDULING) { SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss"); - Slog.i(TAG, "Full backup time but " + entry.packageName - + " is busy; deferring to " - + sdf.format(new Date(nextEligible))); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Full backup time but " + + entry.packageName + + " is busy; deferring to " + + sdf.format(new Date(nextEligible)))); } // This relocates the app's entry from the head of the queue to // its order-appropriate position further down, so upon looping @@ -2225,7 +2470,11 @@ public class UserBackupManagerService { if (!runBackup) { if (DEBUG_SCHEDULING) { - Slog.i(TAG, "Nothing pending full backup; rescheduling +" + latency); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Nothing pending full backup; rescheduling +" + latency)); } final long deferTime = latency; // pin for the closure FullBackupJob.schedule(mUserId, mContext, deferTime, mConstants); @@ -2273,7 +2522,10 @@ public class UserBackupManagerService { } if (pftbt != null) { if (DEBUG_SCHEDULING) { - Slog.i(TAG, "Telling running backup to stop"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Telling running backup to stop")); } pftbt.handleCancel(true); } @@ -2286,7 +2538,7 @@ public class UserBackupManagerService { public void restoreWidgetData(String packageName, byte[] widgetData) { // Apply the restored widget state and generate the ID update for the app if (MORE_DEBUG) { - Slog.i(TAG, "Incorporating restored widget data"); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Incorporating restored widget data")); } AppWidgetBackupBridge.restoreWidgetState(packageName, widgetData, mUserId); } @@ -2306,8 +2558,15 @@ public class UserBackupManagerService { // may share a uid, we need to note all candidates within that uid and schedule // a backup pass for each of them. if (targets == null) { - Slog.w(TAG, "dataChanged but no participant pkg='" + packageName + "'" - + " uid=" + Binder.getCallingUid()); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "dataChanged but no participant pkg='" + + packageName + + "'" + + " uid=" + + Binder.getCallingUid())); return; } @@ -2318,7 +2577,12 @@ public class UserBackupManagerService { // one already there, then overwrite it, but no harm done. BackupRequest req = new BackupRequest(packageName); if (mPendingBackups.put(packageName, req) == null) { - if (MORE_DEBUG) Slog.d(TAG, "Now staging backup of " + packageName); + if (MORE_DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Now staging backup of " + packageName)); + } // Journal this request in case of crash. The put() // operation returned null when this package was not already @@ -2358,7 +2622,10 @@ public class UserBackupManagerService { if (mJournal == null) mJournal = DataChangedJournal.newJournal(mJournalDir); mJournal.addPackage(str); } catch (IOException e) { - Slog.e(TAG, "Can't write " + str + " to backup journal", e); + Slog.e( + TAG, + addUserIdToLogMessage(mUserId, "Can't write " + str + " to backup journal"), + e); mJournal = null; } } @@ -2369,8 +2636,15 @@ public class UserBackupManagerService { public void dataChanged(final String packageName) { final HashSet<String> targets = dataChangedTargets(packageName); if (targets == null) { - Slog.w(TAG, "dataChanged but no participant pkg='" + packageName + "'" - + " uid=" + Binder.getCallingUid()); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "dataChanged but no participant pkg='" + + packageName + + "'" + + " uid=" + + Binder.getCallingUid())); return; } @@ -2385,7 +2659,10 @@ public class UserBackupManagerService { public void initializeTransports(String[] transportNames, IBackupObserver observer) { mContext.enforceCallingOrSelfPermission(android.Manifest.permission.BACKUP, "initializeTransport"); - Slog.v(TAG, "initializeTransport(): " + Arrays.asList(transportNames)); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "initializeTransport(): " + Arrays.asList(transportNames))); final long oldId = Binder.clearCallingIdentity(); try { @@ -2404,11 +2681,18 @@ public class UserBackupManagerService { public void setAncestralSerialNumber(long ancestralSerialNumber) { mContext.enforceCallingPermission(android.Manifest.permission.BACKUP, "setAncestralSerialNumber"); - Slog.v(TAG, "Setting ancestral work profile id to " + ancestralSerialNumber); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Setting ancestral work profile id to " + ancestralSerialNumber)); try (RandomAccessFile af = getAncestralSerialNumberFile()) { af.writeLong(ancestralSerialNumber); } catch (IOException e) { - Slog.w(TAG, "Unable to write to work profile serial mapping file:", e); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Unable to write to work profile serial mapping file:"), + e); } } @@ -2420,7 +2704,11 @@ public class UserBackupManagerService { try (RandomAccessFile af = getAncestralSerialNumberFile()) { return af.readLong(); } catch (IOException e) { - Slog.w(TAG, "Unable to write to work profile serial number file:", e); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Unable to write to work profile serial number file:"), + e); return -1; } } @@ -2443,13 +2731,24 @@ public class UserBackupManagerService { /** Clear the given package's backup data from the current transport. */ public void clearBackupData(String transportName, String packageName) { - if (DEBUG) Slog.v(TAG, "clearBackupData() of " + packageName + " on " + transportName); + if (DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "clearBackupData() of " + packageName + " on " + transportName)); + } + PackageInfo info; try { info = mPackageManager.getPackageInfoAsUser(packageName, PackageManager.GET_SIGNING_CERTIFICATES, mUserId); } catch (NameNotFoundException e) { - Slog.d(TAG, "No such package '" + packageName + "' - not clearing backup data"); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "No such package '" + packageName + "' - not clearing backup data")); return; } @@ -2462,13 +2761,22 @@ public class UserBackupManagerService { } else { // a caller with full permission can ask to back up any participating app // !!! TODO: allow data-clear of ANY app? - if (MORE_DEBUG) Slog.v(TAG, "Privileged caller, allowing clear of other apps"); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Privileged caller, allowing clear of other apps")); + } apps = mProcessedPackagesJournal.getPackagesCopy(); } if (apps.contains(packageName)) { // found it; fire off the clear request - if (MORE_DEBUG) Slog.v(TAG, "Found the app - running clear process"); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage(mUserId, "Found the app - running clear process")); + } mBackupHandler.removeMessages(MSG_RETRY_CLEAR); synchronized (mQueueLock) { TransportClient transportClient = @@ -2507,24 +2815,36 @@ public class UserBackupManagerService { final PowerSaveState result = mPowerManager.getPowerSaveState(ServiceType.KEYVALUE_BACKUP); if (result.batterySaverEnabled) { - if (DEBUG) Slog.v(TAG, "Not running backup while in battery save mode"); + if (DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Not running backup while in battery save mode")); + } // Try again in several hours. KeyValueBackupJob.schedule(mUserId, mContext, mConstants); } else { - if (DEBUG) Slog.v(TAG, "Scheduling immediate backup pass"); + if (DEBUG) { + Slog.v(TAG, addUserIdToLogMessage(mUserId, "Scheduling immediate backup pass")); + } synchronized (getQueueLock()) { if (getPendingInits().size() > 0) { // If there are pending init operations, we process those and then settle // into the usual periodic backup schedule. if (MORE_DEBUG) { - Slog.v(TAG, "Init pending at scheduled backup"); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Init pending at scheduled backup")); } try { getAlarmManager().cancel(mRunInitIntent); mRunInitIntent.send(); } catch (PendingIntent.CanceledException ce) { - Slog.w(TAG, "Run init intent cancelled"); + Slog.w( + TAG, + addUserIdToLogMessage(mUserId, "Run init intent cancelled")); } return; } @@ -2534,8 +2854,8 @@ public class UserBackupManagerService { if (!isEnabled() || !isSetupComplete()) { Slog.w( TAG, - "Backup pass but enabled=" + isEnabled() - + " setupComplete=" + isSetupComplete()); + addUserIdToLogMessage(mUserId, "Backup pass but enabled=" + isEnabled() + + " setupComplete=" + isSetupComplete())); return; } @@ -2582,16 +2902,31 @@ public class UserBackupManagerService { long oldId = Binder.clearCallingIdentity(); try { if (!mSetupComplete) { - Slog.i(TAG, "Backup not supported before setup"); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Backup not supported before setup")); return; } if (DEBUG) { - Slog.v(TAG, "Requesting backup: apks=" + includeApks + " obb=" + includeObbs - + " shared=" + includeShared + " all=" + doAllApps + " system=" - + includeSystem + " includekeyvalue=" + doKeyValue + " pkgs=" + pkgList); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "Requesting backup: apks=" + + includeApks + + " obb=" + + includeObbs + + " shared=" + + includeShared + + " all=" + + doAllApps + + " system=" + + includeSystem + + " includekeyvalue=" + + doKeyValue + + " pkgs=" + + pkgList)); } - Slog.i(TAG, "Beginning adb backup..."); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Beginning adb backup...")); AdbBackupParams params = new AdbBackupParams(fd, includeApks, includeObbs, includeShared, doWidgets, doAllApps, includeSystem, compress, doKeyValue, @@ -2602,9 +2937,16 @@ public class UserBackupManagerService { } // start up the confirmation UI - if (DEBUG) Slog.d(TAG, "Starting backup confirmation UI, token=" + token); + if (DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Starting backup confirmation UI, token=" + token)); + } if (!startConfirmationUi(token, FullBackup.FULL_BACKUP_INTENT_ACTION)) { - Slog.e(TAG, "Unable to launch backup confirmation UI"); + Slog.e( + TAG, + addUserIdToLogMessage(mUserId, "Unable to launch backup confirmation UI")); mAdbBackupRestoreConfirmations.delete(token); return; } @@ -2618,16 +2960,22 @@ public class UserBackupManagerService { startConfirmationTimeout(token, params); // wait for the backup to be performed - if (DEBUG) Slog.d(TAG, "Waiting for backup completion..."); + if (DEBUG) { + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Waiting for backup completion...")); + } waitForCompletion(params); } finally { try { fd.close(); } catch (IOException e) { - Slog.e(TAG, "IO error closing output for adb backup: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "IO error closing output for adb backup: " + e.getMessage())); } Binder.restoreCallingIdentity(oldId); - Slog.d(TAG, "Adb backup processing complete."); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Adb backup processing complete.")); } } @@ -2644,10 +2992,14 @@ public class UserBackupManagerService { String transportName = mTransportManager.getCurrentTransportName(); if (!fullBackupAllowable(transportName)) { - Slog.i(TAG, "Full backup not currently possible -- key/value backup not yet run?"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Full backup not currently possible -- key/value backup not yet run?")); } else { if (DEBUG) { - Slog.d(TAG, "fullTransportBackup()"); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "fullTransportBackup()")); } final long oldId = Binder.clearCallingIdentity(); @@ -2687,7 +3039,7 @@ public class UserBackupManagerService { } if (DEBUG) { - Slog.d(TAG, "Done with full transport backup."); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Done with full transport backup.")); } } @@ -2707,11 +3059,13 @@ public class UserBackupManagerService { try { if (!mSetupComplete) { - Slog.i(TAG, "Full restore not permitted before setup"); + Slog.i( + TAG, + addUserIdToLogMessage(mUserId, "Full restore not permitted before setup")); return; } - Slog.i(TAG, "Beginning restore..."); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Beginning restore...")); AdbRestoreParams params = new AdbRestoreParams(fd); final int token = generateRandomIntegerToken(); @@ -2720,9 +3074,16 @@ public class UserBackupManagerService { } // start up the confirmation UI - if (DEBUG) Slog.d(TAG, "Starting restore confirmation UI, token=" + token); + if (DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Starting restore confirmation UI, token=" + token)); + } if (!startConfirmationUi(token, FullBackup.FULL_RESTORE_INTENT_ACTION)) { - Slog.e(TAG, "Unable to launch restore confirmation"); + Slog.e( + TAG, + addUserIdToLogMessage(mUserId, "Unable to launch restore confirmation")); mAdbBackupRestoreConfirmations.delete(token); return; } @@ -2736,16 +3097,21 @@ public class UserBackupManagerService { startConfirmationTimeout(token, params); // wait for the restore to be performed - if (DEBUG) Slog.d(TAG, "Waiting for restore completion..."); + if (DEBUG) { + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Waiting for restore completion...")); + } waitForCompletion(params); } finally { try { fd.close(); } catch (IOException e) { - Slog.w(TAG, "Error trying to close fd after adb restore: " + e); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Error trying to close fd after adb restore: " + e)); } Binder.restoreCallingIdentity(oldId); - Slog.i(TAG, "adb restore processing complete."); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "adb restore processing complete.")); } } @@ -2773,8 +3139,8 @@ public class UserBackupManagerService { private void startConfirmationTimeout(int token, AdbParams params) { if (MORE_DEBUG) { - Slog.d(TAG, "Posting conf timeout msg after " - + TIMEOUT_FULL_CONFIRMATION + " millis"); + Slog.d(TAG, addUserIdToLogMessage(mUserId, "Posting conf timeout msg after " + + TIMEOUT_FULL_CONFIRMATION + " millis")); } Message msg = mBackupHandler.obtainMessage(MSG_FULL_CONFIRMATION_TIMEOUT, token, 0, params); @@ -2806,8 +3172,11 @@ public class UserBackupManagerService { public void acknowledgeAdbBackupOrRestore(int token, boolean allow, String curPassword, String encPpassword, IFullBackupRestoreObserver observer) { if (DEBUG) { - Slog.d(TAG, "acknowledgeAdbBackupOrRestore : token=" + token - + " allow=" + allow); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "acknowledgeAdbBackupOrRestore : token=" + token + " allow=" + allow)); } // TODO: possibly require not just this signature-only permission, but even @@ -2835,17 +3204,29 @@ public class UserBackupManagerService { params.encryptPassword = encPpassword; - if (MORE_DEBUG) Slog.d(TAG, "Sending conf message with verb " + verb); + if (MORE_DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "Sending conf message with verb " + verb)); + } mWakelock.acquire(); Message msg = mBackupHandler.obtainMessage(verb, params); mBackupHandler.sendMessage(msg); } else { - Slog.w(TAG, "User rejected full backup/restore operation"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "User rejected full backup/restore operation")); // indicate completion without having actually transferred any data signalAdbBackupRestoreCompletion(params); } } else { - Slog.w(TAG, "Attempted to ack full backup/restore with invalid token"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Attempted to ack full backup/restore with invalid token")); } } } finally { @@ -2858,7 +3239,7 @@ public class UserBackupManagerService { mContext.enforceCallingOrSelfPermission(android.Manifest.permission.BACKUP, "setBackupEnabled"); - Slog.i(TAG, "Backup enabled => " + enable); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Backup enabled => " + enable)); long oldId = Binder.clearCallingIdentity(); try { @@ -2875,7 +3256,9 @@ public class UserBackupManagerService { scheduleNextFullBackupJob(0); } else if (!enable) { // No longer enabled, so stop running backups - if (MORE_DEBUG) Slog.i(TAG, "Opting out of backup"); + if (MORE_DEBUG) { + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Opting out of backup")); + } KeyValueBackupJob.cancel(mUserId, mContext); @@ -2891,12 +3274,15 @@ public class UserBackupManagerService { name -> { final String dirName; try { - dirName = - mTransportManager - .getTransportDirName(name); + dirName = mTransportManager.getTransportDirName(name); } catch (TransportNotRegisteredException e) { // Should never happen - Slog.e(TAG, "Unexpected unregistered transport", e); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unexpected unregistered transport"), + e); return; } transportNames.add(name); @@ -2925,7 +3311,7 @@ public class UserBackupManagerService { mContext.enforceCallingOrSelfPermission(android.Manifest.permission.BACKUP, "setAutoRestore"); - Slog.i(TAG, "Auto restore => " + doAutoRestore); + Slog.i(TAG, addUserIdToLogMessage(mUserId, "Auto restore => " + doAutoRestore)); final long oldId = Binder.clearCallingIdentity(); try { @@ -2951,7 +3337,12 @@ public class UserBackupManagerService { mContext.enforceCallingOrSelfPermission(android.Manifest.permission.BACKUP, "getCurrentTransport"); String currentTransport = mTransportManager.getCurrentTransportName(); - if (MORE_DEBUG) Slog.v(TAG, "... getCurrentTransport() returning " + currentTransport); + if (MORE_DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "... getCurrentTransport() returning " + currentTransport)); + } return currentTransport; } @@ -3090,8 +3481,14 @@ public class UserBackupManagerService { try { String previousTransportName = mTransportManager.selectTransport(transportName); updateStateForTransport(transportName); - Slog.v(TAG, "selectBackupTransport(transport = " + transportName - + "): previous transport = " + previousTransportName); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "selectBackupTransport(transport = " + + transportName + + "): previous transport = " + + previousTransportName)); return previousTransportName; } finally { Binder.restoreCallingIdentity(oldId); @@ -3110,7 +3507,11 @@ public class UserBackupManagerService { final long oldId = Binder.clearCallingIdentity(); try { String transportString = transportComponent.flattenToShortString(); - Slog.v(TAG, "selectBackupTransportAsync(transport = " + transportString + ")"); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "selectBackupTransportAsync(transport = " + transportString + ")")); mBackupHandler.post( () -> { String transportName = null; @@ -3122,7 +3523,10 @@ public class UserBackupManagerService { mTransportManager.getTransportName(transportComponent); updateStateForTransport(transportName); } catch (TransportNotRegisteredException e) { - Slog.e(TAG, "Transport got unregistered"); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, "Transport got unregistered")); result = BackupManager.ERROR_TRANSPORT_UNAVAILABLE; } } @@ -3134,7 +3538,12 @@ public class UserBackupManagerService { listener.onFailure(result); } } catch (RemoteException e) { - Slog.e(TAG, "ISelectBackupTransportCallback listener not available"); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "ISelectBackupTransportCallback listener not" + + " available")); } }); } finally { @@ -3159,11 +3568,23 @@ public class UserBackupManagerService { // Oops. We can't know the current dataset token, so reset and figure it out // when we do the next k/v backup operation on this transport. mCurrentToken = 0; - Slog.w(TAG, "Transport " + newTransportName + " not available: current token = 0"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Transport " + + newTransportName + + " not available: current token = 0")); } mTransportManager.disposeOfTransportClient(transportClient, callerLogString); } else { - Slog.w(TAG, "Transport " + newTransportName + " not registered: current token = 0"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Transport " + + newTransportName + + " not registered: current token = 0")); // The named transport isn't registered, so we can't know what its current dataset token // is. Reset as above. mCurrentToken = 0; @@ -3181,11 +3602,19 @@ public class UserBackupManagerService { try { Intent intent = mTransportManager.getTransportConfigurationIntent(transportName); if (MORE_DEBUG) { - Slog.d(TAG, "getConfigurationIntent() returning intent " + intent); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "getConfigurationIntent() returning intent " + intent)); } return intent; } catch (TransportNotRegisteredException e) { - Slog.e(TAG, "Unable to get configuration intent from transport: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unable to get configuration intent from transport: " + + e.getMessage())); return null; } } @@ -3206,11 +3635,18 @@ public class UserBackupManagerService { try { String string = mTransportManager.getTransportCurrentDestinationString(transportName); if (MORE_DEBUG) { - Slog.d(TAG, "getDestinationString() returning " + string); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "getDestinationString() returning " + string)); } return string; } catch (TransportNotRegisteredException e) { - Slog.e(TAG, "Unable to get destination string from transport: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unable to get destination string from transport: " + e.getMessage())); return null; } } @@ -3223,11 +3659,18 @@ public class UserBackupManagerService { try { Intent intent = mTransportManager.getTransportDataManagementIntent(transportName); if (MORE_DEBUG) { - Slog.d(TAG, "getDataManagementIntent() returning intent " + intent); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "getDataManagementIntent() returning intent " + intent)); } return intent; } catch (TransportNotRegisteredException e) { - Slog.e(TAG, "Unable to get management intent from transport: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unable to get management intent from transport: " + e.getMessage())); return null; } } @@ -3243,11 +3686,18 @@ public class UserBackupManagerService { try { CharSequence label = mTransportManager.getTransportDataManagementLabel(transportName); if (MORE_DEBUG) { - Slog.d(TAG, "getDataManagementLabel() returning " + label); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, "getDataManagementLabel() returning " + label)); } return label; } catch (TransportNotRegisteredException e) { - Slog.e(TAG, "Unable to get management label from transport: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, + "Unable to get management label from transport: " + e.getMessage())); return null; } } @@ -3259,12 +3709,21 @@ public class UserBackupManagerService { public void agentConnected(String packageName, IBinder agentBinder) { synchronized (mAgentConnectLock) { if (Binder.getCallingUid() == Process.SYSTEM_UID) { - Slog.d(TAG, "agentConnected pkg=" + packageName + " agent=" + agentBinder); + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "agentConnected pkg=" + packageName + " agent=" + agentBinder)); mConnectedAgent = IBackupAgent.Stub.asInterface(agentBinder); mConnecting = false; } else { - Slog.w(TAG, "Non-system process uid=" + Binder.getCallingUid() - + " claiming agent connected"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Non-system process uid=" + + Binder.getCallingUid() + + " claiming agent connected")); } mAgentConnectLock.notifyAll(); } @@ -3282,8 +3741,13 @@ public class UserBackupManagerService { mConnectedAgent = null; mConnecting = false; } else { - Slog.w(TAG, "Non-system process uid=" + Binder.getCallingUid() - + " claiming agent disconnected"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Non-system process uid=" + + Binder.getCallingUid() + + " claiming agent disconnected")); } mAgentConnectLock.notifyAll(); } @@ -3295,8 +3759,13 @@ public class UserBackupManagerService { */ public void restoreAtInstall(String packageName, int token) { if (Binder.getCallingUid() != Process.SYSTEM_UID) { - Slog.w(TAG, "Non-system process uid=" + Binder.getCallingUid() - + " attemping install-time restore"); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Non-system process uid=" + + Binder.getCallingUid() + + " attemping install-time restore")); return; } @@ -3304,25 +3773,35 @@ public class UserBackupManagerService { long restoreSet = getAvailableRestoreToken(packageName); if (DEBUG) { - Slog.v(TAG, "restoreAtInstall pkg=" + packageName - + " token=" + Integer.toHexString(token) - + " restoreSet=" + Long.toHexString(restoreSet)); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "restoreAtInstall pkg=" + + packageName + + " token=" + + Integer.toHexString(token) + + " restoreSet=" + + Long.toHexString(restoreSet))); } if (restoreSet == 0) { - if (MORE_DEBUG) Slog.i(TAG, "No restore set"); + if (MORE_DEBUG) Slog.i(TAG, addUserIdToLogMessage(mUserId, "No restore set")); skip = true; } TransportClient transportClient = mTransportManager.getCurrentTransportClient("BMS.restoreAtInstall()"); if (transportClient == null) { - if (DEBUG) Slog.w(TAG, "No transport client"); + if (DEBUG) Slog.w(TAG, addUserIdToLogMessage(mUserId, "No transport client")); skip = true; } if (!mAutoRestore) { if (DEBUG) { - Slog.w(TAG, "Non-restorable state: auto=" + mAutoRestore); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Non-restorable state: auto=" + mAutoRestore)); } skip = true; } @@ -3341,7 +3820,9 @@ public class UserBackupManagerService { }; if (MORE_DEBUG) { - Slog.d(TAG, "Restore at install of " + packageName); + Slog.d( + TAG, + addUserIdToLogMessage(mUserId, "Restore at install of " + packageName)); } Message msg = mBackupHandler.obtainMessage(MSG_RUN_RESTORE); msg.obj = @@ -3356,7 +3837,10 @@ public class UserBackupManagerService { mBackupHandler.sendMessage(msg); } catch (Exception e) { // Calling into the transport broke; back off and proceed with the installation. - Slog.e(TAG, "Unable to contact transport: " + e.getMessage()); + Slog.e( + TAG, + addUserIdToLogMessage( + mUserId, "Unable to contact transport: " + e.getMessage())); skip = true; } } @@ -3370,7 +3854,7 @@ public class UserBackupManagerService { } // Tell the PackageManager to proceed with the post-install handling for this package. - if (DEBUG) Slog.v(TAG, "Finishing install immediately"); + if (DEBUG) Slog.v(TAG, addUserIdToLogMessage(mUserId, "Finishing install immediately")); try { mPackageManagerBinder.finishPackageInstall(token, false); } catch (RemoteException e) { /* can't happen */ } @@ -3380,8 +3864,11 @@ public class UserBackupManagerService { /** Hand off a restore session. */ public IRestoreSession beginRestoreSession(String packageName, String transport) { if (DEBUG) { - Slog.v(TAG, "beginRestoreSession: pkg=" + packageName - + " transport=" + transport); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "beginRestoreSession: pkg=" + packageName + " transport=" + transport)); } boolean needPermission = true; @@ -3393,7 +3880,10 @@ public class UserBackupManagerService { try { app = mPackageManager.getPackageInfoAsUser(packageName, 0, mUserId); } catch (NameNotFoundException nnf) { - Slog.w(TAG, "Asked to restore nonexistent pkg " + packageName); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, "Asked to restore nonexistent pkg " + packageName)); throw new IllegalArgumentException("Package " + packageName + " not found"); } @@ -3407,19 +3897,32 @@ public class UserBackupManagerService { } if (needPermission) { - mContext.enforceCallingOrSelfPermission(android.Manifest.permission.BACKUP, - "beginRestoreSession"); + mContext.enforceCallingOrSelfPermission( + android.Manifest.permission.BACKUP, "beginRestoreSession"); } else { - if (DEBUG) Slog.d(TAG, "restoring self on current transport; no permission needed"); + if (DEBUG) { + Slog.d( + TAG, + addUserIdToLogMessage( + mUserId, + "restoring self on current transport; no permission needed")); + } } synchronized (this) { if (mActiveRestoreSession != null) { - Slog.i(TAG, "Restore session requested but one already active"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, "Restore session requested but one already active")); return null; } if (mBackupRunning) { - Slog.i(TAG, "Restore session requested but currently running backups"); + Slog.i( + TAG, + addUserIdToLogMessage( + mUserId, + "Restore session requested but currently running backups")); return null; } mActiveRestoreSession = new ActiveRestoreSession(this, packageName, transport); @@ -3433,9 +3936,14 @@ public class UserBackupManagerService { public void clearRestoreSession(ActiveRestoreSession currentSession) { synchronized (this) { if (currentSession != mActiveRestoreSession) { - Slog.e(TAG, "ending non-current restore session"); + Slog.e(TAG, addUserIdToLogMessage(mUserId, "ending non-current restore session")); } else { - if (DEBUG) Slog.v(TAG, "Clearing restore session and halting timeout"); + if (DEBUG) { + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, "Clearing restore session and halting timeout")); + } mActiveRestoreSession = null; mBackupHandler.removeMessages(MSG_RESTORE_SESSION_TIMEOUT); } @@ -3448,7 +3956,11 @@ public class UserBackupManagerService { */ public void opComplete(int token, long result) { if (MORE_DEBUG) { - Slog.v(TAG, "opComplete: " + Integer.toHexString(token) + " result=" + result); + Slog.v( + TAG, + addUserIdToLogMessage( + mUserId, + "opComplete: " + Integer.toHexString(token) + " result=" + result)); } Operation op = null; synchronized (mCurrentOpLock) { @@ -3461,8 +3973,12 @@ public class UserBackupManagerService { mCurrentOperations.delete(token); } else if (op.state == OP_ACKNOWLEDGED) { if (DEBUG) { - Slog.w(TAG, "Received duplicate ack for token=" - + Integer.toHexString(token)); + Slog.w( + TAG, + addUserIdToLogMessage( + mUserId, + "Received duplicate ack for token=" + + Integer.toHexString(token))); } op = null; mCurrentOperations.remove(token); @@ -3606,7 +4122,7 @@ public class UserBackupManagerService { " " + f.getName() + " - " + f.length() + " state bytes"); } } catch (Exception e) { - Slog.e(TAG, "Error in transport", e); + Slog.e(TAG, addUserIdToLogMessage(mUserId, "Error in transport"), e); pw.println(" Error: " + e); } } @@ -3665,6 +4181,10 @@ public class UserBackupManagerService { } } + private static String addUserIdToLogMessage(int userId, String message) { + return "[UserID:" + userId + "] " + message; + } + public IBackupManager getBackupManagerBinder() { return mBackupManagerBinder; diff --git a/services/robotests/backup/src/com/android/server/backup/testing/BackupManagerServiceTestUtils.java b/services/robotests/backup/src/com/android/server/backup/testing/BackupManagerServiceTestUtils.java index 84421ef178c9..77b5b61b8f01 100644 --- a/services/robotests/backup/src/com/android/server/backup/testing/BackupManagerServiceTestUtils.java +++ b/services/robotests/backup/src/com/android/server/backup/testing/BackupManagerServiceTestUtils.java @@ -166,7 +166,7 @@ public class BackupManagerServiceTestUtils { PowerManager powerManager = (PowerManager) application.getSystemService(Context.POWER_SERVICE); return new UserBackupManagerService.BackupWakeLock( - powerManager.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, "*backup*")); + powerManager.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, "*backup*"), 0); } /** |