Log history of Content Capture flushes.

Bug: 122959591

Test: manual verification
Test: atest CtsContentCaptureServiceTestCases \
            FrameworksCoreTests:android.view.contentcapture.ContentCaptureTest

Change-Id: I9a5af8d1ea882b7b8fbbfa32aa2a37466b524ce5

6 files changed, 124 insertions, 42 deletions

diff --git a/core/java/android/app/Activity.java b/core/java/android/app/Activity.java
index d374f1c0acdf..836627efb379 100644
--- a/core/java/android/app/Activity.java
+++ b/core/java/android/app/Activity.java
@@ -124,6 +124,7 @@ import android.view.autofill.AutofillPopupWindow;
 import android.view.autofill.IAutofillWindowPresenter;
 import android.view.contentcapture.ContentCaptureContext;
 import android.view.contentcapture.ContentCaptureManager;
+import android.view.contentcapture.ContentCaptureSession;
 import android.widget.AdapterView;
 import android.widget.Toast;
 import android.widget.Toolbar;
@@ -1034,13 +1035,15 @@ public class Activity extends ContextThemeWrapper
     }
 
     /** @hide */ private static final int CONTENT_CAPTURE_START = 1;
-    /** @hide */ private static final int CONTENT_CAPTURE_FLUSH = 2;
-    /** @hide */ private static final int CONTENT_CAPTURE_STOP = 3;
+    /** @hide */ private static final int CONTENT_CAPTURE_PAUSE = 2;
+    /** @hide */ private static final int CONTENT_CAPTURE_RESUME = 3;
+    /** @hide */ private static final int CONTENT_CAPTURE_STOP = 4;
 
     /** @hide */
     @IntDef(prefix = { "CONTENT_CAPTURE_" }, value = {
             CONTENT_CAPTURE_START,
-            CONTENT_CAPTURE_FLUSH,
+            CONTENT_CAPTURE_PAUSE,
+            CONTENT_CAPTURE_RESUME,
             CONTENT_CAPTURE_STOP
     })
     @Retention(RetentionPolicy.SOURCE)
@@ -1062,8 +1065,11 @@ public class Activity extends ContextThemeWrapper
                 }
                 cm.onActivityStarted(mToken, getComponentName(), flags);
                 break;
-            case CONTENT_CAPTURE_FLUSH:
-                cm.flush();
+            case CONTENT_CAPTURE_PAUSE:
+                cm.flush(ContentCaptureSession.FLUSH_REASON_ACTIVITY_PAUSED);
+                break;
+            case CONTENT_CAPTURE_RESUME:
+                cm.flush(ContentCaptureSession.FLUSH_REASON_ACTIVITY_RESUMED);
                 break;
             case CONTENT_CAPTURE_STOP:
                 cm.onActivityStopped();
@@ -1755,7 +1761,7 @@ public class Activity extends ContextThemeWrapper
             }
         }
         mCalled = true;
-        notifyContentCaptureManagerIfNeeded(CONTENT_CAPTURE_FLUSH);
+        notifyContentCaptureManagerIfNeeded(CONTENT_CAPTURE_RESUME);
     }
 
     /**
@@ -2149,7 +2155,7 @@ public class Activity extends ContextThemeWrapper
             }
         }
         mCalled = true;
-        notifyContentCaptureManagerIfNeeded(CONTENT_CAPTURE_FLUSH);
+        notifyContentCaptureManagerIfNeeded(CONTENT_CAPTURE_PAUSE);
     }
 
     /**
diff --git a/core/java/android/view/contentcapture/ChildContentCaptureSession.java b/core/java/android/view/contentcapture/ChildContentCaptureSession.java
index 04e725e64e9c..cb4c4b4b6899 100644
--- a/core/java/android/view/contentcapture/ChildContentCaptureSession.java
+++ b/core/java/android/view/contentcapture/ChildContentCaptureSession.java
@@ -68,8 +68,8 @@ final class ChildContentCaptureSession extends ContentCaptureSession {
     }
 
     @Override
-    void flush() {
-        mParent.flush();
+    void flush(@FlushReason int reason) {
+        mParent.flush(reason);
     }
 
     @Override
diff --git a/core/java/android/view/contentcapture/ContentCaptureManager.java b/core/java/android/view/contentcapture/ContentCaptureManager.java
index 81b2e01dfbc7..209dc2cbac25 100644
--- a/core/java/android/view/contentcapture/ContentCaptureManager.java
+++ b/core/java/android/view/contentcapture/ContentCaptureManager.java
@@ -28,6 +28,7 @@ import android.os.HandlerThread;
 import android.os.IBinder;
 import android.os.RemoteException;
 import android.util.Log;
+import android.view.contentcapture.ContentCaptureSession.FlushReason;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.os.IResultReceiver;
@@ -154,8 +155,8 @@ public final class ContentCaptureManager {
      *
      * @hide
      */
-    public void flush() {
-        getMainContentCaptureSession().flush();
+    public void flush(@FlushReason int reason) {
+        getMainContentCaptureSession().flush(reason);
     }
 
     /**
diff --git a/core/java/android/view/contentcapture/ContentCaptureSession.java b/core/java/android/view/contentcapture/ContentCaptureSession.java
index 7bfc5b413615..a9e7b5e5de70 100644
--- a/core/java/android/view/contentcapture/ContentCaptureSession.java
+++ b/core/java/android/view/contentcapture/ContentCaptureSession.java
@@ -19,6 +19,7 @@ import static android.view.contentcapture.ContentCaptureManager.DEBUG;
 import static android.view.contentcapture.ContentCaptureManager.VERBOSE;
 
 import android.annotation.CallSuper;
+import android.annotation.IntDef;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
 import android.util.DebugUtils;
@@ -35,6 +36,8 @@ import com.android.internal.util.Preconditions;
 import dalvik.system.CloseGuard;
 
 import java.io.PrintWriter;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
 import java.util.ArrayList;
 import java.util.UUID;
 
@@ -125,6 +128,32 @@ public abstract class ContentCaptureSession implements AutoCloseable {
 
     private static final int INITIAL_CHILDREN_CAPACITY = 5;
 
+    /** @hide */
+    public static final int FLUSH_REASON_FULL = 1;
+    /** @hide */
+    public static final int FLUSH_REASON_ACTIVITY_PAUSED = 2;
+    /** @hide */
+    public static final int FLUSH_REASON_ACTIVITY_RESUMED = 3;
+    /** @hide */
+    public static final int FLUSH_REASON_SESSION_STARTED = 4;
+    /** @hide */
+    public static final int FLUSH_REASON_SESSION_FINISHED = 5;
+    /** @hide */
+    public static final int FLUSH_REASON_IDLE_TIMEOUT = 6;
+
+    /** @hide */
+    @IntDef(prefix = { "FLUSH_REASON_" }, value = {
+            FLUSH_REASON_FULL,
+            FLUSH_REASON_ACTIVITY_PAUSED,
+            FLUSH_REASON_ACTIVITY_RESUMED,
+            FLUSH_REASON_SESSION_STARTED,
+            FLUSH_REASON_SESSION_FINISHED,
+            FLUSH_REASON_IDLE_TIMEOUT
+    })
+    @Retention(RetentionPolicy.SOURCE)
+    @interface FlushReason{}
+
+
     private final CloseGuard mCloseGuard = CloseGuard.get();
 
     private final Object mLock = new Object();
@@ -212,7 +241,7 @@ public abstract class ContentCaptureSession implements AutoCloseable {
     /**
      * Flushes the buffered events to the service.
      */
-    abstract void flush();
+    abstract void flush(@FlushReason int reason);
 
     /**
      * Destroys this session, flushing out all pending notifications to the service.
@@ -250,7 +279,7 @@ public abstract class ContentCaptureSession implements AutoCloseable {
         }
 
         try {
-            flush();
+            flush(FLUSH_REASON_SESSION_FINISHED);
         } finally {
             onDestroy();
         }
@@ -407,12 +436,31 @@ public abstract class ContentCaptureSession implements AutoCloseable {
         return mId;
     }
 
-    /**
-     * @hide
-     */
+    /** @hide */
     @NonNull
     protected static String getStateAsString(int state) {
         return state + " (" + (state == UNKNWON_STATE ? "UNKNOWN"
                 : DebugUtils.flagsToString(ContentCaptureSession.class, "STATE_", state)) + ")";
     }
+
+    /** @hide */
+    @NonNull
+    static String getflushReasonAsString(@FlushReason int reason) {
+        switch (reason) {
+            case FLUSH_REASON_FULL:
+                return "FULL";
+            case FLUSH_REASON_ACTIVITY_PAUSED:
+                return "PAUSED";
+            case FLUSH_REASON_ACTIVITY_RESUMED:
+                return "RESUMED";
+            case FLUSH_REASON_SESSION_STARTED:
+                return "STARTED";
+            case FLUSH_REASON_SESSION_FINISHED:
+                return "FINISHED";
+            case FLUSH_REASON_IDLE_TIMEOUT:
+                return "IDLE";
+            default:
+                return "UNKOWN-" + reason;
+        }
+    }
 }
diff --git a/core/java/android/view/contentcapture/MainContentCaptureSession.java b/core/java/android/view/contentcapture/MainContentCaptureSession.java
index a3ff8c09aa0c..f0778fa343b1 100644
--- a/core/java/android/view/contentcapture/MainContentCaptureSession.java
+++ b/core/java/android/view/contentcapture/MainContentCaptureSession.java
@@ -35,7 +35,7 @@ import android.os.Handler;
 import android.os.IBinder;
 import android.os.IBinder.DeathRecipient;
 import android.os.RemoteException;
-import android.os.SystemClock;
+import android.util.LocalLog;
 import android.util.Log;
 import android.util.TimeUtils;
 import android.view.autofill.AutofillId;
@@ -131,6 +131,9 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
     // Used just for debugging purposes (on dump)
     private long mNextFlush;
 
+    // TODO(b/121044064): use settings to set size
+    private final LocalLog mFlushHistory = new LocalLog(10);
+
     /** @hide */
     protected MainContentCaptureSession(@NonNull Context context, @NonNull Handler handler,
             @Nullable IContentCaptureManager systemServerInterface,
@@ -172,8 +175,9 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
     }
 
     @Override
-    void flush() {
-        mHandler.sendMessage(obtainMessage(MainContentCaptureSession::handleForceFlush, this));
+    void flush(@FlushReason int reason) {
+        mHandler.sendMessage(
+                obtainMessage(MainContentCaptureSession::handleForceFlush, this, reason));
     }
 
     @Override
@@ -264,24 +268,25 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
     }
 
     private void handleSendEvent(@NonNull ContentCaptureEvent event, boolean forceFlush) {
-        if (!handleHasStarted()
-                && event.getType() != ContentCaptureEvent.TYPE_SESSION_STARTED) {
+        final int eventType = event.getType();
+        if (!handleHasStarted() && eventType != ContentCaptureEvent.TYPE_SESSION_STARTED) {
             // TODO(b/120494182): comment when this could happen (dialogs?)
             Log.v(TAG, "handleSendEvent(" + getDebugState() + ", "
-                    + ContentCaptureEvent.getTypeAsString(event.getType())
+                    + ContentCaptureEvent.getTypeAsString(eventType)
                     + "): session not started yet");
             return;
         }
+        if (VERBOSE) Log.v(TAG, "handleSendEvent(" + getDebugState() + "): " + event);
         if (mEvents == null) {
             if (VERBOSE) {
                 Log.v(TAG, "handleSendEvent(" + getDebugState() + ", "
-                        + ContentCaptureEvent.getTypeAsString(event.getType())
-                        + "): cCreating buffer for " + MAX_BUFFER_SIZE + " events");
+                        + ContentCaptureEvent.getTypeAsString(eventType)
+                        + "): creating buffer for " + MAX_BUFFER_SIZE + " events");
             }
             mEvents = new ArrayList<>(MAX_BUFFER_SIZE);
         }
 
-        if (!mEvents.isEmpty() && event.getType() == TYPE_VIEW_TEXT_CHANGED) {
+        if (!mEvents.isEmpty() && eventType == TYPE_VIEW_TEXT_CHANGED) {
             final ContentCaptureEvent lastEvent = mEvents.get(mEvents.size() - 1);
 
             // TODO(b/121045053): check if flags match
@@ -304,7 +309,7 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
         final boolean bufferEvent = numberEvents < MAX_BUFFER_SIZE;
 
         if (bufferEvent && !forceFlush) {
-            handleScheduleFlush(/* checkExisting= */ true);
+            handleScheduleFlush(FLUSH_REASON_IDLE_TIMEOUT, /* checkExisting= */ true);
             return;
         }
 
@@ -323,15 +328,26 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
             // when it's launched again
             return;
         }
+        final int flushReason;
+        switch (eventType) {
+            case ContentCaptureEvent.TYPE_SESSION_STARTED:
+                flushReason = FLUSH_REASON_SESSION_STARTED;
+                break;
+            case ContentCaptureEvent.TYPE_SESSION_FINISHED:
+                flushReason = FLUSH_REASON_SESSION_FINISHED;
+                break;
+            default:
+                flushReason = FLUSH_REASON_FULL;
+        }
 
-        handleForceFlush();
+        handleForceFlush(flushReason);
     }
 
     private boolean handleHasStarted() {
         return mState != UNKNWON_STATE;
     }
 
-    private void handleScheduleFlush(boolean checkExisting) {
+    private void handleScheduleFlush(@FlushReason int reason, boolean checkExisting) {
         if (!handleHasStarted()) {
             Log.v(TAG, "handleScheduleFlush(" + getDebugState() + "): session not started yet");
             return;
@@ -340,43 +356,51 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
             // "Renew" the flush message by removing the previous one
             mHandler.removeMessages(MSG_FLUSH);
         }
-        mNextFlush = SystemClock.elapsedRealtime() + FLUSHING_FREQUENCY_MS;
+        mNextFlush = System.currentTimeMillis() + FLUSHING_FREQUENCY_MS;
         if (VERBOSE) {
-            Log.v(TAG, "handleScheduleFlush(" + getDebugState() + "): scheduled to flush in "
-                    + FLUSHING_FREQUENCY_MS + "ms: " + TimeUtils.formatUptime(mNextFlush));
+            Log.v(TAG, "handleScheduleFlush(" + getDebugState()
+                    + ", reason=" + getflushReasonAsString(reason) + "): scheduled to flush in "
+                    + FLUSHING_FREQUENCY_MS + "ms: " + TimeUtils.logTimeOfDay(mNextFlush));
         }
         mHandler.sendMessageDelayed(
-                obtainMessage(MainContentCaptureSession::handleFlushIfNeeded, this)
+                obtainMessage(MainContentCaptureSession::handleFlushIfNeeded, this, reason)
                 .setWhat(MSG_FLUSH), FLUSHING_FREQUENCY_MS);
     }
 
-    private void handleFlushIfNeeded() {
+    private void handleFlushIfNeeded(@FlushReason int reason) {
         if (mEvents.isEmpty()) {
             if (VERBOSE) Log.v(TAG, "Nothing to flush");
             return;
         }
-        handleForceFlush();
+        handleForceFlush(reason);
     }
 
-    private void handleForceFlush() {
+    private void handleForceFlush(@FlushReason int reason) {
         if (mEvents == null) return;
 
         if (mDirectServiceInterface == null) {
             if (VERBOSE) {
                 Log.v(TAG, "handleForceFlush(" + getDebugState()
+                        + ", reason=" + getflushReasonAsString(reason)
                         + "): hold your horses, client not ready: " + mEvents);
             }
             if (!mHandler.hasMessages(MSG_FLUSH)) {
-                handleScheduleFlush(/* checkExisting= */ false);
+                handleScheduleFlush(reason, /* checkExisting= */ false);
             }
             return;
         }
 
         final int numberEvents = mEvents.size();
+        final String reasonString = getflushReasonAsString(reason);
+        if (DEBUG) {
+            Log.d(TAG, "Flushing " + numberEvents + " event(s) for " + getDebugState()
+                    + ". Reason: " + reasonString);
+        }
+        // Logs reason, size, max size, idle timeout
+        final String logRecord = "r=" + reasonString + " s=" + numberEvents
+                + " m=" + MAX_BUFFER_SIZE + " i=" + FLUSHING_FREQUENCY_MS;
         try {
-            if (DEBUG) {
-                Log.d(TAG, "Flushing " + numberEvents + " event(s) for " + getDebugState());
-            }
+            mFlushHistory.log(logRecord);
             mHandler.removeMessages(MSG_FLUSH);
 
             final ParceledListSlice<ContentCaptureEvent> events = handleClearEvents();
@@ -500,7 +524,6 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
 
     @Override
     void dump(@NonNull String prefix, @NonNull PrintWriter pw) {
-        pw.print(prefix); pw.print("id: "); pw.println(mId);
         pw.print(prefix); pw.print("mContext: "); pw.println(mContext);
         pw.print(prefix); pw.print("user: "); pw.println(mContext.getUserId());
         if (mSystemServerInterface != null) {
@@ -535,8 +558,12 @@ public final class MainContentCaptureSession extends ContentCaptureSession {
             }
             pw.print(prefix); pw.print("flush frequency: "); pw.println(FLUSHING_FREQUENCY_MS);
             pw.print(prefix); pw.print("next flush: ");
-            TimeUtils.formatDuration(mNextFlush - SystemClock.elapsedRealtime(), pw); pw.println();
+            TimeUtils.formatDuration(mNextFlush - System.currentTimeMillis(), pw);
+            pw.print(" ("); pw.print(TimeUtils.logTimeOfDay(mNextFlush)); pw.println(")");
         }
+        pw.print(prefix); pw.println("flush history:");
+        mFlushHistory.reverseDump(/* fd= */ null, pw, /* args= */ null); pw.println();
+
         super.dump(prefix, pw);
     }
 
diff --git a/core/tests/coretests/src/android/view/contentcapture/ContentCaptureSessionTest.java b/core/tests/coretests/src/android/view/contentcapture/ContentCaptureSessionTest.java
index 73cceaeee547..4d3302404d87 100644
--- a/core/tests/coretests/src/android/view/contentcapture/ContentCaptureSessionTest.java
+++ b/core/tests/coretests/src/android/view/contentcapture/ContentCaptureSessionTest.java
@@ -114,7 +114,7 @@ public class ContentCaptureSessionTest {
         }
 
         @Override
-        void flush() {
+        void flush(int reason) {
             throw new UnsupportedOperationException("should not have been called");
         }