From c9d11e8208636d1534672681a0601f5ff3c2e6f7 Mon Sep 17 00:00:00 2001 From: Charlie Anderson Date: Wed, 2 Aug 2023 11:41:55 -0400 Subject: [PATCH] add logging for Launcher backup and restore events Test: Manually verify logs Bug: 294386159 Change-Id: Ic3a77f4a09556e0d769837129e0bd094f1e91b6b --- .../launcher3/InvariantDeviceProfile.java | 6 +- .../launcher3/LauncherBackupAgent.java | 3 +- .../launcher3/SessionCommitReceiver.java | 15 ++++- .../android/launcher3/model/LoaderTask.java | 2 + .../launcher3/provider/RestoreDbTask.java | 63 +++++++++++++++++-- 5 files changed, 79 insertions(+), 10 deletions(-) diff --git a/src/com/android/launcher3/InvariantDeviceProfile.java b/src/com/android/launcher3/InvariantDeviceProfile.java index be14844fbc..e3de79e03a 100644 --- a/src/com/android/launcher3/InvariantDeviceProfile.java +++ b/src/com/android/launcher3/InvariantDeviceProfile.java @@ -50,6 +50,7 @@ import androidx.core.content.res.ResourcesCompat; import com.android.launcher3.config.FeatureFlags; import com.android.launcher3.icons.DotRenderer; +import com.android.launcher3.logging.FileLog; import com.android.launcher3.model.DeviceGridState; import com.android.launcher3.provider.RestoreDbTask; import com.android.launcher3.testing.shared.ResourceUtils; @@ -287,12 +288,13 @@ public class InvariantDeviceProfile { * Reinitialize the current grid after a restore, where some grids might now be disabled. */ public void reinitializeAfterRestore(Context context) { + FileLog.d(TAG, "Reinitializing grid after restore"); String currentGridName = getCurrentGridName(context); String currentDbFile = dbFile; String newGridName = initGrid(context, currentGridName); String newDbFile = dbFile; if (!newDbFile.equals(currentDbFile)) { - Log.d(TAG, "Restored grid is disabled : " + currentGridName + FileLog.d(TAG, "Restored grid is disabled : " + currentGridName + ", migrating to: " + newGridName + ", removing all other grid db files"); for (String gridDbFile : LauncherFiles.GRID_DB_FILES) { @@ -300,7 +302,7 @@ public class InvariantDeviceProfile { continue; } if (context.getDatabasePath(gridDbFile).delete()) { - Log.d(TAG, "Removed old grid db file: " + gridDbFile); + FileLog.d(TAG, "Removed old grid db file: " + gridDbFile); } } setCurrentGrid(context, newGridName); diff --git a/src/com/android/launcher3/LauncherBackupAgent.java b/src/com/android/launcher3/LauncherBackupAgent.java index 3d2700de40..2617b9337d 100644 --- a/src/com/android/launcher3/LauncherBackupAgent.java +++ b/src/com/android/launcher3/LauncherBackupAgent.java @@ -34,7 +34,7 @@ public class LauncherBackupAgent extends BackupAgent { // Remove old files which might contain obsolete attributes like idp_grid_name in shared // preference that will obstruct backup's attribute from writing to shared preferences. if (destination.delete()) { - FileLog.d("LauncherBackupAgent", "Removed obsolete file: " + destination); + FileLog.d(TAG, "onRestoreFile: Removed obsolete file " + destination); } super.onRestoreFile(data, size, destination, type, mode, mtime); } @@ -47,6 +47,7 @@ public class LauncherBackupAgent extends BackupAgent { @Override public void onRestoreFinished() { + FileLog.d(TAG, "onRestoreFinished: set pending for RestoreDbTask"); RestoreDbTask.setPending(this); } } diff --git a/src/com/android/launcher3/SessionCommitReceiver.java b/src/com/android/launcher3/SessionCommitReceiver.java index aaccb7dfc0..d460ba8668 100644 --- a/src/com/android/launcher3/SessionCommitReceiver.java +++ b/src/com/android/launcher3/SessionCommitReceiver.java @@ -32,6 +32,8 @@ import com.android.launcher3.model.ItemInstallQueue; import com.android.launcher3.pm.InstallSessionHelper; import com.android.launcher3.util.Executors; +import java.util.Locale; + /** * BroadcastReceiver to handle session commit intent. */ @@ -63,9 +65,20 @@ public class SessionCommitReceiver extends BroadcastReceiver { } InstallSessionHelper packageInstallerCompat = InstallSessionHelper.INSTANCE.get(context); + boolean alreadyAddedPromiseIcon = + packageInstallerCompat.promiseIconAddedForId(info.getSessionId()); if (TextUtils.isEmpty(info.getAppPackageName()) || info.getInstallReason() != PackageManager.INSTALL_REASON_USER - || packageInstallerCompat.promiseIconAddedForId(info.getSessionId())) { + || alreadyAddedPromiseIcon) { + FileLog.d(LOG, + String.format(Locale.ENGLISH, + "Removing PromiseIcon for package: %s, install reason: %d," + + " alreadyAddedPromiseIcon: %s", + info.getAppPackageName(), + info.getInstallReason(), + alreadyAddedPromiseIcon + ) + ); packageInstallerCompat.removePromiseIconId(info.getSessionId()); return; } diff --git a/src/com/android/launcher3/model/LoaderTask.java b/src/com/android/launcher3/model/LoaderTask.java index 933468cab1..0e68db29e8 100644 --- a/src/com/android/launcher3/model/LoaderTask.java +++ b/src/com/android/launcher3/model/LoaderTask.java @@ -374,6 +374,8 @@ public class LoaderTask implements Runnable { final HashMap installingPkgs = mSessionHelper.getActiveSessions(); installingPkgs.forEach(mApp.getIconCache()::updateSessionCache); + FileLog.d(TAG, "loadWorkspace: Packages with active install sessions: " + + installingPkgs.values()); final PackageUserKey tempPackageKey = new PackageUserKey(null, null); mFirstScreenBroadcast = new FirstScreenBroadcast(installingPkgs); diff --git a/src/com/android/launcher3/provider/RestoreDbTask.java b/src/com/android/launcher3/provider/RestoreDbTask.java index c554def0de..4725dd16b2 100644 --- a/src/com/android/launcher3/provider/RestoreDbTask.java +++ b/src/com/android/launcher3/provider/RestoreDbTask.java @@ -82,11 +82,15 @@ public class RestoreDbTask { public static final String APPWIDGET_OLD_IDS = "appwidget_old_ids"; public static final String APPWIDGET_IDS = "appwidget_ids"; + private static final String[] DB_COLUMNS_TO_LOG = {"profileId", "title", "itemType", "screen", + "container", "cellX", "cellY", "spanX", "spanY", "intent"}; + /** * Tries to restore the backup DB if needed */ public static void restoreIfNeeded(Context context, ModelDbController dbController) { if (!isPending(context)) { + Log.d(TAG, "No restore task pending, exiting RestoreDbTask"); return; } if (!performRestore(context, dbController)) { @@ -106,6 +110,7 @@ public class RestoreDbTask { private static boolean performRestore(Context context, ModelDbController controller) { SQLiteDatabase db = controller.getDb(); + FileLog.d(TAG, "performRestore: starting restore from db"); try (SQLiteTransaction t = new SQLiteTransaction(db)) { RestoreDbTask task = new RestoreDbTask(); task.sanitizeDB(context, controller, db, new BackupManager(context)); @@ -133,10 +138,11 @@ public class RestoreDbTask { @VisibleForTesting protected int sanitizeDB(Context context, ModelDbController controller, SQLiteDatabase db, BackupManager backupManager) throws Exception { + FileLog.d(TAG, "Old Launcher Database before sanitizing:"); // Primary user ids long myProfileId = controller.getSerialNumberForUser(myUserHandle()); long oldProfileId = getDefaultProfileId(db); - Log.d(TAG, "sanitizeDB: myProfileId=" + myProfileId + " oldProfileId=" + oldProfileId); + FileLog.d(TAG, "sanitizeDB: myProfileId=" + myProfileId + " oldProfileId=" + oldProfileId); LongSparseArray oldManagedProfileIds = getManagedProfileIds(db, oldProfileId); LongSparseArray profileMapping = new LongSparseArray<>(oldManagedProfileIds.size() + 1); @@ -149,8 +155,11 @@ public class RestoreDbTask { if (user != null) { long newManagedProfileId = controller.getSerialNumberForUser(user); profileMapping.put(oldManagedProfileId, newManagedProfileId); - Log.d(TAG, "sanitizeDB: managed profile id=" + oldManagedProfileId + FileLog.d(TAG, "sanitizeDB: managed profile id=" + oldManagedProfileId + " should be mapped to new id=" + newManagedProfileId); + } else { + FileLog.e(TAG, "sanitizeDB: No User found for old profileId, Ancestral Serial " + + "Number: " + oldManagedProfileId); } } @@ -161,11 +170,13 @@ public class RestoreDbTask { for (int i = numProfiles - 1; i >= 1; --i) { profileIds[i] = Long.toString(profileMapping.keyAt(i)); } + final String[] args = new String[profileIds.length]; Arrays.fill(args, "?"); final String where = "profileId NOT IN (" + TextUtils.join(", ", Arrays.asList(args)) + ")"; - int itemsDeleted = db.delete(Favorites.TABLE_NAME, where, profileIds); - FileLog.d(TAG, itemsDeleted + " items from unrestored user(s) were deleted"); + logUnrestoredItems(db, where, profileIds); + int itemsDeletedCount = db.delete(Favorites.TABLE_NAME, where, profileIds); + FileLog.d(TAG, itemsDeletedCount + " total items from unrestored user(s) were deleted"); // Mark all items as restored. boolean keepAllIcons = Utilities.isPropertyEnabled(LogConfig.KEEP_ALL_ICONS); @@ -219,8 +230,48 @@ public class RestoreDbTask { // Override shortcuts maybeOverrideShortcuts(context, controller, db, myProfileId); + return itemsDeletedCount; + } - return itemsDeleted; + /** + * Queries and logs the items we will delete from unrestored profiles in the launcher db. + * This is to understand why items might be missing during the restore process for Launcher. + * @param database the Launcher db to query from. + * @param where the SELECT statement to query items that will be deleted. + * @param profileIds the profile ID's the user will be migrating to. + */ + private void logUnrestoredItems(SQLiteDatabase database, String where, String[] profileIds) { + try (Cursor itemsToDelete = database.query( + /* table */ Favorites.TABLE_NAME, + /* columns */ DB_COLUMNS_TO_LOG, + /* selection */ where, + /* selection args */ profileIds, + /* groupBy */ null, + /* having */ null, + /* orderBy */ null + )) { + if (itemsToDelete.moveToFirst()) { + String[] columnNames = itemsToDelete.getColumnNames(); + StringBuilder stringBuilder = new StringBuilder( + "items to be deleted from the Favorites Table during restore:\n" + ); + do { + for (String columnName : columnNames) { + stringBuilder.append(columnName) + .append("=") + .append(itemsToDelete.getString( + itemsToDelete.getColumnIndex(columnName))) + .append(" "); + } + stringBuilder.append("\n"); + } while (itemsToDelete.moveToNext()); + FileLog.d(TAG, stringBuilder.toString()); + } else { + FileLog.d(TAG, "logDeletedItems: No items found to delete"); + } + } catch (Exception e) { + FileLog.e(TAG, "logDeletedItems: Error reading from database", e); + } } /** @@ -321,7 +372,7 @@ public class RestoreDbTask { * Marks the DB state as pending restoration */ public static void setPending(Context context) { - FileLog.d(TAG, "Restore data received through full backup "); + FileLog.d(TAG, "Restore data received through full backup"); LauncherPrefs.get(context) .putSync(RESTORE_DEVICE.to(new DeviceGridState(context).getDeviceType())); }