Add some logs to help debug a NotificationAssistant issue
Found a droidfood device has smart suggestions missing.
The issue seems like NMS is not calling into NAS's
onNotificationEnqueued for some reasons. Adding more log around it,
the logs can be enabled by running
setprop log.tag.notification_assistant VERBOSE.
Also, use Slog rather than log, so that it is written to system log
ring buffer.
Test: check logcat
Change-Id: I157c94cdfbccbf6b274c246302999a5820781e28
diff --git a/core/java/android/service/notification/NotificationAssistantService.java b/core/java/android/service/notification/NotificationAssistantService.java
index 87bdfe0..780b576 100644
--- a/core/java/android/service/notification/NotificationAssistantService.java
+++ b/core/java/android/service/notification/NotificationAssistantService.java
@@ -373,7 +373,10 @@
args.recycle();
Adjustment adjustment = onNotificationEnqueued(sbn, channel);
if (adjustment != null) {
- if (!isBound()) return;
+ if (!isBound()) {
+ Log.w(TAG, "MSG_ON_NOTIFICATION_ENQUEUED: service not bound, skip.");
+ return;
+ }
try {
getNotificationInterface().applyEnqueuedAdjustmentFromAssistant(
mWrapper, adjustment);
diff --git a/services/core/java/com/android/server/notification/ManagedServices.java b/services/core/java/com/android/server/notification/ManagedServices.java
index 7a87a57..0c0c23a 100644
--- a/services/core/java/com/android/server/notification/ManagedServices.java
+++ b/services/core/java/com/android/server/notification/ManagedServices.java
@@ -1112,7 +1112,7 @@
binder.linkToDeath(info, 0);
added = mServices.add(info);
} catch (RemoteException e) {
- // already dead
+ Slog.e(TAG, "Failed to linkToDeath, already dead", e);
}
}
if (added) {
@@ -1144,6 +1144,11 @@
}
}
}
+
+ @Override
+ public void onNullBinding(ComponentName name) {
+ Slog.v(TAG, "onNullBinding() called with: name = [" + name + "]");
+ }
};
if (!mContext.bindServiceAsUser(intent,
serviceConnection,
diff --git a/services/core/java/com/android/server/notification/NotificationManagerService.java b/services/core/java/com/android/server/notification/NotificationManagerService.java
index d25360a..88e697c 100644
--- a/services/core/java/com/android/server/notification/NotificationManagerService.java
+++ b/services/core/java/com/android/server/notification/NotificationManagerService.java
@@ -251,7 +251,6 @@
import java.util.Set;
import java.util.concurrent.TimeUnit;
import java.util.function.BiConsumer;
-import java.util.function.Predicate;
/** {@hide} */
public class NotificationManagerService extends SystemService {
@@ -759,7 +758,7 @@
synchronized (mNotificationLock) {
NotificationRecord r = mNotificationsByKey.get(key);
if (r == null) {
- Log.w(TAG, "No notification with key: " + key);
+ Slog.w(TAG, "No notification with key: " + key);
return;
}
final long now = System.currentTimeMillis();
@@ -789,7 +788,7 @@
synchronized (mNotificationLock) {
NotificationRecord r = mNotificationsByKey.get(key);
if (r == null) {
- Log.w(TAG, "No notification with key: " + key);
+ Slog.w(TAG, "No notification with key: " + key);
return;
}
final long now = System.currentTimeMillis();
@@ -3133,7 +3132,7 @@
synchronized (mNotificationLock) {
final ManagedServiceInfo info = mListeners.checkServiceTokenLocked(token);
if (info.supportsProfiles()) {
- Log.e(TAG, "Ignoring deprecated cancelNotification(pkg, tag, id) "
+ Slog.e(TAG, "Ignoring deprecated cancelNotification(pkg, tag, id) "
+ "from " + info.component
+ " use cancelNotification(key) instead.");
} else {
@@ -4553,7 +4552,7 @@
+ ", incomingUserId=" + incomingUserId
+ ", notificationUid=" + notificationUid
+ ", notification=" + notification;
- Log.e(TAG, noChannelStr);
+ Slog.e(TAG, noChannelStr);
boolean appNotificationsOff = mPreferencesHelper.getImportance(pkg, notificationUid)
== NotificationManager.IMPORTANCE_NONE;
@@ -4650,7 +4649,7 @@
android.Manifest.permission.USE_FULL_SCREEN_INTENT, pkg);
if (fullscreenIntentPermission != PERMISSION_GRANTED) {
notification.fullScreenIntent = null;
- Log.w(TAG, "Package " + pkg +
+ Slog.w(TAG, "Package " + pkg +
": Use of fullScreenIntent requires the USE_FULL_SCREEN_INTENT permission");
}
}
@@ -5179,7 +5178,7 @@
// Ignore summary updates because we don't display most of the information.
if (r.sbn.isGroup() && r.sbn.getNotification().isGroupSummary()) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is not interruptive: summary");
}
return false;
@@ -5187,7 +5186,7 @@
if (old == null) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: new notification");
}
return true;
@@ -5195,7 +5194,7 @@
if (r == null) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is not interruptive: null");
}
return false;
@@ -5206,7 +5205,7 @@
if (oldN.extras == null || newN.extras == null) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is not interruptive: no extras");
}
return false;
@@ -5216,7 +5215,7 @@
// consider them one 'session'. Count them for everything else.
if ((r.sbn.getNotification().flags & FLAG_FOREGROUND_SERVICE) != 0) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is not interruptive: foreground service");
}
return false;
@@ -5226,11 +5225,11 @@
final String newTitle = String.valueOf(newN.extras.get(Notification.EXTRA_TITLE));
if (!Objects.equals(oldTitle, newTitle)) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: changed title");
- Log.v(TAG, "INTERRUPTIVENESS: " + String.format(" old title: %s (%s@0x%08x)",
+ Slog.v(TAG, "INTERRUPTIVENESS: " + String.format(" old title: %s (%s@0x%08x)",
oldTitle, oldTitle.getClass(), oldTitle.hashCode()));
- Log.v(TAG, "INTERRUPTIVENESS: " + String.format(" new title: %s (%s@0x%08x)",
+ Slog.v(TAG, "INTERRUPTIVENESS: " + String.format(" new title: %s (%s@0x%08x)",
newTitle, newTitle.getClass(), newTitle.hashCode()));
}
return true;
@@ -5240,18 +5239,18 @@
final String newText = String.valueOf(newN.extras.get(Notification.EXTRA_TEXT));
if (!Objects.equals(oldText, newText)) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: changed text");
- Log.v(TAG, "INTERRUPTIVENESS: " + String.format(" old text: %s (%s@0x%08x)",
+ Slog.v(TAG, "INTERRUPTIVENESS: " + String.format(" old text: %s (%s@0x%08x)",
oldText, oldText.getClass(), oldText.hashCode()));
- Log.v(TAG, "INTERRUPTIVENESS: " + String.format(" new text: %s (%s@0x%08x)",
+ Slog.v(TAG, "INTERRUPTIVENESS: " + String.format(" new text: %s (%s@0x%08x)",
newText, newText.getClass(), newText.hashCode()));
}
return true;
}
if (oldN.hasCompletedProgress() != newN.hasCompletedProgress()) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: completed progress");
}
return true;
@@ -5259,7 +5258,7 @@
// Actions
if (Notification.areActionsVisiblyDifferent(oldN, newN)) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: changed actions");
}
return true;
@@ -5272,7 +5271,7 @@
// Style based comparisons
if (Notification.areStyledNotificationsVisiblyDifferent(oldB, newB)) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: styles differ");
}
return true;
@@ -5281,7 +5280,7 @@
// Remote views
if (Notification.areRemoteViewsChanged(oldB, newB)) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ r.getKey() + " is interruptive: remoteviews differ");
}
return true;
@@ -5510,12 +5509,12 @@
// Ignore summary updates because we don't display most of the information.
if (record.sbn.isGroup() && record.sbn.getNotification().isGroupSummary()) {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ record.getKey() + " is not interruptive: summary");
}
} else {
if (DEBUG_INTERRUPTIVENESS) {
- Log.v(TAG, "INTERRUPTIVENESS: "
+ Slog.v(TAG, "INTERRUPTIVENESS: "
+ record.getKey() + " is interruptive: alerted");
}
record.setInterruptive(true);
@@ -6603,7 +6602,7 @@
String pkg = r.sbn.getPackageName();
if (pkg == null) {
- if (DBG) Log.e(TAG, "No package for group summary: " + r.getKey());
+ if (DBG) Slog.e(TAG, "No package for group summary: " + r.getKey());
return;
}
@@ -6862,7 +6861,7 @@
return;
}
} catch (RemoteException re) {
- if (DBG) Log.e(TAG, "Unable to confirm if it's safe to skip category "
+ if (DBG) Slog.e(TAG, "Unable to confirm if it's safe to skip category "
+ "restrictions check thus the check will be done anyway");
}
if (Notification.CATEGORY_CAR_EMERGENCY.equals(notification.category)
@@ -7104,7 +7103,7 @@
canUseManagedServices = false;
}
} catch (RemoteException e) {
- Log.e(TAG, "can't talk to pm", e);
+ Slog.e(TAG, "can't talk to pm", e);
}
}
@@ -7247,21 +7246,29 @@
try {
assistant.onNotificationsSeen(keys);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (seen): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (seen): " + assistant, ex);
}
}
@GuardedBy("mNotificationLock")
private void onNotificationEnqueuedLocked(final NotificationRecord r) {
+ final boolean debug = isVerboseLogEnabled();
+ if (debug) {
+ Slog.v(TAG, "onNotificationEnqueuedLocked() called with: r = [" + r + "]");
+ }
final StatusBarNotification sbn = r.sbn;
notifyAssistantLocked(
sbn,
true /* sameUserOnly */,
(assistant, sbnHolder) -> {
try {
+ if (debug) {
+ Slog.v(TAG,
+ "calling onNotificationEnqueuedWithChannel " + sbnHolder);
+ }
assistant.onNotificationEnqueuedWithChannel(sbnHolder, r.getChannel());
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (enqueued): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (enqueued): " + assistant, ex);
}
});
}
@@ -7279,7 +7286,7 @@
try {
assistant.onNotificationExpansionChanged(key, isUserAction, isExpanded);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (expanded): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (expanded): " + assistant, ex);
}
});
}
@@ -7295,7 +7302,7 @@
try {
assistant.onNotificationDirectReply(key);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (expanded): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (expanded): " + assistant, ex);
}
});
}
@@ -7316,7 +7323,7 @@
? NotificationAssistantService.SOURCE_FROM_ASSISTANT
: NotificationAssistantService.SOURCE_FROM_APP);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
}
});
}
@@ -7338,7 +7345,7 @@
? NotificationAssistantService.SOURCE_FROM_ASSISTANT
: NotificationAssistantService.SOURCE_FROM_APP);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
}
});
}
@@ -7358,7 +7365,7 @@
assistant.onNotificationSnoozedUntilContext(
sbnHolder, snoozeCriterionId);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
+ Slog.e(TAG, "unable to notify assistant (snoozed): " + assistant, ex);
}
});
}
@@ -7380,9 +7387,19 @@
TrimCache trimCache = new TrimCache(sbn);
// There should be only one, but it's a list, so while we enforce
// singularity elsewhere, we keep it general here, to avoid surprises.
+
+ final boolean debug = isVerboseLogEnabled();
+ if (debug) {
+ Slog.v(TAG,
+ "notifyAssistantLocked() called with: sbn = [" + sbn + "], sameUserOnly = ["
+ + sameUserOnly + "], callback = [" + callback + "]");
+ }
for (final ManagedServiceInfo info : NotificationAssistants.this.getServices()) {
boolean sbnVisible = isVisibleToListener(sbn, info)
&& (!sameUserOnly || info.isSameUser(sbn.getUserId()));
+ if (debug) {
+ Slog.v(TAG, "notifyAssistantLocked info=" + info + " snbVisible=" + sbnVisible);
+ }
if (!sbnVisible) {
continue;
}
@@ -7436,6 +7453,10 @@
}
}
}
+
+ private boolean isVerboseLogEnabled() {
+ return Log.isLoggable("notification_assistant", Log.VERBOSE);
+ }
}
public class NotificationListeners extends ManagedServices {
@@ -7530,7 +7551,7 @@
try {
listener.onStatusBarIconsBehaviorChanged(hideSilentStatusIcons);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener "
+ Slog.e(TAG, "unable to notify listener "
+ "(hideSilentStatusIcons): " + listener, ex);
}
});
@@ -7824,7 +7845,7 @@
try {
listener.onNotificationPosted(sbnHolder, rankingUpdate);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (posted): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (posted): " + listener, ex);
}
}
@@ -7838,7 +7859,7 @@
try {
listener.onNotificationRemoved(sbnHolder, rankingUpdate, stats, reason);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (removed): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (removed): " + listener, ex);
}
}
@@ -7848,7 +7869,7 @@
try {
listener.onNotificationRankingUpdate(rankingUpdate);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (ranking update): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (ranking update): " + listener, ex);
}
}
@@ -7857,7 +7878,7 @@
try {
listener.onListenerHintsChanged(hints);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (listener hints): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (listener hints): " + listener, ex);
}
}
@@ -7867,7 +7888,7 @@
try {
listener.onInterruptionFilterChanged(interruptionFilter);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (interruption filter): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (interruption filter): " + listener, ex);
}
}
@@ -7878,7 +7899,7 @@
try {
listener.onNotificationChannelModification(pkg, user, channel, modificationType);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (channel changed): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (channel changed): " + listener, ex);
}
}
@@ -7889,7 +7910,7 @@
try {
listener.onNotificationChannelGroupModification(pkg, user, group, modificationType);
} catch (RemoteException ex) {
- Log.e(TAG, "unable to notify listener (channel group changed): " + listener, ex);
+ Slog.e(TAG, "unable to notify listener (channel group changed): " + listener, ex);
}
}