From a8e003f538a4a960d312a355a3c3d5e4c9376b22 Mon Sep 17 00:00:00 2001 From: Suprabh Shukla Date: Tue, 27 Apr 2021 15:18:31 -0700 Subject: [PATCH] Recording alarm removal reasons for debugging If an alarm is removed from the service for some reason, the bugreport contains no useful information about it. Recording the last 10 removes with their reason. For now, the set of reasons includes: - Data cleared on the calling app. - App requested to cancel it. - Exact alarm permission revoked. - PendingIntent used to set the alarm was cancelled. More reasons can be added as seen useful in the future. Test: adb shell dumpsys alarm atest FrameworksMockingServicesTests:com.android.server.alarm atest CtsAlarmManagerTestCases Fixes: 184677899 Change-Id: I9d67b90572b5d731ad5d224ae7d537ae176508d5 --- .../server/alarm/AlarmManagerService.java | 149 ++++++++++++++---- .../server/alarm/AlarmManagerServiceTest.java | 30 ++-- 2 files changed, 136 insertions(+), 43 deletions(-) diff --git a/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java b/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java index aafeb48b7c599..54e47cf2f13d3 100644 --- a/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java +++ b/apex/jobscheduler/service/java/com/android/server/alarm/AlarmManagerService.java @@ -43,6 +43,11 @@ import static com.android.server.alarm.Alarm.EXACT_ALLOW_REASON_COMPAT; import static com.android.server.alarm.Alarm.EXACT_ALLOW_REASON_NOT_APPLICABLE; import static com.android.server.alarm.Alarm.EXACT_ALLOW_REASON_PERMISSION; import static com.android.server.alarm.Alarm.REQUESTER_POLICY_INDEX; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_ALARM_CANCELLED; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_DATA_CLEARED; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_EXACT_PERMISSION_REVOKED; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_PI_CANCELLED; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_UNDEFINED; import android.Manifest; import android.annotation.NonNull; @@ -116,6 +121,7 @@ import com.android.internal.app.IAppOpsService; import com.android.internal.util.DumpUtils; import com.android.internal.util.FrameworkStatsLog; import com.android.internal.util.LocalLog; +import com.android.internal.util.RingBuffer; import com.android.internal.util.StatLogger; import com.android.server.AlarmManagerInternal; import com.android.server.AppStateTracker; @@ -160,6 +166,7 @@ import java.util.function.Predicate; public class AlarmManagerService extends SystemService { private static final int RTC_WAKEUP_MASK = 1 << RTC_WAKEUP; private static final int ELAPSED_REALTIME_WAKEUP_MASK = 1 << ELAPSED_REALTIME_WAKEUP; + private static final int REMOVAL_HISTORY_SIZE_PER_UID = 10; static final int TIME_CHANGED_MASK = 1 << 16; static final int IS_WAKEUP_MASK = RTC_WAKEUP_MASK | ELAPSED_REALTIME_WAKEUP_MASK; @@ -238,6 +245,7 @@ public class AlarmManagerService extends SystemService { AppWakeupHistory mAppWakeupHistory; AppWakeupHistory mAllowWhileIdleHistory; private final SparseLongArray mLastPriorityAlarmDispatch = new SparseLongArray(); + private final SparseArray> mRemovalHistory = new SparseArray<>(); ClockReceiver mClockReceiver; final DeliveryTracker mDeliveryTracker = new DeliveryTracker(); IBinder.DeathRecipient mListenerDeathRecipient; @@ -392,6 +400,57 @@ public class AlarmManagerService extends SystemService { } } + static class RemovedAlarm { + static final int REMOVE_REASON_UNDEFINED = 0; + static final int REMOVE_REASON_ALARM_CANCELLED = 1; + static final int REMOVE_REASON_EXACT_PERMISSION_REVOKED = 2; + static final int REMOVE_REASON_DATA_CLEARED = 3; + static final int REMOVE_REASON_PI_CANCELLED = 4; + + final String mTag; + final long mWhenRemovedElapsed; + final long mWhenRemovedRtc; + final int mRemoveReason; + + RemovedAlarm(Alarm a, int removeReason, long nowRtc, long nowElapsed) { + mTag = a.statsTag; + mRemoveReason = removeReason; + mWhenRemovedRtc = nowRtc; + mWhenRemovedElapsed = nowElapsed; + } + + static final boolean isLoggable(int reason) { + // We don't want to log meaningless reasons. This also gives a way for callers to + // opt out of logging, e.g. when replacing an alarm. + return reason != REMOVE_REASON_UNDEFINED; + } + + static final String removeReasonToString(int reason) { + switch (reason) { + case REMOVE_REASON_ALARM_CANCELLED: + return "alarm_cancelled"; + case REMOVE_REASON_EXACT_PERMISSION_REVOKED: + return "exact_alarm_permission_revoked"; + case REMOVE_REASON_DATA_CLEARED: + return "data_cleared"; + case REMOVE_REASON_PI_CANCELLED: + return "pi_cancelled"; + default: + return "unknown:" + reason; + } + } + + void dump(IndentingPrintWriter pw, long nowElapsed, SimpleDateFormat sdf) { + pw.print("[tag", mTag); + pw.print("reason", removeReasonToString(mRemoveReason)); + pw.print("elapsed="); + TimeUtils.formatDuration(mWhenRemovedElapsed, nowElapsed, pw); + pw.print(" rtc="); + pw.print(sdf.format(new Date(mWhenRemovedRtc))); + pw.println("]"); + } + } + /** * All times are in milliseconds. These constants are kept synchronized with the system * global Settings. Any access to this class or its fields should be done while @@ -1691,7 +1750,7 @@ public class AlarmManagerService extends SystemService { void removeImpl(PendingIntent operation, IAlarmListener listener) { synchronized (mLock) { - removeLocked(operation, listener); + removeLocked(operation, listener, REMOVE_REASON_UNDEFINED); } } @@ -1812,7 +1871,7 @@ public class AlarmManagerService extends SystemService { + " -- package not allowed to start"); return; } - removeLocked(operation, directReceiver); + removeLocked(operation, directReceiver, REMOVE_REASON_UNDEFINED); incrementAlarmCount(a.uid); setImplLocked(a); MetricsHelper.pushAlarmScheduled(a); @@ -2106,7 +2165,7 @@ public class AlarmManagerService extends SystemService { @Override public void removeAlarmsForUid(int uid) { synchronized (mLock) { - removeLocked(uid); + removeLocked(uid, REMOVE_REASON_DATA_CLEARED); } } @@ -2342,7 +2401,7 @@ public class AlarmManagerService extends SystemService { return; } synchronized (mLock) { - removeLocked(operation, listener); + removeLocked(operation, listener, REMOVE_REASON_ALARM_CANCELLED); } } @@ -2688,6 +2747,7 @@ public class AlarmManagerService extends SystemService { pw.println("Allow while idle history:"); mAllowWhileIdleHistory.dump(pw, nowELAPSED); + pw.println(); if (mLastPriorityAlarmDispatch.size() > 0) { pw.println("Last priority alarm dispatches:"); @@ -2702,6 +2762,23 @@ public class AlarmManagerService extends SystemService { pw.decreaseIndent(); } + if (mRemovalHistory.size() > 0) { + pw.println("Removal history: "); + pw.increaseIndent(); + for (int i = 0; i < mRemovalHistory.size(); i++) { + UserHandle.formatUid(pw, mRemovalHistory.keyAt(i)); + pw.println(":"); + pw.increaseIndent(); + final RemovedAlarm[] historyForUid = mRemovalHistory.valueAt(i).toArray(); + for (final RemovedAlarm removedAlarm : historyForUid) { + removedAlarm.dump(pw, nowELAPSED, sdf); + } + pw.decreaseIndent(); + } + pw.decreaseIndent(); + pw.println(); + } + if (mLog.dump(pw, "Recent problems:")) { pw.println(); } @@ -3239,7 +3316,7 @@ public class AlarmManagerService extends SystemService { } return !hasScheduleExactAlarmInternal(a.packageName, a.uid); }; - removeAlarmsInternalLocked(whichAlarms); + removeAlarmsInternalLocked(whichAlarms, REMOVE_REASON_EXACT_PERMISSION_REVOKED); } /** @@ -3247,7 +3324,6 @@ public class AlarmManagerService extends SystemService { * that the app is no longer eligible to use. * * This is not expected to get called frequently. - * TODO (b/179541791): Add revocation history to dumpsys. */ void removeExactAlarmsOnPermissionRevokedLocked(int uid, String packageName) { Slog.w(TAG, "Package " + packageName + ", uid " + uid + " lost SCHEDULE_EXACT_ALARM!"); @@ -3263,26 +3339,22 @@ public class AlarmManagerService extends SystemService { } return false; }; - removeAlarmsInternalLocked(whichAlarms); + removeAlarmsInternalLocked(whichAlarms, REMOVE_REASON_EXACT_PERMISSION_REVOKED); } - private void removeAlarmsInternalLocked(Predicate whichAlarms) { + private void removeAlarmsInternalLocked(Predicate whichAlarms, int reason) { + final long nowRtc = mInjector.getCurrentTimeMillis(); + final long nowElapsed = mInjector.getElapsedRealtime(); + final ArrayList removedAlarms = mAlarmStore.remove(whichAlarms); - final boolean didRemove = !removedAlarms.isEmpty(); - if (didRemove) { - for (final Alarm removed : removedAlarms) { - decrementAlarmCount(removed.uid, 1); - } - } + final boolean removedFromStore = !removedAlarms.isEmpty(); for (int i = mPendingBackgroundAlarms.size() - 1; i >= 0; i--) { final ArrayList alarmsForUid = mPendingBackgroundAlarms.valueAt(i); for (int j = alarmsForUid.size() - 1; j >= 0; j--) { final Alarm alarm = alarmsForUid.get(j); if (whichAlarms.test(alarm)) { - // Don't set didRemove, since this doesn't impact the scheduled alarms. - alarmsForUid.remove(j); - decrementAlarmCount(alarm.uid, 1); + removedAlarms.add(alarmsForUid.remove(j)); } } if (alarmsForUid.size() == 0) { @@ -3292,13 +3364,24 @@ public class AlarmManagerService extends SystemService { for (int i = mPendingNonWakeupAlarms.size() - 1; i >= 0; i--) { final Alarm a = mPendingNonWakeupAlarms.get(i); if (whichAlarms.test(a)) { - // Don't set didRemove, since this doesn't impact the scheduled alarms. - mPendingNonWakeupAlarms.remove(i); - decrementAlarmCount(a.uid, 1); + removedAlarms.add(mPendingNonWakeupAlarms.remove(i)); } } - if (didRemove) { + for (final Alarm removed : removedAlarms) { + decrementAlarmCount(removed.uid, 1); + if (!RemovedAlarm.isLoggable(reason)) { + continue; + } + RingBuffer bufferForUid = mRemovalHistory.get(removed.uid); + if (bufferForUid == null) { + bufferForUid = new RingBuffer<>(RemovedAlarm.class, REMOVAL_HISTORY_SIZE_PER_UID); + mRemovalHistory.put(removed.uid, bufferForUid); + } + bufferForUid.append(new RemovedAlarm(removed, reason, nowRtc, nowElapsed)); + } + + if (removedFromStore) { boolean idleUntilUpdated = false; if (mPendingIdleUntil != null && whichAlarms.test(mPendingIdleUntil)) { mPendingIdleUntil = null; @@ -3320,7 +3403,7 @@ public class AlarmManagerService extends SystemService { } } - void removeLocked(PendingIntent operation, IAlarmListener directReceiver) { + void removeLocked(PendingIntent operation, IAlarmListener directReceiver, int reason) { if (operation == null && directReceiver == null) { if (localLOGV) { Slog.w(TAG, "requested remove() of null operation", @@ -3328,15 +3411,15 @@ public class AlarmManagerService extends SystemService { } return; } - removeAlarmsInternalLocked(a -> a.matches(operation, directReceiver)); + removeAlarmsInternalLocked(a -> a.matches(operation, directReceiver), reason); } - void removeLocked(final int uid) { + void removeLocked(final int uid, int reason) { if (uid == Process.SYSTEM_UID) { // If a force-stop occurs for a system-uid package, ignore it. return; } - removeAlarmsInternalLocked(a -> a.uid == uid); + removeAlarmsInternalLocked(a -> a.uid == uid, reason); } void removeLocked(final String packageName) { @@ -3347,7 +3430,7 @@ public class AlarmManagerService extends SystemService { } return; } - removeAlarmsInternalLocked(a -> a.matches(packageName)); + removeAlarmsInternalLocked(a -> a.matches(packageName), REMOVE_REASON_UNDEFINED); } // Only called for ephemeral apps @@ -3358,7 +3441,7 @@ public class AlarmManagerService extends SystemService { } final Predicate whichAlarms = (a) -> (a.uid == uid && mActivityManagerInternal.isAppStartModeDisabled(uid, a.packageName)); - removeAlarmsInternalLocked(whichAlarms); + removeAlarmsInternalLocked(whichAlarms, REMOVE_REASON_UNDEFINED); } void removeUserLocked(int userHandle) { @@ -3368,13 +3451,18 @@ public class AlarmManagerService extends SystemService { } final Predicate whichAlarms = (Alarm a) -> UserHandle.getUserId(a.uid) == userHandle; - removeAlarmsInternalLocked(whichAlarms); + removeAlarmsInternalLocked(whichAlarms, REMOVE_REASON_UNDEFINED); for (int i = mLastPriorityAlarmDispatch.size() - 1; i >= 0; i--) { if (UserHandle.getUserId(mLastPriorityAlarmDispatch.keyAt(i)) == userHandle) { mLastPriorityAlarmDispatch.removeAt(i); } } + for (int i = mRemovalHistory.size() - 1; i >= 0; i--) { + if (UserHandle.getUserId(mRemovalHistory.keyAt(i)) == userHandle) { + mRemovalHistory.removeAt(i); + } + } } void interactiveStateChangedLocked(boolean interactive) { @@ -4018,7 +4106,7 @@ public class AlarmManagerService extends SystemService { case REMOVE_FOR_CANCELED: final PendingIntent operation = (PendingIntent) msg.obj; synchronized (mLock) { - removeLocked(operation, null); + removeLocked(operation, null, REMOVE_REASON_PI_CANCELLED); } break; @@ -4198,6 +4286,7 @@ public class AlarmManagerService extends SystemService { return; case Intent.ACTION_UID_REMOVED: mLastPriorityAlarmDispatch.delete(uid); + mRemovalHistory.delete(uid); return; case Intent.ACTION_PACKAGE_REMOVED: if (intent.getBooleanExtra(Intent.EXTRA_REPLACING, false)) { @@ -4227,7 +4316,7 @@ public class AlarmManagerService extends SystemService { // package-removed and package-restarted case mAppWakeupHistory.removeForPackage(pkg, UserHandle.getUserId(uid)); mAllowWhileIdleHistory.removeForPackage(pkg, UserHandle.getUserId(uid)); - removeLocked(uid); + removeLocked(uid, REMOVE_REASON_UNDEFINED); } else { // external-applications-unavailable case removeLocked(pkg); diff --git a/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java b/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java index 3bc1c8a4037d8..64dad7f0feab7 100644 --- a/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/alarm/AlarmManagerServiceTest.java @@ -80,6 +80,7 @@ import static com.android.server.alarm.AlarmManagerService.Constants.MAX_EXACT_A import static com.android.server.alarm.AlarmManagerService.FREQUENT_INDEX; import static com.android.server.alarm.AlarmManagerService.INDEFINITE_DELAY; import static com.android.server.alarm.AlarmManagerService.IS_WAKEUP_MASK; +import static com.android.server.alarm.AlarmManagerService.RemovedAlarm.REMOVE_REASON_UNDEFINED; import static com.android.server.alarm.AlarmManagerService.TIME_CHANGED_MASK; import static com.android.server.alarm.AlarmManagerService.WORKING_INDEX; import static com.android.server.alarm.Constants.TEST_CALLING_PACKAGE; @@ -771,10 +772,10 @@ public class AlarmManagerServiceTest { setTestAlarm(ELAPSED_REALTIME_WAKEUP, mNowElapsedTest + 6, pi6); assertEquals(mNowElapsedTest + 6, mTestTimer.getElapsed()); - mService.removeLocked(pi6, null); + mService.removeLocked(pi6, null, REMOVE_REASON_UNDEFINED); assertEquals(mNowElapsedTest + 8, mTestTimer.getElapsed()); - mService.removeLocked(pi8, null); + mService.removeLocked(pi8, null, REMOVE_REASON_UNDEFINED); assertEquals(mNowElapsedTest + 9, mTestTimer.getElapsed()); } @@ -1252,7 +1253,8 @@ public class AlarmManagerServiceTest { setTestAlarm(ELAPSED_REALTIME, mNowElapsedTest + i + 10, getNewMockPendingIntent()); } assertEquals(numAlarms, mService.mAlarmsPerUid.get(TEST_CALLING_UID)); - mService.removeLocked(TEST_CALLING_UID); + mService.removeLocked(TEST_CALLING_UID, + REMOVE_REASON_UNDEFINED); assertEquals(0, mService.mAlarmsPerUid.get(TEST_CALLING_UID, 0)); } @@ -1292,7 +1294,7 @@ public class AlarmManagerServiceTest { } assertEquals(numAlarms, mService.mAlarmsPerUid.get(TEST_CALLING_UID)); for (int i = 0; i < numAlarms; i++) { - mService.removeLocked(pis[i], null); + mService.removeLocked(pis[i], null, REMOVE_REASON_UNDEFINED); assertEquals(numAlarms - i - 1, mService.mAlarmsPerUid.get(TEST_CALLING_UID, 0)); } } @@ -1422,7 +1424,7 @@ public class AlarmManagerServiceTest { mTestTimer.expire(); assertEquals(numAlarms, mService.mPendingNonWakeupAlarms.size()); for (int i = 0; i < numAlarms; i++) { - mService.removeLocked(pis[i], null); + mService.removeLocked(pis[i], null, REMOVE_REASON_UNDEFINED); assertEquals(numAlarms - i - 1, mService.mAlarmsPerUid.get(TEST_CALLING_UID, 0)); } } @@ -1492,13 +1494,13 @@ public class AlarmManagerServiceTest { assertEquals(trigger6, mTestTimer.getElapsed()); assertEquals(trigger6, mService.mNextWakeFromIdle.getWhenElapsed()); - mService.removeLocked(wakeFromIdle6, null); + mService.removeLocked(wakeFromIdle6, null, REMOVE_REASON_UNDEFINED); assertTrue(mService.mNextWakeFromIdle.matches(wakeFromIdle10, null)); assertEquals(trigger10, mTestTimer.getElapsed()); assertEquals(trigger10, mService.mNextWakeFromIdle.getWhenElapsed()); - mService.removeLocked(wakeFromIdle10, null); + mService.removeLocked(wakeFromIdle10, null, REMOVE_REASON_UNDEFINED); assertNull(mService.mNextWakeFromIdle); } @@ -1524,13 +1526,13 @@ public class AlarmManagerServiceTest { setWakeFromIdle(ELAPSED_REALTIME_WAKEUP, mNowElapsedTest + 12, wakeFromIdle12); assertEquals(mNowElapsedTest + 5, mService.mPendingIdleUntil.getWhenElapsed()); - mService.removeLocked(wakeFromIdle5, null); + mService.removeLocked(wakeFromIdle5, null, REMOVE_REASON_UNDEFINED); assertEquals(mNowElapsedTest + 8, mService.mPendingIdleUntil.getWhenElapsed()); - mService.removeLocked(wakeFromIdle8, null); + mService.removeLocked(wakeFromIdle8, null, REMOVE_REASON_UNDEFINED); assertEquals(requestedIdleUntil, mService.mPendingIdleUntil.getWhenElapsed()); - mService.removeLocked(idleUntilPi, null); + mService.removeLocked(idleUntilPi, null, REMOVE_REASON_UNDEFINED); assertNull(mService.mPendingIdleUntil); setIdleUntilAlarm(ELAPSED_REALTIME_WAKEUP, mNowElapsedTest + 15, idleUntilPi); @@ -1641,7 +1643,7 @@ public class AlarmManagerServiceTest { verify(pis[0], never()).send(eq(mMockContext), eq(0), any(Intent.class), any(), any(Handler.class), isNull(), any()); - mService.removeLocked(idleUntil, null); + mService.removeLocked(idleUntil, null, REMOVE_REASON_UNDEFINED); mTestTimer.expire(); // Now, the first 5 alarms (upto i = 4) should expire. for (int i = 0; i < 5; i++) { @@ -1688,14 +1690,16 @@ public class AlarmManagerServiceTest { getNewMockPendingIntent(), false), quota, mAllowWhileIdleWindow); // Refresh the state - mService.removeLocked(TEST_CALLING_UID); + mService.removeLocked(TEST_CALLING_UID, + REMOVE_REASON_UNDEFINED); mService.mAllowWhileIdleHistory.removeForPackage(TEST_CALLING_PACKAGE, TEST_CALLING_USER); testQuotasDeferralOnExpiration(trigger -> setAllowWhileIdleAlarm(ELAPSED_REALTIME_WAKEUP, trigger, getNewMockPendingIntent(), false), quota, mAllowWhileIdleWindow); // Refresh the state - mService.removeLocked(TEST_CALLING_UID); + mService.removeLocked(TEST_CALLING_UID, + REMOVE_REASON_UNDEFINED); mService.mAllowWhileIdleHistory.removeForPackage(TEST_CALLING_PACKAGE, TEST_CALLING_USER); testQuotasNoDeferral(trigger -> setAllowWhileIdleAlarm(ELAPSED_REALTIME_WAKEUP, trigger,