Moar Content capture improvements:

- Drop Content Capture events when the session is disabled, otherwise sessions
  on this state might never finish.
- Fixed PII leak.
- Created helper class for common stuff.
- Improved logging.

Test: manually chenged VERBOSE to true, restarted system_server, and watched logcat - without
      this change, launcher's session would never die because it kept re-scheduling flush
      requests.
Test: atest CtsContentCaptureServiceTestCases
Bug: 122959591

Change-Id: Idcc1bbb12763d1cf98149164c68c2712834d5112
diff --git a/core/java/android/view/contentcapture/ContentCaptureEvent.java b/core/java/android/view/contentcapture/ContentCaptureEvent.java
index 43963c3..a6d4472 100644
--- a/core/java/android/view/contentcapture/ContentCaptureEvent.java
+++ b/core/java/android/view/contentcapture/ContentCaptureEvent.java
@@ -15,6 +15,8 @@
  */
 package android.view.contentcapture;
 
+import static android.view.contentcapture.ContentCaptureHelper.getSanitizedString;
+
 import android.annotation.IntDef;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
@@ -267,8 +269,7 @@
             pw.print(", parentSessionId="); pw.print(mParentSessionId);
         }
         if (mText != null) {
-            // Cannot print content because could have PII
-            pw.print(", text="); pw.print(mText.length()); pw.print("_chars");
+            pw.print(", text="); pw.println(getSanitizedString(mText));
         }
     }
 
@@ -293,6 +294,9 @@
             }
             string.append(", id=").append(mNode.getAutofillId());
         }
+        if (mText != null) {
+            string.append(", text=").append(getSanitizedString(mText));
+        }
         return string.append(']').toString();
     }
 
diff --git a/core/java/android/view/contentcapture/ContentCaptureHelper.java b/core/java/android/view/contentcapture/ContentCaptureHelper.java
new file mode 100644
index 0000000..508880f
--- /dev/null
+++ b/core/java/android/view/contentcapture/ContentCaptureHelper.java
@@ -0,0 +1,40 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package android.view.contentcapture;
+
+import android.annotation.Nullable;
+
+/**
+ * Helpe class for this package.
+ */
+final class ContentCaptureHelper {
+
+    // TODO(b/121044306): define a way to dynamically set them(for example, using settings?)
+    static final boolean VERBOSE = false;
+    static final boolean DEBUG = true; // STOPSHIP if not set to false
+
+    /**
+     * Used to log text that could contain PII.
+     */
+    @Nullable
+    public static String getSanitizedString(@Nullable CharSequence text) {
+        return text == null ? null : text.length() + "_chars";
+    }
+
+    private ContentCaptureHelper() {
+        throw new UnsupportedOperationException("contains only static methods");
+    }
+}
diff --git a/core/java/android/view/contentcapture/ContentCaptureManager.java b/core/java/android/view/contentcapture/ContentCaptureManager.java
index 413f1a5..3474e23 100644
--- a/core/java/android/view/contentcapture/ContentCaptureManager.java
+++ b/core/java/android/view/contentcapture/ContentCaptureManager.java
@@ -15,6 +15,8 @@
  */
 package android.view.contentcapture;
 
+import static android.view.contentcapture.ContentCaptureHelper.VERBOSE;
+
 import static com.android.internal.util.function.pooled.PooledLambda.obtainMessage;
 
 import android.annotation.NonNull;
@@ -57,10 +59,6 @@
      */
     private static final int SYNC_CALLS_TIMEOUT_MS = 5000;
 
-    // TODO(b/121044306): define a way to dynamically set them(for example, using settings?)
-    static final boolean VERBOSE = false;
-    static final boolean DEBUG = true; // STOPSHIP if not set to false
-
     private final Object mLock = new Object();
 
     @GuardedBy("mLock")
diff --git a/core/java/android/view/contentcapture/ContentCaptureSession.java b/core/java/android/view/contentcapture/ContentCaptureSession.java
index b620ab1..7902cf5 100644
--- a/core/java/android/view/contentcapture/ContentCaptureSession.java
+++ b/core/java/android/view/contentcapture/ContentCaptureSession.java
@@ -15,8 +15,8 @@
  */
 package android.view.contentcapture;
 
-import static android.view.contentcapture.ContentCaptureManager.DEBUG;
-import static android.view.contentcapture.ContentCaptureManager.VERBOSE;
+import static android.view.contentcapture.ContentCaptureHelper.DEBUG;
+import static android.view.contentcapture.ContentCaptureHelper.VERBOSE;
 
 import android.annotation.CallSuper;
 import android.annotation.IntDef;
@@ -246,7 +246,7 @@
     public final void destroy() {
         synchronized (mLock) {
             if (mDestroyed) {
-                Log.e(TAG, "destroy(" + mId + "): already destroyed");
+                if (DEBUG) Log.d(TAG, "destroy(" + mId + "): already destroyed");
                 return;
             }
             mDestroyed = true;
diff --git a/core/java/android/view/contentcapture/MainContentCaptureSession.java b/core/java/android/view/contentcapture/MainContentCaptureSession.java
index 103d7e6..9e99c88 100644
--- a/core/java/android/view/contentcapture/MainContentCaptureSession.java
+++ b/core/java/android/view/contentcapture/MainContentCaptureSession.java
@@ -20,8 +20,9 @@
 import static android.view.contentcapture.ContentCaptureEvent.TYPE_VIEW_APPEARED;
 import static android.view.contentcapture.ContentCaptureEvent.TYPE_VIEW_DISAPPEARED;
 import static android.view.contentcapture.ContentCaptureEvent.TYPE_VIEW_TEXT_CHANGED;
-import static android.view.contentcapture.ContentCaptureManager.DEBUG;
-import static android.view.contentcapture.ContentCaptureManager.VERBOSE;
+import static android.view.contentcapture.ContentCaptureHelper.DEBUG;
+import static android.view.contentcapture.ContentCaptureHelper.VERBOSE;
+import static android.view.contentcapture.ContentCaptureHelper.getSanitizedString;
 
 import static com.android.internal.util.function.pooled.PooledLambda.obtainMessage;
 
@@ -269,6 +270,7 @@
 
     private void handleSendEvent(@NonNull ContentCaptureEvent event, boolean forceFlush) {
         final int eventType = event.getType();
+        if (VERBOSE) Log.v(TAG, "handleSendEvent(" + getDebugState() + "): " + event);
         if (!handleHasStarted() && eventType != ContentCaptureEvent.TYPE_SESSION_STARTED) {
             // TODO(b/120494182): comment when this could happen (dialogs?)
             Log.v(TAG, "handleSendEvent(" + getDebugState() + ", "
@@ -276,12 +278,16 @@
                     + "): session not started yet");
             return;
         }
-        if (VERBOSE) Log.v(TAG, "handleSendEvent(" + getDebugState() + "): " + event);
+        if (mDisabled.get()) {
+            // This happens when the event was queued in the handler before the sesison was ready,
+            // then handleSessionStarted() returned and set it as disabled - we need to drop it,
+            // otherwise it will keep triggering handleScheduleFlush()
+            if (VERBOSE) Log.v(TAG, "handleSendEvent(): ignoring when disabled");
+            return;
+        }
         if (mEvents == null) {
             if (VERBOSE) {
-                Log.v(TAG, "handleSendEvent(" + getDebugState() + ", "
-                        + ContentCaptureEvent.getTypeAsString(eventType)
-                        + "): creating buffer for " + MAX_BUFFER_SIZE + " events");
+                Log.v(TAG, "handleSendEvent(): creating buffer for " + MAX_BUFFER_SIZE + " events");
             }
             mEvents = new ArrayList<>(MAX_BUFFER_SIZE);
         }
@@ -296,8 +302,8 @@
             if (lastEvent.getType() == TYPE_VIEW_TEXT_CHANGED
                     && lastEvent.getId().equals(event.getId())) {
                 if (VERBOSE) {
-                    Log.v(TAG, "Buffering VIEW_TEXT_CHANGED event, updated text = "
-                            + event.getText());
+                    Log.v(TAG, "Buffering VIEW_TEXT_CHANGED event, updated text="
+                            + getSanitizedString(event.getText()));
                 }
                 lastEvent.setText(event.getText());
                 addEvent = false;
@@ -365,8 +371,20 @@
     }
 
     private void handleScheduleFlush(@FlushReason int reason, boolean checkExisting) {
+        if (VERBOSE) {
+            Log.v(TAG, "handleScheduleFlush(" + getDebugState(reason)
+                    + ", checkExisting=" + checkExisting);
+        }
         if (!handleHasStarted()) {
-            Log.v(TAG, "handleScheduleFlush(" + getDebugState() + "): session not started yet");
+            if (VERBOSE) Log.v(TAG, "handleScheduleFlush(): session not started yet");
+            return;
+        }
+
+        if (mDisabled.get()) {
+            // Should not be called on this state, as handleSendEvent checks.
+            // But we rather add one if check and log than re-schedule and keep the session alive...
+            Log.e(TAG, "handleScheduleFlush(" + getDebugState(reason) + "): should not be called "
+                    + "when disabled. events=" + (mEvents == null ? null : mEvents.size()));
             return;
         }
         if (checkExisting && mHandler.hasMessages(MSG_FLUSH)) {
@@ -375,8 +393,7 @@
         }
         mNextFlush = System.currentTimeMillis() + FLUSHING_FREQUENCY_MS;
         if (VERBOSE) {
-            Log.v(TAG, "handleScheduleFlush(" + getDebugState()
-                    + ", reason=" + getflushReasonAsString(reason) + "): scheduled to flush in "
+            Log.v(TAG, "handleScheduleFlush(): scheduled to flush in "
                     + FLUSHING_FREQUENCY_MS + "ms: " + TimeUtils.logTimeOfDay(mNextFlush));
         }
         mHandler.sendMessageDelayed(
@@ -395,11 +412,16 @@
     private void handleForceFlush(@FlushReason int reason) {
         if (mEvents == null) return;
 
+        if (mDisabled.get()) {
+            Log.e(TAG, "handleForceFlush(" + getDebugState(reason) + "): should not be when "
+                    + "disabled");
+            return;
+        }
+
         if (mDirectServiceInterface == null) {
             if (VERBOSE) {
-                Log.v(TAG, "handleForceFlush(" + getDebugState()
-                        + ", reason=" + getflushReasonAsString(reason)
-                        + "): hold your horses, client not ready: " + mEvents);
+                Log.v(TAG, "handleForceFlush(" + getDebugState(reason) + "): hold your horses, "
+                        + "client not ready: " + mEvents);
             }
             if (!mHandler.hasMessages(MSG_FLUSH)) {
                 handleScheduleFlush(reason, /* checkExisting= */ false);
@@ -410,8 +432,7 @@
         final int numberEvents = mEvents.size();
         final String reasonString = getflushReasonAsString(reason);
         if (DEBUG) {
-            Log.d(TAG, "Flushing " + numberEvents + " event(s) for " + getDebugState()
-                    + ". Reason: " + reasonString);
+            Log.d(TAG, "Flushing " + numberEvents + " event(s) for " + getDebugState(reason));
         }
         // Logs reason, size, max size, idle timeout
         final String logRecord = "r=" + reasonString + " s=" + numberEvents
@@ -592,7 +613,14 @@
                 : "act:" + mComponentName.flattenToShortString();
     }
 
+    @NonNull
     private String getDebugState() {
-        return getActivityName() + " (state=" + getStateAsString(mState) + ")";
+        return getActivityName() + " [state=" + getStateAsString(mState) + ", disabled="
+                + mDisabled.get() + "]";
+    }
+
+    @NonNull
+    private String getDebugState(@FlushReason int reason) {
+        return getDebugState() + ", reason=" + getflushReasonAsString(reason);
     }
 }