Additional debug logging to triage shortcut related issue. (371dd565) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/pm/ShortcutPackage.java

+43 −7

Original line number	Diff line number	Diff line
		@@ -92,6 +92,7 @@ import java.util.concurrent.CompletableFuture;
		import java.util.function.Consumer;
		import java.util.function.Function;
		import java.util.function.Predicate;
		import java.util.stream.Collectors;

		/**
		* Package information used by {@link ShortcutService}.
		@@ -719,7 +720,7 @@ class ShortcutPackage extends ShortcutPackageItem {

		// If not reset yet, then reset.
		if (mLastResetTime < last) {
		if (ShortcutService.DEBUG) {
		if (ShortcutService.DEBUG \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format("%s: last reset=%d, now=%d, last=%d: resetting",
		getPackageName(), mLastResetTime, now, last));
		}
		@@ -1097,7 +1098,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		}
		final int manifestShortcutSize = newManifestShortcutList == null ? 0
		: newManifestShortcutList.size();
		if (ShortcutService.DEBUG) {
		if (ShortcutService.DEBUG \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG,
		String.format("Package %s has %d manifest shortcut(s), and %d share target(s)",
		getPackageName(), manifestShortcutSize, mShareTargets.size()));
		@@ -1109,7 +1110,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		// disabled.
		return false;
		}
		if (ShortcutService.DEBUG) {
		if (ShortcutService.DEBUG \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format("Package %s %s, version %d -> %d", getPackageName(),
		(isNewApp ? "added" : "updated"),
		getPackageInfo().getVersionCode(), pi.getLongVersionCode()));
		@@ -1198,7 +1199,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		}

		private boolean publishManifestShortcuts(List<ShortcutInfo> newManifestShortcutList) {
		if (ShortcutService.DEBUG) {
		if (ShortcutService.DEBUG \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format(
		"Package %s: publishing manifest shortcuts", getPackageName()));
		}
		@@ -1875,7 +1876,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		final int depth = parser.getDepth();

		final String tag = parser.getName();
		if (ShortcutService.DEBUG_LOAD) {
		if (ShortcutService.DEBUG_LOAD \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format("depth=%d type=%d name=%s", depth, type, tag));
		}
		if ((depth == 1) && TAG_ROOT.equals(tag)) {
		@@ -2010,7 +2011,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		}
		final int depth = parser.getDepth();
		final String tag = parser.getName();
		if (ShortcutService.DEBUG_LOAD) {
		if (ShortcutService.DEBUG_LOAD \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format(" depth=%d type=%d name=%s",
		depth, type, tag));
		}
		@@ -2094,7 +2095,7 @@ class ShortcutPackage extends ShortcutPackageItem {
		}
		final int depth = parser.getDepth();
		final String tag = parser.getName();
		if (ShortcutService.DEBUG_LOAD) {
		if (ShortcutService.DEBUG_LOAD \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, String.format(" depth=%d type=%d name=%s",
		depth, type, tag));
		}
		@@ -2297,6 +2298,12 @@ class ShortcutPackage extends ShortcutPackageItem {
		// No need to invoke AppSearch when there's nothing to save.
		return;
		}
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Saving shortcuts for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName() + " ids=["
		+ shortcuts.stream().map(ShortcutInfo::getId)
		.collect(Collectors.joining(",")) + "]");
		}
		awaitInAppSearch("Saving shortcuts", session -> {
		final AndroidFuture<Boolean> future = new AndroidFuture<>();
		session.put(new PutDocumentsRequest.Builder()
		@@ -2369,6 +2376,10 @@ class ShortcutPackage extends ShortcutPackageItem {
		shortcutIds.add(id);
		}
		}
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Getting shortcuts for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName() + " ids: [" + String.join(",", ids) + "]");
		}
		return awaitInAppSearch("Getting shortcut by id", session -> {
		final AndroidFuture<List<ShortcutInfo>> future = new AndroidFuture<>();
		session.getByUri(
		@@ -2413,6 +2424,10 @@ class ShortcutPackage extends ShortcutPackageItem {

		private void forEachShortcutMutateIf(@NonNull final String query,
		@NonNull final Function<ShortcutInfo, Boolean> cb) {
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Changing shortcuts for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName());
		}
		final SearchResults res = awaitInAppSearch("Mutating shortcuts", session ->
		AndroidFuture.completedFuture(session.search(query, getSearchSpec())));
		if (res == null) return;
		@@ -2434,6 +2449,10 @@ class ShortcutPackage extends ShortcutPackageItem {

		private void forEachShortcutStopWhen(
		@NonNull final String query, @NonNull final Function<ShortcutInfo, Boolean> cb) {
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Iterating shortcuts for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName());
		}
		final SearchResults res = awaitInAppSearch("Iterating shortcuts", session ->
		AndroidFuture.completedFuture(session.search(query, getSearchSpec())));
		if (res == null) return;
		@@ -2447,6 +2466,10 @@ class ShortcutPackage extends ShortcutPackageItem {
		}

		private List<ShortcutInfo> getNextPage(@NonNull final SearchResults res) {
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Get next page for search result for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName());
		}
		final AndroidFuture<List<ShortcutInfo>> future = new AndroidFuture<>();
		final List<ShortcutInfo> ret = new ArrayList<>();
		final long callingIdentity = Binder.clearCallingIdentity();
		@@ -2524,6 +2547,10 @@ class ShortcutPackage extends ShortcutPackageItem {
		@NonNull
		private AndroidFuture<AppSearchSession> setupSchema(
		@NonNull final AppSearchSession session) {
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Setup Schema for user=" + mShortcutUser.getUserId()
		+ " pkg=" + getPackageName());
		}
		SetSchemaRequest.Builder schemaBuilder = new SetSchemaRequest.Builder()
		.addSchemas(AppSearchPerson.SCHEMA, AppSearchShortcutInfo.SCHEMA)
		.setForceOverride(true);
		@@ -2564,6 +2591,15 @@ class ShortcutPackage extends ShortcutPackageItem {
		}

		private void restoreParsedShortcuts(final boolean replace) {
		if (ShortcutService.DEBUG_REBOOT) {
		if (replace) {
		Slog.d(TAG, "Replacing all shortcuts with the ones parsed from xml for user="
		+ mShortcutUser.getUserId() + " pkg=" + getPackageName());
		} else {
		Slog.d(TAG, "Restoring pinned shortcuts from xml for user="
		+ mShortcutUser.getUserId() + " pkg=" + getPackageName());
		}
		}
		if (replace) {
		removeShortcuts();
		}

services/core/java/com/android/server/pm/ShortcutService.java

+29 −21

Original line number	Diff line number	Diff line
		@@ -164,6 +164,7 @@ public class ShortcutService extends IShortcutService.Stub {
		static final boolean DEBUG = false; // STOPSHIP if true
		static final boolean DEBUG_LOAD = false; // STOPSHIP if true
		static final boolean DEBUG_PROCSTATE = false; // STOPSHIP if true
		static final boolean DEBUG_REBOOT = true;

		@VisibleForTesting
		static final long DEFAULT_RESET_INTERVAL_SEC = 24 * 60 * 60; // 1 day
		@@ -659,7 +660,7 @@ public class ShortcutService extends IShortcutService.Stub {

		/** lifecycle event */
		void onBootPhase(int phase) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "onBootPhase: " + phase);
		}
		switch (phase) {
		@@ -674,7 +675,7 @@ public class ShortcutService extends IShortcutService.Stub {

		/** lifecycle event */
		void handleUnlockUser(int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "handleUnlockUser: user=" + userId);
		}
		synchronized (mUnlockedUsers) {
		@@ -699,7 +700,7 @@ public class ShortcutService extends IShortcutService.Stub {

		/** lifecycle event */
		void handleStopUser(int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "handleStopUser: user=" + userId);
		}
		synchronized (mLock) {
		@@ -713,7 +714,7 @@ public class ShortcutService extends IShortcutService.Stub {

		@GuardedBy("mLock")
		private void unloadUserLocked(int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "unloadUserLocked: user=" + userId);
		}
		// Save all dirty information.
		@@ -945,7 +946,7 @@ public class ShortcutService extends IShortcutService.Stub {
		@VisibleForTesting
		void saveBaseStateLocked() {
		final AtomicFile file = getBaseStateFile();
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Saving to " + file.getBaseFile());
		}

		@@ -978,7 +979,7 @@ public class ShortcutService extends IShortcutService.Stub {
		mRawLastResetTime = 0;

		final AtomicFile file = getBaseStateFile();
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Loading from " + file.getBaseFile());
		}
		try (FileInputStream in = file.openRead()) {
		@@ -1028,7 +1029,7 @@ public class ShortcutService extends IShortcutService.Stub {
		@GuardedBy("mLock")
		private void saveUserLocked(@UserIdInt int userId) {
		final File path = getUserFile(userId);
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Saving to " + path);
		}

		@@ -1086,7 +1087,7 @@ public class ShortcutService extends IShortcutService.Stub {
		@Nullable
		private ShortcutUser loadUserLocked(@UserIdInt int userId) {
		final File path = getUserFile(userId);
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Loading from " + path);
		}
		final AtomicFile file = new AtomicFile(path);
		@@ -1095,7 +1096,7 @@ public class ShortcutService extends IShortcutService.Stub {
		try {
		in = file.openRead();
		} catch (FileNotFoundException e) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Not found " + path);
		}
		return null;
		@@ -1132,7 +1133,7 @@ public class ShortcutService extends IShortcutService.Stub {
		final int depth = parser.getDepth();

		final String tag = parser.getName();
		if (DEBUG_LOAD) {
		if (DEBUG_LOAD \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("depth=%d type=%d name=%s",
		depth, type, tag));
		}
		@@ -1157,7 +1158,7 @@ public class ShortcutService extends IShortcutService.Stub {
		private final Runnable mSaveDirtyInfoRunner = this::saveDirtyInfo;

		private void scheduleSaveInner(@UserIdInt int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Scheduling to save for " + userId);
		}
		synchronized (mLock) {
		@@ -1172,7 +1173,7 @@ public class ShortcutService extends IShortcutService.Stub {

		@VisibleForTesting
		void saveDirtyInfo() {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "saveDirtyInfo");
		}
		if (mShutdown.get()) {
		@@ -2942,6 +2943,10 @@ public class ShortcutService extends IShortcutService.Stub {
		@Nullable String packageName, @Nullable List<String> shortcutIds,
		@Nullable List<LocusId> locusIds, @Nullable ComponentName componentName,
		int queryFlags, int userId, int callingPid, int callingUid) {
		if (DEBUG_REBOOT) {
		Slog.d(TAG, "Getting shortcuts for launcher= " + callingPackage
		+ "user=" + userId + " pkg=" + packageName);
		}
		final ArrayList<ShortcutInfo> ret = new ArrayList<>();

		int flags = ShortcutInfo.CLONE_REMOVE_FOR_LAUNCHER;
		@@ -3639,7 +3644,7 @@ public class ShortcutService extends IShortcutService.Stub {
		*/
		@VisibleForTesting
		void checkPackageChanges(@UserIdInt int ownerUserId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "checkPackageChanges() ownerUserId=" + ownerUserId);
		}
		if (injectIsSafeModeEnabled()) {
		@@ -3685,6 +3690,9 @@ public class ShortcutService extends IShortcutService.Stub {

		@GuardedBy("mLock")
		private void rescanUpdatedPackagesLocked(@UserIdInt int userId, long lastScanTime) {
		if (DEBUG_REBOOT) {
		Slog.d(TAG, "rescan updated package user=" + userId + " last scanned=" + lastScanTime);
		}
		final ShortcutUser user = getUserShortcutsLocked(userId);

		// Note after each OTA, we'll need to rescan all system apps, as their lastUpdateTime
		@@ -3708,7 +3716,7 @@ public class ShortcutService extends IShortcutService.Stub {
		}

		private void handlePackageAdded(String packageName, @UserIdInt int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("handlePackageAdded: %s user=%d", packageName, userId));
		}
		synchronized (mLock) {
		@@ -3720,7 +3728,7 @@ public class ShortcutService extends IShortcutService.Stub {
		}

		private void handlePackageUpdateFinished(String packageName, @UserIdInt int userId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("handlePackageUpdateFinished: %s user=%d",
		packageName, userId));
		}
		@@ -3736,7 +3744,7 @@ public class ShortcutService extends IShortcutService.Stub {
		}

		private void handlePackageRemoved(String packageName, @UserIdInt int packageUserId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("handlePackageRemoved: %s user=%d", packageName,
		packageUserId));
		}
		@@ -3746,7 +3754,7 @@ public class ShortcutService extends IShortcutService.Stub {
		}

		private void handlePackageDataCleared(String packageName, int packageUserId) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("handlePackageDataCleared: %s user=%d", packageName,
		packageUserId));
		}
		@@ -3761,7 +3769,7 @@ public class ShortcutService extends IShortcutService.Stub {
		handlePackageRemoved(packageName, packageUserId);
		return;
		}
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, String.format("handlePackageChanged: %s user=%d", packageName,
		packageUserId));
		}
		@@ -3948,7 +3956,7 @@ public class ShortcutService extends IShortcutService.Stub {

		private void forUpdatedPackages(@UserIdInt int userId, long lastScanTime, boolean afterOta,
		Consumer<ApplicationInfo> callback) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "forUpdatedPackages for user " + userId + ", lastScanTime=" + lastScanTime
		+ " afterOta=" + afterOta);
		}
		@@ -3960,7 +3968,7 @@ public class ShortcutService extends IShortcutService.Stub {
		// Also if it's right after an OTA, always re-scan all apps anyway, since the
		// shortcut parser might have changed.
		if (afterOta \|\| (pi.lastUpdateTime >= lastScanTime)) {
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Found updated package " + pi.packageName
		+ " updateTime=" + pi.lastUpdateTime);
		}
		@@ -4313,7 +4321,7 @@ public class ShortcutService extends IShortcutService.Stub {
		@Override
		public void applyRestore(byte[] payload, @UserIdInt int userId) {
		enforceSystem();
		if (DEBUG) {
		if (DEBUG \|\| DEBUG_REBOOT) {
		Slog.d(TAG, "Restoring user " + userId);
		}
		synchronized (mLock) {

services/core/java/com/android/server/pm/ShortcutUser.java

+5 −1

Original line number	Diff line number	Diff line
		@@ -328,6 +328,10 @@ class ShortcutUser {

		public void rescanPackageIfNeeded(@NonNull String packageName, boolean forceRescan) {
		final boolean isNewApp = !mPackages.containsKey(packageName);
		if (ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "rescanPackageIfNeeded " + getUserId() + "@" + packageName
		+ ", forceRescan=" + forceRescan + " , isNewApp=" + isNewApp);
		}

		final ShortcutPackage shortcutPackage = getPackageShortcuts(packageName);

		@@ -397,7 +401,7 @@ class ShortcutUser {
		} else {
		// Save each ShortcutPackageItem in a separate Xml file.
		final File path = getShortcutPackageItemFile(spi);
		if (ShortcutService.DEBUG) {
		if (ShortcutService.DEBUG \|\| ShortcutService.DEBUG_REBOOT) {
		Slog.d(TAG, "Saving package item " + spi.getPackageName() + " to " + path);
		}