Merge "Beef up logging in and near tryRemoveNotification" into udc-qpr-dev

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

@@ -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 {
+                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()) {
+            // Mark any children as dismissed as system server will auto-dismiss them as well
-                        if (shouldAutoDismissChildren(otherEntry, entry.getSbn().getGroupKey())) {
+            if (entry.getSbn().getNotification().isGroupSummary()) {
-                            otherEntry.setDismissState(PARENT_DISMISSED);
+                for (NotificationEntry otherEntry : mNotificationSet.values()) {
-                            mLogger.logChildDismissed(otherEntry);
+                    if (shouldAutoDismissChildren(otherEntry, entry.getSbn().getGroupKey())) {
-                            if (otherEntry.isCanceled()) {
+                        if (otherEntry.getDismissState() == DISMISSED) {
-                                canceledEntries.add(otherEntry);
+                            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) {
+        if (entry.getDismissState() == NOT_DISMISSED) {
-            entry.setDismissState(NOT_DISMISSED);
+            mLogger.logCancelLocalDismissalNotDismissedNotif(entry);
-            if (entry.getSbn().getNotification().isGroupSummary()) {
+            return;
-                for (NotificationEntry otherEntry : mNotificationSet.values()) {
+        }
-                    if (otherEntry.getSbn().getGroupKey().equals(entry.getSbn().getGroupKey())
+        entry.setDismissState(NOT_DISMISSED);
-                            && otherEntry.getDismissState() == PARENT_DISMISSED) {
+        if (entry.getSbn().getNotification().isGroupSummary()) {
-                        otherEntry.setDismissState(NOT_DISMISSED);
+            for (NotificationEntry otherEntry : mNotificationSet.values()) {
-                    }
+                if (otherEntry.getSbn().getGroupKey().equals(entry.getSbn().getGroupKey())
+                        && otherEntry.getDismissState() == PARENT_DISMISSED) {
+                    otherEntry.setDismissState(NOT_DISMISSED);
                 }
             }
         }

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

@@ -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"