Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit d5fe5185 authored by Siarhei Vishniakou's avatar Siarhei Vishniakou
Browse files

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
parent 229a8804
Loading
Loading
Loading
Loading
+2 −0
Original line number Diff line number Diff line
@@ -297,6 +297,8 @@ enum class MotionClassification : uint8_t {
 */
const char* motionClassificationToString(MotionClassification classification);

const char* motionToolTypeToString(int32_t toolType);

/**
 * Portion of FrameMetrics timeline of interest to input code.
 */
+19 −0
Original line number Diff line number Diff line
@@ -90,6 +90,25 @@ const char* motionClassificationToString(MotionClassification classification) {
    }
}

const char* motionToolTypeToString(int32_t toolType) {
    switch (toolType) {
        case AMOTION_EVENT_TOOL_TYPE_UNKNOWN:
            return "UNKNOWN";
        case AMOTION_EVENT_TOOL_TYPE_FINGER:
            return "FINGER";
        case AMOTION_EVENT_TOOL_TYPE_STYLUS:
            return "STYLUS";
        case AMOTION_EVENT_TOOL_TYPE_MOUSE:
            return "MOUSE";
        case AMOTION_EVENT_TOOL_TYPE_ERASER:
            return "ERASER";
        case AMOTION_EVENT_TOOL_TYPE_PALM:
            return "PALM";
        default:
            return "INVALID";
    }
}

// --- IdGenerator ---
IdGenerator::IdGenerator(Source source) : mSource(source) {}

+12 −1
Original line number Diff line number Diff line
@@ -196,9 +196,20 @@ std::string NotifyMotionArgs::dump() const {
        }
        coords += StringPrintf("{%" PRIu32 ": ", i);
        coords +=
                StringPrintf("id=%" PRIu32 " x=%.1f y=%.1f, pressure=%.1f", pointerProperties[i].id,
                StringPrintf("id=%" PRIu32 " x=%.1f y=%.1f pressure=%.1f", pointerProperties[i].id,
                             pointerCoords[i].getX(), pointerCoords[i].getY(),
                             pointerCoords[i].getAxisValue(AMOTION_EVENT_AXIS_PRESSURE));
        const int32_t toolType = pointerProperties[i].toolType;
        if (toolType != AMOTION_EVENT_TOOL_TYPE_FINGER) {
            coords += StringPrintf(" toolType=%s", motionToolTypeToString(toolType));
        }
        const float major = pointerCoords[i].getAxisValue(AMOTION_EVENT_AXIS_TOUCH_MAJOR);
        const float minor = pointerCoords[i].getAxisValue(AMOTION_EVENT_AXIS_TOUCH_MINOR);
        const float orientation = pointerCoords[i].getAxisValue(AMOTION_EVENT_AXIS_ORIENTATION);
        if (major != 0 || minor != 0) {
            coords += StringPrintf(" major=%.1f minor=%.1f orientation=%.1f", major, minor,
                                   orientation);
        }
        coords += "}";
    }
    return StringPrintf("NotifyMotionArgs(id=%" PRId32 ", eventTime=%" PRId64 ", deviceId=%" PRId32
+42 −2
Original line number Diff line number Diff line
@@ -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<NotifyMotionArgs> 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<NotifyMotionArgs> processedArgs = it->second.processMotion(*args);
    for (const NotifyMotionArgs& loopArgs : processedArgs) {
        mQueuedListener.notifyMotion(&loopArgs);
        enqueueOutboundMotionLocked(loopArgs);
    }
}

@@ -616,8 +646,18 @@ std::vector<NotifyMotionArgs> 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<int32_t> oldSuppressedIds;
    std::swap(oldSuppressedIds, mSuppressedPointerIds);
+3 −0
Original line number Diff line number Diff line
@@ -101,6 +101,9 @@ private:
    std::map<int32_t /*deviceId*/, PalmRejector> mPalmRejectors GUARDED_BY(mLock);
    // TODO(b/210159205): delete this when simultaneous stylus and touch is supported
    void notifyMotionLocked(const NotifyMotionArgs* args) REQUIRES(mLock);

    // Call this function for outbound events so that they can be logged when logging is enabled.
    void enqueueOutboundMotionLocked(const NotifyMotionArgs& args) REQUIRES(mLock);
};

class SlotState {