Adds more in depth logging of Launcher restore functionality (c61288e2) · Commits · e / os / android_packages_apps_Trebuchet

src/com/android/launcher3/AppWidgetsRestoredReceiver.java

+19 −2

Original line number	Diff line number	Diff line
		@@ -9,9 +9,13 @@ import android.content.Context;
		import android.content.Intent;
		import android.util.Log;

		import com.android.launcher3.logging.FileLog;
		import com.android.launcher3.provider.RestoreDbTask;
		import com.android.launcher3.util.IntArray;
		import com.android.launcher3.widget.LauncherWidgetHolder;

		import java.util.Arrays;

		public class AppWidgetsRestoredReceiver extends BroadcastReceiver {

		private static final String TAG = "AppWidgetsRestoredReceiver";
		@@ -20,8 +24,11 @@ public class AppWidgetsRestoredReceiver extends BroadcastReceiver {
		public void onReceive(final Context context, Intent intent) {
		if (AppWidgetManager.ACTION_APPWIDGET_HOST_RESTORED.equals(intent.getAction())) {
		int hostId = intent.getIntExtra(AppWidgetManager.EXTRA_HOST_ID, 0);
		Log.d(TAG, "Widget ID map received for host:" + hostId);
		Log.d(TAG, "onReceive: Widget ID map received for host:" + hostId);
		if (hostId != LauncherWidgetHolder.APPWIDGET_HOST_ID) {
		Log.w(TAG, "onReceive: hostId does not match Launcher."
		+ " Expected: " + LauncherWidgetHolder.APPWIDGET_HOST_ID
		+ ", Actual: " + hostId);
		return;
		}

		@@ -31,8 +38,18 @@ public class AppWidgetsRestoredReceiver extends BroadcastReceiver {
		LauncherPrefs.get(context).putSync(
		OLD_APP_WIDGET_IDS.to(IntArray.wrap(oldIds).toConcatString()),
		APP_WIDGET_IDS.to(IntArray.wrap(newIds).toConcatString()));
		FileLog.d(TAG, "onReceive: Valid Widget IDs received."
		+ " old IDs=" + Arrays.toString(oldIds)
		+ ", new IDs=" + Arrays.toString(newIds));
		if (!RestoreDbTask.isPending(context)) {
		FileLog.w(TAG, "onReceive: Restored App Widget Ids received but Launcher"
		+ " restore is not pending. New widget Ids might not get restored.");
		}
		} else {
		Log.e(TAG, "Invalid host restored received");
		Log.e(TAG, "onReceive: Invalid widget ids received for Launcher"
		+ ", skipping restore of widget ids."
		+ " newIds=" + Arrays.toString(newIds)
		+ ", oldIds=" + Arrays.toString(oldIds));
		}
		}
		}

src/com/android/launcher3/InvariantDeviceProfile.java

+5 −1

Original line number	Diff line number	Diff line
		@@ -298,11 +298,15 @@ 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;
		FileLog.d(TAG, "Reinitializing grid after restore."
		+ " currentGridName=" + currentGridName
		+ ", currentDbFile=" + currentDbFile
		+ ", newGridName=" + newGridName
		+ ", newDbFile=" + newDbFile);
		if (!newDbFile.equals(currentDbFile)) {
		FileLog.d(TAG, "Restored grid is disabled : " + currentGridName
		+ ", migrating to: " + newGridName

src/com/android/launcher3/model/LoaderTask.java

+14 −8

Original line number	Diff line number	Diff line
		@@ -411,7 +411,7 @@ public class LoaderTask implements Runnable {
		mSessionHelper.getActiveSessions();
		installingPkgs.forEach(mApp.getIconCache()::updateSessionCache);
		FileLog.d(TAG, "loadWorkspace: Packages with active install sessions: "
		+ installingPkgs.values());
		+ installingPkgs.keySet().stream().map(info -> info.mPackageName).toList());

		final PackageUserKey tempPackageKey = new PackageUserKey(null, null);
		mFirstScreenBroadcast = new FirstScreenBroadcast(installingPkgs);
		@@ -440,10 +440,15 @@ public class LoaderTask implements Runnable {
		mShortcutKeyToPinnedShortcuts.put(ShortcutKey.fromInfo(shortcut),
		shortcut);
		}
		if (pinnedShortcuts.isEmpty()) {
		FileLog.d(TAG, "No pinned shortcuts found for user " + user);
		}
		} else {
		// Shortcut manager can fail due to some race condition when the
		// lock state changes too frequently. For the purpose of the loading
		// shortcuts, consider the user is still locked.
		FileLog.d(TAG, "Shortcut request failed for user "
		+ user + ", user may still be locked.");
		userUnlocked = false;
		}
		}
		@@ -589,17 +594,17 @@ public class LoaderTask implements Runnable {
		// Package is not yet available but might be
		// installed later.
		FileLog.d(TAG, "package not yet restored: " + targetPkg);

		tempPackageKey.update(targetPkg, c.user);
		if (c.hasRestoreFlag(WorkspaceItemInfo.FLAG_RESTORE_STARTED)) {
		// Restore has started once.
		} else if (installingPkgs.containsKey(tempPackageKey)) {
		// App restore has started. Update the flag
		c.restoreFlag \|= WorkspaceItemInfo.FLAG_RESTORE_STARTED;
		c.updater().put(Favorites.RESTORED,
		c.restoreFlag).commit();
		FileLog.d(TAG, "restore started for installing app: " + targetPkg);
		c.updater().put(Favorites.RESTORED, c.restoreFlag).commit();
		} else {
		c.markDeleted("Unrestored app removed: " + targetPkg);
		c.markDeleted("removing app that is not restored and not "
		+ "installing. package: " + targetPkg);
		return;
		}
		} else if (pmHelper.isAppOnSdcard(targetPkg, c.user)) {
		@@ -610,7 +615,7 @@ public class LoaderTask implements Runnable {
		} else if (!isSdCardReady) {
		// SdCard is not ready yet. Package might get available,
		// once it is ready.
		Log.d(TAG, "Missing pkg, will check later: " + targetPkg);
		Log.d(TAG, "Missing package, will check later: " + targetPkg);
		mPendingPackages.add(new PackageUserKey(targetPkg, c.user));
		// Add the icon on the workspace anyway.
		allowMissingTarget = true;
		@@ -646,7 +651,8 @@ public class LoaderTask implements Runnable {
		ShortcutInfo pinnedShortcut = mShortcutKeyToPinnedShortcuts.get(key);
		if (pinnedShortcut == null) {
		// The shortcut is no longer valid.
		c.markDeleted("Pinned shortcut not found");
		c.markDeleted("Pinned shortcut not found for package: "
		+ key.getPackageName());
		return;
		}
		info = new WorkspaceItemInfo(pinnedShortcut, mApp.getContext());

src/com/android/launcher3/model/ModelDbController.java

+8 −2

Original line number	Diff line number	Diff line
		@@ -62,6 +62,7 @@ import com.android.launcher3.LauncherPrefs;
		import com.android.launcher3.LauncherSettings;
		import com.android.launcher3.LauncherSettings.Favorites;
		import com.android.launcher3.Utilities;
		import com.android.launcher3.logging.FileLog;
		import com.android.launcher3.pm.UserCache;
		import com.android.launcher3.provider.LauncherDbUtils;
		import com.android.launcher3.provider.LauncherDbUtils.SQLiteTransaction;
		@@ -262,7 +263,7 @@ public class ModelDbController {
		*/
		public void tryMigrateDB() {
		if (!migrateGridIfNeeded()) {
		Log.d(TAG, "Migration failed: resetting launcher database");
		FileLog.d(TAG, "Migration failed: resetting launcher database");
		createEmptyDB();
		LauncherPrefs.get(mContext).putSync(
		getEmptyDbCreatedKey(mOpenHelper.getDatabaseName()).to(true));
		@@ -282,15 +283,17 @@ public class ModelDbController {
		createDbIfNotExists();
		if (LauncherPrefs.get(mContext).get(getEmptyDbCreatedKey())) {
		// If we have already create a new DB, ignore migration
		Log.d(TAG, "migrateGridIfNeeded: new DB already created, skipping migration");
		return false;
		}
		InvariantDeviceProfile idp = LauncherAppState.getIDP(mContext);
		if (!GridSizeMigrationUtil.needsToMigrate(mContext, idp)) {
		Log.d(TAG, "migrateGridIfNeeded: no grid migration needed");
		return true;
		}
		String targetDbName = new DeviceGridState(idp).getDbFile();
		if (TextUtils.equals(targetDbName, mOpenHelper.getDatabaseName())) {
		Log.e(TAG, "migrateGridIfNeeded - target db is same as current: " + targetDbName);
		Log.e(TAG, "migrateGridIfNeeded: target db is same as current: " + targetDbName);
		return false;
		}
		DatabaseHelper oldHelper = mOpenHelper;
		@@ -299,6 +302,9 @@ public class ModelDbController {
		try {
		return GridSizeMigrationUtil.migrateGridIfNeeded(mContext, idp, mOpenHelper,
		oldHelper.getWritableDatabase());
		} catch (Exception e) {
		FileLog.e(TAG, "Failed to migrate grid", e);
		return false;
		} finally {
		if (mOpenHelper != oldHelper) {
		oldHelper.close();

src/com/android/launcher3/provider/RestoreDbTask.java

+58 −57

Original line number	Diff line number	Diff line
		@@ -89,9 +89,9 @@ 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"};
		"container", "cellX", "cellY", "spanX", "spanY", "intent", "appWidgetProvider",
		"appWidgetId", "restored"};

		/**
		* Tries to restore the backup DB if needed
		@@ -141,16 +141,17 @@ public class RestoreDbTask {
		* 4. If restored from a single display backup, remove gaps between screenIds
		* 5. Override shortcuts that need to be replaced.
		*
		* @return number of items deleted.
		* @return number of items deleted
		*/
		@VisibleForTesting
		protected int sanitizeDB(Context context, ModelDbController controller, SQLiteDatabase db,
		BackupManager backupManager) throws Exception {
		FileLog.d(TAG, "Old Launcher Database before sanitizing:");
		logFavoritesTable(db, "Old Launcher Database before sanitizing:", null, null);
		// Primary user ids
		long myProfileId = controller.getSerialNumberForUser(myUserHandle());
		long oldProfileId = getDefaultProfileId(db);
		FileLog.d(TAG, "sanitizeDB: myProfileId=" + myProfileId + " oldProfileId=" + oldProfileId);
		FileLog.d(TAG, "sanitizeDB: myProfileId= " + myProfileId
		+ ", oldProfileId= " + oldProfileId);
		LongSparseArray<Long> oldManagedProfileIds = getManagedProfileIds(db, oldProfileId);
		LongSparseArray<Long> profileMapping = new LongSparseArray<>(oldManagedProfileIds.size()
		+ 1);
		@@ -182,7 +183,7 @@ public class RestoreDbTask {
		final String[] args = new String[profileIds.length];
		Arrays.fill(args, "?");
		final String where = "profileId NOT IN (" + TextUtils.join(", ", Arrays.asList(args)) + ")";
		logUnrestoredItems(db, where, profileIds);
		logFavoritesTable(db, "items to delete from unrestored profiles:", where, profileIds);
		int itemsDeletedCount = db.delete(Favorites.TABLE_NAME, where, profileIds);
		FileLog.d(TAG, itemsDeletedCount + " total items from unrestored user(s) were deleted");

		@@ -241,47 +242,6 @@ public class RestoreDbTask {
		return itemsDeletedCount;
		}

		/**
		* 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);
		}
		}

		/**
		* Remove gaps between screenIds to make sure no empty pages are left in between.
		*
		@@ -396,7 +356,7 @@ public class RestoreDbTask {
		IntArray.fromConcatString(lp.get(APP_WIDGET_IDS)).toArray(),
		host);
		} else {
		FileLog.d(TAG, "No app widget ids to restore.");
		FileLog.d(TAG, "No app widget ids were received from backup to restore.");
		}

		lp.remove(APP_WIDGET_IDS, OLD_APP_WIDGET_IDS);
		@@ -409,16 +369,16 @@ public class RestoreDbTask {
		private void restoreAppWidgetIds(Context context, ModelDbController controller,
		int[] oldWidgetIds, int[] newWidgetIds, @NonNull AppWidgetHost host) {
		if (WidgetsModel.GO_DISABLE_WIDGETS) {
		Log.e(TAG, "Skipping widget ID remap as widgets not supported");
		FileLog.e(TAG, "Skipping widget ID remap as widgets not supported");
		host.deleteHost();
		return;
		}
		if (!RestoreDbTask.isPending(context)) {
		// Someone has already gone through our DB once, probably LoaderTask. Skip any further
		// modifications of the DB.
		Log.e(TAG, "Skipping widget ID remap as DB already in use");
		FileLog.e(TAG, "Skipping widget ID remap as DB already in use");
		for (int widgetId : newWidgetIds) {
		Log.d(TAG, "Deleting widgetId: " + widgetId);
		FileLog.d(TAG, "Deleting widgetId: " + widgetId);
		host.deleteAppWidgetId(widgetId);
		}
		return;
		@@ -426,7 +386,7 @@ public class RestoreDbTask {

		final AppWidgetManager widgets = AppWidgetManager.getInstance(context);

		Log.d(TAG, "restoreAppWidgetIds: "
		FileLog.d(TAG, "restoreAppWidgetIds: "
		+ "oldWidgetIds=" + IntArray.wrap(oldWidgetIds).toConcatString()
		+ ", newWidgetIds=" + IntArray.wrap(newWidgetIds).toConcatString());

		@@ -434,7 +394,7 @@ public class RestoreDbTask {
		logDatabaseWidgetInfo(controller);

		for (int i = 0; i < oldWidgetIds.length; i++) {
		Log.i(TAG, "Widget state restore id " + oldWidgetIds[i] + " => " + newWidgetIds[i]);
		FileLog.i(TAG, "Widget state restore id " + oldWidgetIds[i] + " => " + newWidgetIds[i]);

		final AppWidgetProviderInfo provider = widgets.getAppWidgetInfo(newWidgetIds[i]);
		final int state;
		@@ -454,7 +414,7 @@ public class RestoreDbTask {
		final String where = "appWidgetId=? and (restored & 1) = 1 and profileId=?";
		String profileId = Long.toString(mainProfileId);
		final String[] args = new String[] { oldWidgetId, profileId };
		Log.d(TAG, "restoreAppWidgetIds: querying profile id=" + profileId
		FileLog.d(TAG, "restoreAppWidgetIds: querying profile id=" + profileId
		+ " with controller profile ID=" + controllerProfileId);
		int result = new ContentWriter(context,
		new ContentWriter.CommitParams(controller, where, args))
		@@ -463,7 +423,7 @@ public class RestoreDbTask {
		.commit();
		if (result == 0) {
		// TODO(b/234700507): Remove the logs after the bug is fixed
		Log.e(TAG, "restoreAppWidgetIds: remapping failed since the widget is not in"
		FileLog.e(TAG, "restoreAppWidgetIds: remapping failed since the widget is not in"
		+ " the database anymore");
		try (Cursor cursor = controller.getDb().query(
		Favorites.TABLE_NAME,
		@@ -471,7 +431,7 @@ public class RestoreDbTask {
		"appWidgetId=?", new String[]{oldWidgetId}, null, null, null)) {
		if (!cursor.moveToFirst()) {
		// The widget no long exists.
		Log.d(TAG, "Deleting widgetId: " + newWidgetIds[i] + " with old id: "
		FileLog.d(TAG, "Deleting widgetId: " + newWidgetIds[i] + " with old id: "
		+ oldWidgetId);
		host.deleteAppWidgetId(newWidgetIds[i]);
		}
		@@ -523,7 +483,7 @@ public class RestoreDbTask {
		}
		builder.append("]");
		Log.d(TAG, "restoreAppWidgetIds: all widget ids in database: "
		+ builder.toString());
		+ builder);
		} catch (Exception ex) {
		Log.e(TAG, "Getting widget ids from the database failed", ex);
		}
		@@ -572,4 +532,45 @@ public class RestoreDbTask {
		Collectors.joining(" OR "));
		}

		/**
		* Queries and logs the items from the Favorites table 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 logHeader First line in log statement, used to explain what is being logged.
		* @param where The SELECT statement to query items.
		* @param profileIds The profile ID's for each user profile.
		*/
		public static void logFavoritesTable(SQLiteDatabase database, @NonNull String logHeader,
		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(logHeader + "\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, "logFavoritesTable: No items found from query for"
		+ "\"" + logHeader + "\"");
		}
		} catch (Exception e) {
		FileLog.e(TAG, "logFavoritesTable: Error reading from database", e);
		}
		}
		}