Merge "Add userId to log messages - DO NOT MERGE" into rvc-dev
diff --git a/services/backup/java/com/android/server/backup/UserBackupManagerService.java b/services/backup/java/com/android/server/backup/UserBackupManagerService.java
index 6247a63..69154b4 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.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 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 @@
/** 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 @@
}
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 @@
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 @@
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 @@
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 @@
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 @@
}
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 @@
}
} 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
() -> 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 @@
// 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 @@
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 @@
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 @@
// 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 @@
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 @@
// 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 @@
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 @@
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 @@
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 @@
// 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 @@
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 @@
} 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 @@
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 @@
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 @@
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 @@
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 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 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 @@
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 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 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 @@
/** 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 @@
// 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 @@
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 @@
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 @@
// 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 @@
// 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 @@
} 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 @@
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 @@
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 @@
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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
+ 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 @@
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 @@
}
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 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 @@
// 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 @@
// 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 @@
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 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 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 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 @@
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 @@
/** 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 @@
} 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 @@
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 @@
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 @@
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 @@
}
// 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 @@
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 @@
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 @@
}
if (DEBUG) {
- Slog.d(TAG, "Done with full transport backup.");
+ Slog.d(TAG, addUserIdToLogMessage(mUserId, "Done with full transport backup."));
}
}
@@ -2707,11 +3059,13 @@
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 @@
}
// 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 @@
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 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
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 @@
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 @@
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 @@
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 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 @@
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 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 @@
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 @@
};
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 @@
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 @@
}
// 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 @@
/** 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 @@
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 @@
}
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 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 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 @@
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 @@
" " + 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 @@
}
}
+ 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 84421ef..77b5b61 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 @@
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);
}
/**