From d5fe5185d8b4d1ae017e2a27f8d14c459b880619 Mon Sep 17 00:00:00 2001 From: Siarhei Vishniakou Date: Wed, 20 Jul 2022 23:28:40 +0000 Subject: 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 --- .../inputflinger/UnwantedInteractionBlocker.cpp | 44 +++++++++++++++++++++- 1 file changed, 42 insertions(+), 2 deletions(-) (limited to 'services/inputflinger/UnwantedInteractionBlocker.cpp') diff --git a/services/inputflinger/UnwantedInteractionBlocker.cpp b/services/inputflinger/UnwantedInteractionBlocker.cpp index 2193b7c4f0..4744db0a17 100644 --- a/services/inputflinger/UnwantedInteractionBlocker.cpp +++ b/services/inputflinger/UnwantedInteractionBlocker.cpp @@ -39,6 +39,30 @@ using PalmFilterImplementation = ::ui::NeuralStylusPalmDetectionFilter; 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::notifyKey(const NotifyKeyArgs* args) { } 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 processedArgs = @@ -322,17 +347,22 @@ void UnwantedInteractionBlocker::notifyMotion(const NotifyMotionArgs* args) { 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 processedArgs = it->second.processMotion(*args); for (const NotifyMotionArgs& loopArgs : processedArgs) { - mQueuedListener.notifyMotion(&loopArgs); + enqueueOutboundMotionLocked(loopArgs); } } @@ -616,8 +646,18 @@ std::vector PalmRejector::processMotion(const NotifyMotionArgs 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 oldSuppressedIds; std::swap(oldSuppressedIds, mSuppressedPointerIds); -- cgit v1.2.3-59-g8ed1b