Adds more in depth logging of Launcher restore functionality
Test: locally
Flag: N/A
Bug: 294386159
Change-Id: I810239047480090911c54dbe65a4aad8515f640c
diff --git a/src/com/android/launcher3/AppWidgetsRestoredReceiver.java b/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
index 641fd83..429978e 100644
--- a/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
+++ b/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
@@ -9,9 +9,13 @@
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 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 @@
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));
}
}
}
diff --git a/src/com/android/launcher3/InvariantDeviceProfile.java b/src/com/android/launcher3/InvariantDeviceProfile.java
index 567d0c5..d34963e 100644
--- a/src/com/android/launcher3/InvariantDeviceProfile.java
+++ b/src/com/android/launcher3/InvariantDeviceProfile.java
@@ -298,11 +298,15 @@
* 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
diff --git a/src/com/android/launcher3/model/LoaderTask.java b/src/com/android/launcher3/model/LoaderTask.java
index f4ce360..c91bfdf 100644
--- a/src/com/android/launcher3/model/LoaderTask.java
+++ b/src/com/android/launcher3/model/LoaderTask.java
@@ -411,7 +411,7 @@
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 @@
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 @@
// 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 @@
} 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 @@
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());
@@ -816,7 +822,7 @@
} else {
Log.v(TAG, "Widget restore pending id=" + c.id
+ " appWidgetId=" + appWidgetId
- + " status =" + c.restoreFlag);
+ + " status=" + c.restoreFlag);
appWidgetInfo = new LauncherAppWidgetInfo(appWidgetId, component);
appWidgetInfo.restoreStatus = c.restoreFlag;
diff --git a/src/com/android/launcher3/model/ModelDbController.java b/src/com/android/launcher3/model/ModelDbController.java
index 139efc3..d2b7161 100644
--- a/src/com/android/launcher3/model/ModelDbController.java
+++ b/src/com/android/launcher3/model/ModelDbController.java
@@ -62,6 +62,7 @@
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 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 @@
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 @@
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();
diff --git a/src/com/android/launcher3/provider/RestoreDbTask.java b/src/com/android/launcher3/provider/RestoreDbTask.java
index dbd13b3..dc8cd3a 100644
--- a/src/com/android/launcher3/provider/RestoreDbTask.java
+++ b/src/com/android/launcher3/provider/RestoreDbTask.java
@@ -89,9 +89,9 @@
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 @@
* 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 @@
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");
@@ -242,47 +243,6 @@
}
/**
- * 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.
*
* e.g. [0, 3, 4, 6, 7] -> [0, 1, 2, 3, 4]
@@ -396,7 +356,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
.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 @@
"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 @@
}
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 @@
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);
+ }
+ }
}
diff --git a/src/com/android/launcher3/shortcuts/ShortcutRequest.java b/src/com/android/launcher3/shortcuts/ShortcutRequest.java
index 5291ce4..21efceb 100644
--- a/src/com/android/launcher3/shortcuts/ShortcutRequest.java
+++ b/src/com/android/launcher3/shortcuts/ShortcutRequest.java
@@ -24,10 +24,11 @@
import android.content.pm.LauncherApps.ShortcutQuery;
import android.content.pm.ShortcutInfo;
import android.os.UserHandle;
-import android.util.Log;
import androidx.annotation.Nullable;
+import com.android.launcher3.logging.FileLog;
+
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
@@ -101,7 +102,7 @@
return new QueryResult(mContext.getSystemService(LauncherApps.class)
.getShortcuts(mQuery, mUserHandle));
} catch (SecurityException | IllegalStateException e) {
- Log.e(TAG, "Failed to query for shortcuts", e);
+ FileLog.e(TAG, "Failed to query for shortcuts", e);
return QueryResult.DEFAULT;
}
}
