Dynamic logs for motions in UnwantedInteractionBlocker
Currently, we have no way to debug the palm rejection operation in real
time. On some devices, we are observing touches rejected unreasonably.
For improved debugging, provide a way to turn on the logs at runtime.
Sample logs:
07-29 20:50:51.938 21364 21461 D UnwantedInteractionBlocker: notifyMotion: NotifyMotionArgs(id=437279320, eventTime=681206765436000, deviceId=4, source=TOUCHSCREEN, action=MOVE, pointerCount=2 pointers={0: id=0 x=1998.0 y=732.0 pressure=1.0 major=78.0 minor=78.0 orientation=1.6}, {1: id=1 x=1651.0 y=705.0 pressure=0.5 major=14.0 minor=14.0 orientation=1.6}, flags=0x00000000)
07-29 20:50:51.939 21364 21461 D UnwantedInteractionBlocker: Filter: touches = 0 : InProgressTouchEvdev(x=1998, y=732, tracking_id=0, slot=0, pressure=0.996094, major=78, minor=78, tool_type=0, altered=1, was_touching=1, touching=1)
07-29 20:50:51.939 21364 21461 D UnwantedInteractionBlocker: 1 : InProgressTouchEvdev(x=1651, y=705, tracking_id=1, slot=1, pressure=0.546875, major=14, minor=14, tool_type=0, altered=1, was_touching=1, touching=1)
07-29 20:50:51.939 21364 21461 D UnwantedInteractionBlocker: Response: slotsToHold = 00000000000000000000, slotsToSuppress = 00000000000000000011
07-29 20:50:51.939 21364 21461 I UnwantedInteractionBlocker: Palm detected, removing pointer ids {0, 1} after 656ms from NotifyMotionArgs(id=437279320, eventTime=681206765436000, deviceId=4, source=TOUCHSCREEN, action=MOVE, pointerCount=2 pointers={0: id=0 x=1998.0 y=732.0 pressure=1.0 major=78.0 minor=78.0 orientation=1.6}, {1: id=1 x=1651.0 y=705.0 pressure=0.5 major=14.0 minor=14.0 orientation=1.6}, flags=0x00000000)
07-29 20:50:51.939 21364 21461 D UnwantedInteractionBlocker: enqueueOutboundMotionLocked: NotifyMotionArgs(id=437279320, eventTime=681206765436000, deviceId=4, source=TOUCHSCREEN, action=CANCEL, pointerCount=1 pointers={0: id=1 x=1651.0 y=705.0 pressure=0.5 major=14.0 minor=14.0 orientation=1.6}, flags=0x00000020)
07-29 20:50:51.947 21364 21461 D UnwantedInteractionBlocker: notifyMotion: NotifyMotionArgs(id=1057496278, eventTime=681206774728000, deviceId=4, source=TOUCHSCREEN, action=MOVE, pointerCount=2 pointers={0: id=0 x=1996.0 y=732.0 pressure=1.0 major=78.0 minor=78.0 orientation=1.6}, {1: id=1 x=1651.0 y=705.0 pressure=0.5 major=14.0 minor=14.0 orientation=1.6}, flags=0x00000000)
07-29 20:50:51.947 21364 21461 D UnwantedInteractionBlocker: Filter: touches = 0 : InProgressTouchEvdev(x=1996, y=732, tracking_id=0, slot=0, pressure=0.996094, major=78, minor=78, tool_type=0, altered=1, was_touching=1, touching=1)
07-29 20:50:51.947 21364 21461 D UnwantedInteractionBlocker: 1 : InProgressTouchEvdev(x=1651, y=705, tracking_id=1, slot=1, pressure=0.542969, major=14, minor=14, tool_type=0, altered=1, was_touching=1, touching=1)
07-29 20:50:51.948 21364 21461 D UnwantedInteractionBlocker: Response: slotsToHold = 00000000000000000000, slotsToSuppress = 00000000000000000011
Bug: 239463037
Bug: 198472780
Test: looked at the logs with palm rejection enabled
Change-Id: I10e54bd0c4ca26fd6197b3ff0069f9799ea91ccf
diff --git a/services/inputflinger/UnwantedInteractionBlocker.cpp b/services/inputflinger/UnwantedInteractionBlocker.cpp
index 2193b7c..4744db0 100644
--- a/services/inputflinger/UnwantedInteractionBlocker.cpp
+++ b/services/inputflinger/UnwantedInteractionBlocker.cpp
@@ -39,6 +39,30 @@
namespace android {
+/**
+ * Log detailed debug messages about each inbound motion event notification to the blocker.
+ * Enable this via "adb shell setprop log.tag.UnwantedInteractionBlockerInboundMotion DEBUG"
+ * (requires restart)
+ */
+const bool DEBUG_INBOUND_MOTION =
+ __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "InboundMotion", ANDROID_LOG_INFO);
+
+/**
+ * Log detailed debug messages about each outbound motion event processed by the blocker.
+ * Enable this via "adb shell setprop log.tag.UnwantedInteractionBlockerOutboundMotion DEBUG"
+ * (requires restart)
+ */
+const bool DEBUG_OUTBOUND_MOTION =
+ __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "OutboundMotion", ANDROID_LOG_INFO);
+
+/**
+ * Log the data sent to the model and received back from the model.
+ * Enable this via "adb shell setprop log.tag.UnwantedInteractionBlockerModel DEBUG"
+ * (requires restart)
+ */
+const bool DEBUG_MODEL =
+ __android_log_is_loggable(ANDROID_LOG_DEBUG, LOG_TAG "Model", ANDROID_LOG_INFO);
+
// Category (=namespace) name for the input settings that are applied at boot time
static const char* INPUT_NATIVE_BOOT = "input_native_boot";
/**
@@ -309,6 +333,7 @@
}
void UnwantedInteractionBlocker::notifyMotion(const NotifyMotionArgs* args) {
+ ALOGD_IF(DEBUG_INBOUND_MOTION, "%s: %s", __func__, args->dump().c_str());
{ // acquire lock
std::scoped_lock lock(mLock);
const std::vector<NotifyMotionArgs> processedArgs =
@@ -322,17 +347,22 @@
mQueuedListener.flush();
}
+void UnwantedInteractionBlocker::enqueueOutboundMotionLocked(const NotifyMotionArgs& args) {
+ ALOGD_IF(DEBUG_OUTBOUND_MOTION, "%s: %s", __func__, args.dump().c_str());
+ mQueuedListener.notifyMotion(&args);
+}
+
void UnwantedInteractionBlocker::notifyMotionLocked(const NotifyMotionArgs* args) {
auto it = mPalmRejectors.find(args->deviceId);
const bool sendToPalmRejector = it != mPalmRejectors.end() && isFromTouchscreen(args->source);
if (!sendToPalmRejector) {
- mQueuedListener.notifyMotion(args);
+ enqueueOutboundMotionLocked(*args);
return;
}
std::vector<NotifyMotionArgs> processedArgs = it->second.processMotion(*args);
for (const NotifyMotionArgs& loopArgs : processedArgs) {
- mQueuedListener.notifyMotion(&loopArgs);
+ enqueueOutboundMotionLocked(loopArgs);
}
}
@@ -616,8 +646,18 @@
getTouches(args, mDeviceInfo, oldSlotState, mSlotState);
::base::TimeTicks chromeTimestamp = toChromeTimestamp(args.eventTime);
+ if (DEBUG_MODEL) {
+ std::stringstream touchesStream;
+ for (const ::ui::InProgressTouchEvdev& touch : touches) {
+ touchesStream << touch.tracking_id << " : " << touch << "\n";
+ }
+ ALOGD("Filter: touches = %s", touchesStream.str().c_str());
+ }
mPalmDetectionFilter->Filter(touches, chromeTimestamp, &slotsToHold, &slotsToSuppress);
+ ALOGD_IF(DEBUG_MODEL, "Response: slotsToHold = %s, slotsToSuppress = %s",
+ slotsToHold.to_string().c_str(), slotsToSuppress.to_string().c_str());
+
// Now that we know which slots should be suppressed, let's convert those to pointer id's.
std::set<int32_t> oldSuppressedIds;
std::swap(oldSuppressedIds, mSuppressedPointerIds);