Adds more in depth logging of Launcher restore functionality

Test: locally
Flag: N/A
Bug: 294386159
Change-Id: I810239047480090911c54dbe65a4aad8515f640c

6 files changed, 107 insertions, 72 deletions

diff --git a/src/com/android/launcher3/AppWidgetsRestoredReceiver.java b/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
index 641fd834e2..429978eeb4 100644
--- a/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
+++ b/src/com/android/launcher3/AppWidgetsRestoredReceiver.java
@@ -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));
             }
         }
     }
diff --git a/src/com/android/launcher3/InvariantDeviceProfile.java b/src/com/android/launcher3/InvariantDeviceProfile.java
index 567d0c503f..d34963ea6a 100644
--- a/src/com/android/launcher3/InvariantDeviceProfile.java
+++ b/src/com/android/launcher3/InvariantDeviceProfile.java
@@ -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
diff --git a/src/com/android/launcher3/model/LoaderTask.java b/src/com/android/launcher3/model/LoaderTask.java
index f4ce3607f7..c91bfdf8d0 100644
--- a/src/com/android/launcher3/model/LoaderTask.java
+++ b/src/com/android/launcher3/model/LoaderTask.java
@@ -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());
@@ -816,7 +822,7 @@ public class LoaderTask implements Runnable {
                         } 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 139efc3d99..d2b7161697 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.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();
diff --git a/src/com/android/launcher3/provider/RestoreDbTask.java b/src/com/android/launcher3/provider/RestoreDbTask.java
index dbd13b38ad..dc8cd3af65 100644
--- a/src/com/android/launcher3/provider/RestoreDbTask.java
+++ b/src/com/android/launcher3/provider/RestoreDbTask.java
@@ -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");
 
@@ -242,47 +243,6 @@ public class RestoreDbTask {
     }
 
     /**
-     * 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 @@ 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);
+        }
+    }
 }
diff --git a/src/com/android/launcher3/shortcuts/ShortcutRequest.java b/src/com/android/launcher3/shortcuts/ShortcutRequest.java
index 5291ce4620..21efceb0fd 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;
 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 @@ public class ShortcutRequest {
             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;
         }
     }