FalsingLog: Fix false positive Log.wtfs

Fixes a frequent case where we do not get notified immediately of the
screen turning on and log a WTF as a result when a touch makes it
through to the lockscreen.

Change-Id: I5437aa0283d78624ffb3a43404e7248b7e91372c
Fixes: 32575746

packages/SystemUI/src/com/android/systemui/classifier/FalsingLog.java

@@ -84,6 +84,11 @@ public class FalsingLog {
         log("I", tag, s);
     }
 
+    public static void wLogcat(String tag, String s) {
+        Log.w(TAG, tag + "\t" + s);
+        log("W", tag, s);
+    }
+
     public static void w(String tag, String s) {
         if (LOGCAT) {
             Log.w(TAG, tag + "\t" + s);
@@ -133,7 +138,7 @@ public class FalsingLog {
         pw.println();
     }
 
-    public static synchronized void wtf(String tag, String s) {
+    public static synchronized void wtf(String tag, String s, Throwable here) {
         if (!ENABLED) {
             return;
         }
@@ -161,6 +166,6 @@ public class FalsingLog {
             Log.e(TAG, "Unable to write log, build must be debuggable.");
         }
 
-        Log.wtf(TAG, tag + " " + s + "; " + fileMessage);
+        Log.wtf(TAG, tag + " " + s + "; " + fileMessage, here);
     }
 }

packages/SystemUI/src/com/android/systemui/classifier/FalsingManager.java

@@ -71,6 +71,7 @@ public class FalsingManager implements SensorEventListener {
     private boolean mSessionActive = false;
     private int mState = StatusBarState.SHADE;
     private boolean mScreenOn;
+    private Runnable mPendingWtf;
 
     protected final ContentObserver mSettingsObserver = new ContentObserver(mHandler) {
         @Override
@@ -136,6 +137,7 @@ public class FalsingManager implements SensorEventListener {
     private void onSessionStart() {
         if (FalsingLog.ENABLED) {
             FalsingLog.i("onSessionStart", "classifierEnabled=" + isClassiferEnabled());
+            clearPendingWtf();
         }
         mBouncerOn = false;
         mSessionActive = true;
@@ -172,13 +174,35 @@ public class FalsingManager implements SensorEventListener {
         if (FalsingLog.ENABLED) {
             // We're getting some false wtfs from touches that happen after the device went
             // to sleep. Only report missing sessions that happen when the device is interactive.
-            if (!mSessionActive && mContext.getSystemService(PowerManager.class).isInteractive()) {
+            if (!mSessionActive && mContext.getSystemService(PowerManager.class).isInteractive()
-                FalsingLog.wtf("isFalseTouch", new StringBuilder()
+                    && mPendingWtf == null) {
+                int enabled = isEnabled() ? 1 : 0;
+                int screenOn = mScreenOn ? 1 : 0;
+                String state = StatusBarState.toShortString(mState);
+                Throwable here = new Throwable("here");
+                FalsingLog.wLogcat("isFalseTouch", new StringBuilder()
                         .append("Session is not active, yet there's a query for a false touch.")
-                        .append(" enabled=").append(isEnabled() ? 1 : 0)
+                        .append(" enabled=").append(enabled)
-                        .append(" mScreenOn=").append(mScreenOn ? 1 : 0)
+                        .append(" mScreenOn=").append(screenOn)
-                        .append(" mState=").append(StatusBarState.toShortString(mState))
+                        .append(" mState=").append(state)
+                        .append(". Escalating to WTF if screen does not turn on soon.")
                         .toString());
+
+                // Unfortunately we're also getting false positives for touches that happen right
+                // after the screen turns on, but before that notification has made it to us.
+                // Unfortunately there's no good way to catch that, except to wait and see if we get
+                // the screen on notification soon.
+                mPendingWtf = () -> FalsingLog.wtf("isFalseTouch", new StringBuilder()
+                        .append("Session did not become active after query for a false touch.")
+                        .append(" enabled=").append(enabled)
+                        .append('/').append(isEnabled() ? 1 : 0)
+                        .append(" mScreenOn=").append(screenOn)
+                        .append('/').append(mScreenOn ? 1 : 0)
+                        .append(" mState=").append(state)
+                        .append('/').append(StatusBarState.toShortString(mState))
+                        .append(". Look for warnings ~1000ms earlier to see root cause.")
+                        .toString(), here);
+                mHandler.postDelayed(mPendingWtf, 1000);
             }
         }
         if (mAccessibilityManager.isTouchExplorationEnabled()) {
@@ -189,6 +213,13 @@ public class FalsingManager implements SensorEventListener {
         return mHumanInteractionClassifier.isFalseTouch();
     }
 
+    private void clearPendingWtf() {
+        if (mPendingWtf != null) {
+            mHandler.removeCallbacks(mPendingWtf);
+            mPendingWtf = null;
+        }
+    }
+
     @Override
     public synchronized void onSensorChanged(SensorEvent event) {
         mDataCollector.onSensorChanged(event);
@@ -224,6 +255,7 @@ public class FalsingManager implements SensorEventListener {
             FalsingLog.i("onScreenTurningOn", new StringBuilder()
                     .append("from=").append(mScreenOn ? 1 : 0)
                     .toString());
+            clearPendingWtf();
         }
         mScreenOn = true;
         if (sessionEntrypoint()) {