Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Beef up logging in and near tryRemoveNotification

Browse Source 
We're ending up removing a notification twice -- probably a race
between clear all and dismissing or cancelling one of the notifications
hit by the clear all.

Long term, we want to figure out how this is happening, which means
catching the erroneous state changes earlier or at a higher level, so
this adds a bunch of logging around edge cases in the dismissal process
in NotifCollection.

Bug: 282945192
Test: presubmit
Change-Id: I452ae013b539208a26304caba17a3b8630f5e685
This commit is contained in:
Julia Tuttle
2023-06-08 16:06:08 -04:00
parent 89c150dac0
commit 17847aab20
2 changed files with 215 additions and 40 deletions
Download Patch File Download Diff File Expand all files Collapse all files

82
packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifCollection.java
View File

@@ -275,6 +275,7 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
Assert.isMainThread();
checkForReentrantCall();
final int entryCount = entriesToDismiss.size();
final List<NotificationEntry> entriesToLocallyDismiss = new ArrayList<>();
for (int i = 0; i < entriesToDismiss.size(); i++) {
NotificationEntry entry = entriesToDismiss.get(i).first;
@@ -283,28 +284,34 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
requireNonNull(stats);
NotificationEntry storedEntry = mNotificationSet.get(entry.getKey());
if (storedEntry == null) {
mLogger.logNonExistentNotifDismissed(entry);
mLogger.logDismissNonExistentNotif(entry, i, entryCount);
continue;
}
if (entry != storedEntry) {
throw mEulogizer.record(
new IllegalStateException("Invalid entry: "
+ "different stored and dismissed entries for " + logKey(entry)
+ " (" + i + "/" + entryCount + ")"
+ " dismissed=@" + Integer.toHexString(entry.hashCode())
+ " stored=@" + Integer.toHexString(storedEntry.hashCode())));
}
if (entry.getDismissState() == DISMISSED) {
mLogger.logDismissAlreadyDismissedNotif(entry, i, entryCount);
continue;
} else if (entry.getDismissState() == PARENT_DISMISSED) {
mLogger.logDismissAlreadyParentDismissedNotif(entry, i, entryCount);
}
updateDismissInterceptors(entry);
if (isDismissIntercepted(entry)) {
mLogger.logNotifDismissedIntercepted(entry);
mLogger.logNotifDismissedIntercepted(entry, i, entryCount);
continue;
}
entriesToLocallyDismiss.add(entry);
if (!entry.isCanceled()) {
int finalI = i;
// send message to system server if this notification hasn't already been cancelled
mBgExecutor.execute(() -> {
try {
@@ -317,7 +324,7 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
stats.notificationVisibility);
} catch (RemoteException e) {
// system process is dead if we're here.
mLogger.logRemoteExceptionOnNotificationClear(entry, e);
mLogger.logRemoteExceptionOnNotificationClear(entry, finalI, entryCount, e);
}
});
}
@@ -354,14 +361,16 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
}
final List<NotificationEntry> entries = new ArrayList<>(getAllNotifs());
final int initialEntryCount = entries.size();
for (int i = entries.size() - 1; i >= 0; i--) {
NotificationEntry entry = entries.get(i);
if (!shouldDismissOnClearAll(entry, userId)) {
// system server won't be removing these notifications, but we still give dismiss
// interceptors the chance to filter the notification
updateDismissInterceptors(entry);
if (isDismissIntercepted(entry)) {
mLogger.logNotifClearAllDismissalIntercepted(entry);
mLogger.logNotifClearAllDismissalIntercepted(entry, i, initialEntryCount);
}
entries.remove(i);
}
@@ -377,25 +386,46 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
*/
private void locallyDismissNotifications(List<NotificationEntry> entries) {
final List<NotificationEntry> canceledEntries = new ArrayList<>();
final int entryCount = entries.size();
for (int i = 0; i < entries.size(); i++) {
NotificationEntry entry = entries.get(i);
final NotificationEntry storedEntry = mNotificationSet.get(entry.getKey());
if (storedEntry == null) {
mLogger.logLocallyDismissNonExistentNotif(entry, i, entryCount);
} else if (storedEntry != entry) {
mLogger.logLocallyDismissMismatchedEntry(entry, i, entryCount, storedEntry);
}
if (entry.getDismissState() == DISMISSED) {
mLogger.logLocallyDismissAlreadyDismissedNotif(entry, i, entryCount);
} else if (entry.getDismissState() == PARENT_DISMISSED) {
mLogger.logLocallyDismissAlreadyParentDismissedNotif(entry, i, entryCount);
}
entry.setDismissState(DISMISSED);
mLogger.logNotifDismissed(entry);
mLogger.logLocallyDismissed(entry, i, entryCount);
if (entry.isCanceled()) {
canceledEntries.add(entry);
} else {
// Mark any children as dismissed as system server will auto-dismiss them as well
if (entry.getSbn().getNotification().isGroupSummary()) {
for (NotificationEntry otherEntry : mNotificationSet.values()) {
if (shouldAutoDismissChildren(otherEntry, entry.getSbn().getGroupKey())) {
otherEntry.setDismissState(PARENT_DISMISSED);
mLogger.logChildDismissed(otherEntry);
if (otherEntry.isCanceled()) {
canceledEntries.add(otherEntry);
}
continue;
}
// Mark any children as dismissed as system server will auto-dismiss them as well
if (entry.getSbn().getNotification().isGroupSummary()) {
for (NotificationEntry otherEntry : mNotificationSet.values()) {
if (shouldAutoDismissChildren(otherEntry, entry.getSbn().getGroupKey())) {
if (otherEntry.getDismissState() == DISMISSED) {
mLogger.logLocallyDismissAlreadyDismissedChild(
otherEntry, entry, i, entryCount);
} else if (otherEntry.getDismissState() == PARENT_DISMISSED) {
mLogger.logLocallyDismissAlreadyParentDismissedChild(
otherEntry, entry, i, entryCount);
}
otherEntry.setDismissState(PARENT_DISMISSED);
mLogger.logLocallyDismissedChild(otherEntry, entry, i, entryCount);
if (otherEntry.isCanceled()) {
canceledEntries.add(otherEntry);
}
}
}
@@ -405,7 +435,7 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
// Immediately remove any dismissed notifs that have already been canceled by system server
// (probably due to being lifetime-extended up until this point).
for (NotificationEntry canceledEntry : canceledEntries) {
mLogger.logDismissOnAlreadyCanceledEntry(canceledEntry);
mLogger.logLocallyDismissedAlreadyCanceledEntry(canceledEntry);
tryRemoveNotification(canceledEntry);
}
}
@@ -737,14 +767,16 @@ public class NotifCollection implements Dumpable, PipelineDumpable {
}
private void cancelLocalDismissal(NotificationEntry entry) {
if (entry.getDismissState() != NOT_DISMISSED) {
entry.setDismissState(NOT_DISMISSED);
if (entry.getSbn().getNotification().isGroupSummary()) {
for (NotificationEntry otherEntry : mNotificationSet.values()) {
if (otherEntry.getSbn().getGroupKey().equals(entry.getSbn().getGroupKey())
&& otherEntry.getDismissState() == PARENT_DISMISSED) {
otherEntry.setDismissState(NOT_DISMISSED);
}
if (entry.getDismissState() == NOT_DISMISSED) {
mLogger.logCancelLocalDismissalNotDismissedNotif(entry);
return;
}
entry.setDismissState(NOT_DISMISSED);
if (entry.getSbn().getNotification().isGroupSummary()) {
for (NotificationEntry otherEntry : mNotificationSet.values()) {
if (otherEntry.getSbn().getGroupKey().equals(entry.getSbn().getGroupKey())
&& otherEntry.getDismissState() == PARENT_DISMISSED) {
otherEntry.setDismissState(NOT_DISMISSED);
}
}
}

173
packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/notifcollection/NotifCollectionLogger.kt
View File

@@ -108,27 +108,39 @@ class NotifCollectionLogger @Inject constructor(
})
}
fun logNotifDismissed(entry: NotificationEntry) {
fun logLocallyDismissed(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"DISMISSED $str1"
"LOCALLY DISMISSED $str1 ($int1/$int2)"
})
}
fun logNonExistentNotifDismissed(entry: NotificationEntry) {
fun logDismissNonExistentNotif(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"DISMISSED Non Existent $str1"
"DISMISS Non Existent $str1 ($int1/$int2)"
})
}
fun logChildDismissed(entry: NotificationEntry) {
fun logLocallyDismissedChild(
child: NotificationEntry,
parent: NotificationEntry,
parentIndex: Int,
parentCount: Int
) {
buffer.log(TAG, DEBUG, {
str1 = entry.logKey
str1 = child.logKey
str2 = parent.logKey
int1 = parentIndex
int2 = parentCount
}, {
"CHILD DISMISSED (inferred): $str1"
"LOCALLY DISMISSED CHILD (inferred): $str1 of parent $str2 ($int1/$int2)"
})
}
@@ -140,27 +152,31 @@ class NotifCollectionLogger @Inject constructor(
})
}
fun logDismissOnAlreadyCanceledEntry(entry: NotificationEntry) {
fun logLocallyDismissedAlreadyCanceledEntry(entry: NotificationEntry) {
buffer.log(TAG, DEBUG, {
str1 = entry.logKey
}, {
"Dismiss on $str1, which was already canceled. Trying to remove..."
"LOCALLY DISMISSED Already Canceled $str1. Trying to remove."
})
}
fun logNotifDismissedIntercepted(entry: NotificationEntry) {
fun logNotifDismissedIntercepted(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"DISMISS INTERCEPTED $str1"
"DISMISS INTERCEPTED $str1 ($int1/$int2)"
})
}
fun logNotifClearAllDismissalIntercepted(entry: NotificationEntry) {
fun logNotifClearAllDismissalIntercepted(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"CLEAR ALL DISMISSAL INTERCEPTED $str1"
"CLEAR ALL DISMISSAL INTERCEPTED $str1 ($int1/$int2)"
})
}
@@ -251,12 +267,19 @@ class NotifCollectionLogger @Inject constructor(
})
}
fun logRemoteExceptionOnNotificationClear(entry: NotificationEntry, e: RemoteException) {
fun logRemoteExceptionOnNotificationClear(
entry: NotificationEntry,
index: Int,
count: Int,
e: RemoteException
) {
buffer.log(TAG, WTF, {
str1 = entry.logKey
int1 = index
int2 = count
str2 = e.toString()
}, {
"RemoteException while attempting to clear $str1:\n$str2"
"RemoteException while attempting to clear $str1 ($int1/$int2):\n$str2"
})
}
@@ -387,6 +410,126 @@ class NotifCollectionLogger @Inject constructor(
"Mismatch: current $str2 is $str3 for: $str1"
})
}
fun logDismissAlreadyDismissedNotif(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, DEBUG, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"DISMISS Already Dismissed $str1 ($int1/$int2)"
})
}
fun logDismissAlreadyParentDismissedNotif(
childEntry: NotificationEntry,
childIndex: Int,
childCount: Int
) {
buffer.log(TAG, DEBUG, {
str1 = childEntry.logKey
int1 = childIndex
int2 = childCount
str2 = childEntry.parent?.summary?.logKey ?: "(null)"
}, {
"DISMISS Already Parent-Dismissed $str1 ($int1/$int2) with summary $str2"
})
}
fun logLocallyDismissNonExistentNotif(entry: NotificationEntry, index: Int, count: Int) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"LOCALLY DISMISS Non Existent $str1 ($int1/$int2)"
})
}
fun logLocallyDismissMismatchedEntry(
entry: NotificationEntry,
index: Int,
count: Int,
storedEntry: NotificationEntry
) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
str2 = Integer.toHexString(entry.hashCode())
str3 = Integer.toHexString(storedEntry.hashCode())
}, {
"LOCALLY DISMISS Mismatch $str1 ($int1/$int2): dismissing @$str2 but stored @$str3"
})
}
fun logLocallyDismissAlreadyDismissedNotif(
entry: NotificationEntry,
index: Int,
count: Int
) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"LOCALLY DISMISS Already Dismissed $str1 ($int1/$int2)"
})
}
fun logLocallyDismissAlreadyParentDismissedNotif(
entry: NotificationEntry,
index: Int,
count: Int
) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
int1 = index
int2 = count
}, {
"LOCALLY DISMISS Already Dismissed $str1 ($int1/$int2)"
})
}
fun logLocallyDismissAlreadyDismissedChild(
childEntry: NotificationEntry,
parentEntry: NotificationEntry,
parentIndex: Int,
parentCount: Int
) {
buffer.log(TAG, INFO, {
str1 = childEntry.logKey
str2 = parentEntry.logKey
int1 = parentIndex
int2 = parentCount
}, {
"LOCALLY DISMISS Already Dismissed Child $str1 of parent $str2 ($int1/$int2)"
})
}
fun logLocallyDismissAlreadyParentDismissedChild(
childEntry: NotificationEntry,
parentEntry: NotificationEntry,
parentIndex: Int,
parentCount: Int
) {
buffer.log(TAG, INFO, {
str1 = childEntry.logKey
str2 = parentEntry.logKey
int1 = parentIndex
int2 = parentCount
}, {
"LOCALLY DISMISS Already Parent-Dismissed Child $str1 of parent $str2 ($int1/$int2)"
})
}
fun logCancelLocalDismissalNotDismissedNotif(entry: NotificationEntry) {
buffer.log(TAG, INFO, {
str1 = entry.logKey
}, {
"CANCEL LOCAL DISMISS Not Dismissed $str1"
})
}
}
private const val TAG = "NotifCollection"