Test AppFunctions logging

Add tests that verify AppFunctionsStatsLog is called with the expected values when the appfunction service reports a result or error.

Flag: android.app.appfunctions.flags.enable_app_function_manager
Bug: 376688078
Test: unit tests
Change-Id: Ia1b23644726e2d497af39c02be5d97f77786b388

3 files changed, 107 insertions, 47 deletions

diff --git a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
index 669025f071c0..37276ddac75a 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
@@ -155,23 +155,8 @@ public class AppFunctionManagerServiceImpl extends IAppFunctionManager.Stub {
         int callingPid = Binder.getCallingPid();
 
         final SafeOneTimeExecuteAppFunctionCallback safeExecuteAppFunctionCallback =
-                new SafeOneTimeExecuteAppFunctionCallback(executeAppFunctionCallback,
-                        new SafeOneTimeExecuteAppFunctionCallback.CompletionCallback() {
-                            @Override
-                            public void finalizeOnSuccess(
-                                    @NonNull ExecuteAppFunctionResponse result,
-                                    long executionStartTimeMillis) {
-                                mLoggerWrapper.logAppFunctionSuccess(requestInternal, result,
-                                        callingUid, executionStartTimeMillis);
-                            }
-
-                            @Override
-                            public void finalizeOnError(@NonNull AppFunctionException error,
-                                    long executionStartTimeMillis) {
-                                mLoggerWrapper.logAppFunctionError(requestInternal,
-                                        error.getErrorCode(), callingUid, executionStartTimeMillis);
-                            }
-                        });
+                initializeSafeExecuteAppFunctionCallback(
+                        requestInternal, executeAppFunctionCallback, callingUid);
 
         String validatedCallingPackage;
         try {
@@ -576,6 +561,38 @@ public class AppFunctionManagerServiceImpl extends IAppFunctionManager.Stub {
         }
     }
 
+    /**
+     * Returns a new {@link SafeOneTimeExecuteAppFunctionCallback} initialized with a {@link
+     * SafeOneTimeExecuteAppFunctionCallback.CompletionCallback} that logs the results.
+     */
+    @VisibleForTesting
+    SafeOneTimeExecuteAppFunctionCallback initializeSafeExecuteAppFunctionCallback(
+            @NonNull ExecuteAppFunctionAidlRequest requestInternal,
+            @NonNull IExecuteAppFunctionCallback executeAppFunctionCallback,
+            int callingUid) {
+        return new SafeOneTimeExecuteAppFunctionCallback(
+                executeAppFunctionCallback,
+                new SafeOneTimeExecuteAppFunctionCallback.CompletionCallback() {
+                    @Override
+                    public void finalizeOnSuccess(
+                            @NonNull ExecuteAppFunctionResponse result,
+                            long executionStartTimeMillis) {
+                        mLoggerWrapper.logAppFunctionSuccess(
+                                requestInternal, result, callingUid, executionStartTimeMillis);
+                    }
+
+                    @Override
+                    public void finalizeOnError(
+                            @NonNull AppFunctionException error, long executionStartTimeMillis) {
+                        mLoggerWrapper.logAppFunctionError(
+                                requestInternal,
+                                error.getErrorCode(),
+                                callingUid,
+                                executionStartTimeMillis);
+                    }
+                });
+    }
+
     private static class AppFunctionMetadataObserver implements ObserverCallback {
         @Nullable private final MetadataSyncAdapter mPerUserMetadataSyncAdapter;
 
diff --git a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
index 7ba1bbc536f6..666d8fe0044c 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
@@ -26,58 +26,99 @@ import android.content.pm.PackageManager;
 import android.os.SystemClock;
 import android.util.Slog;
 
+import com.android.internal.annotations.VisibleForTesting;
+
 import java.util.Objects;
+import java.util.concurrent.Executor;
 
 /** Wraps AppFunctionsStatsLog. */
 public class AppFunctionsLoggerWrapper {
     private static final String TAG = AppFunctionsLoggerWrapper.class.getSimpleName();
 
-    private static final int SUCCESS_RESPONSE_CODE = -1;
+    @VisibleForTesting static final int SUCCESS_RESPONSE_CODE = -1;
+
+    private final PackageManager mPackageManager;
+    private final Executor mLoggingExecutor;
+    private final AppFunctionsLoggerClock mLoggerClock;
 
-    private final Context mContext;
+    AppFunctionsLoggerWrapper(@NonNull Context context) {
+        this(context.getPackageManager(), LOGGING_THREAD_EXECUTOR, SystemClock::elapsedRealtime);
+    }
 
-    public AppFunctionsLoggerWrapper(@NonNull Context context) {
-        mContext = Objects.requireNonNull(context);
+    @VisibleForTesting
+    AppFunctionsLoggerWrapper(
+            @NonNull PackageManager packageManager,
+            @NonNull Executor executor,
+            AppFunctionsLoggerClock loggerClock) {
+        mLoggingExecutor = Objects.requireNonNull(executor);
+        mPackageManager = Objects.requireNonNull(packageManager);
+        mLoggerClock = loggerClock;
     }
 
-    void logAppFunctionSuccess(ExecuteAppFunctionAidlRequest request,
-            ExecuteAppFunctionResponse response, int callingUid, long executionStartTimeMillis) {
-        logAppFunctionsRequestReported(request, SUCCESS_RESPONSE_CODE,
-                response.getResponseDataSize(), callingUid, executionStartTimeMillis);
+    void logAppFunctionSuccess(
+            ExecuteAppFunctionAidlRequest request,
+            ExecuteAppFunctionResponse response,
+            int callingUid,
+            long executionStartTimeMillis) {
+        logAppFunctionsRequestReported(
+                request,
+                SUCCESS_RESPONSE_CODE,
+                response.getResponseDataSize(),
+                callingUid,
+                executionStartTimeMillis);
     }
 
-    void logAppFunctionError(ExecuteAppFunctionAidlRequest request, int errorCode, int callingUid,
+    void logAppFunctionError(
+            ExecuteAppFunctionAidlRequest request,
+            int errorCode,
+            int callingUid,
             long executionStartTimeMillis) {
-        logAppFunctionsRequestReported(request, errorCode, /* responseSizeBytes = */ 0, callingUid,
+        logAppFunctionsRequestReported(
+                request,
+                errorCode,
+                /* responseSizeBytes= */ 0,
+                callingUid,
                 executionStartTimeMillis);
     }
 
-    private void logAppFunctionsRequestReported(ExecuteAppFunctionAidlRequest request,
-            int errorCode, int responseSizeBytes, int callingUid, long executionStartTimeMillis) {
+    private void logAppFunctionsRequestReported(
+            ExecuteAppFunctionAidlRequest request,
+            int errorCode,
+            int responseSizeBytes,
+            int callingUid,
+            long executionStartTimeMillis) {
         final long e2eRequestLatencyMillis =
-                SystemClock.elapsedRealtime() - request.getRequestTime();
+                mLoggerClock.getCurrentTimeMillis() - request.getRequestTime();
         final long requestOverheadMillis =
-                executionStartTimeMillis > 0 ? (executionStartTimeMillis - request.getRequestTime())
+                executionStartTimeMillis > 0
+                        ? (executionStartTimeMillis - request.getRequestTime())
                         : e2eRequestLatencyMillis;
-        LOGGING_THREAD_EXECUTOR.execute(() -> AppFunctionsStatsLog.write(
-                AppFunctionsStatsLog.APP_FUNCTIONS_REQUEST_REPORTED,
-                /* callerPackageUid= */ callingUid,
-                /* targetPackageUid= */
-                getPackageUid(request.getClientRequest().getTargetPackageName()),
-                /* errorCode= */ errorCode,
-                /* requestSizeBytes= */ request.getClientRequest().getRequestDataSize(),
-                /* responseSizeBytes= */  responseSizeBytes,
-                /* requestDurationMs= */ e2eRequestLatencyMillis,
-                /* requestOverheadMs= */ requestOverheadMillis)
-        );
+        mLoggingExecutor.execute(
+                () ->
+                        AppFunctionsStatsLog.write(
+                                AppFunctionsStatsLog.APP_FUNCTIONS_REQUEST_REPORTED,
+                                /* callerPackageUid= */ callingUid,
+                                /* targetPackageUid= */ getPackageUid(
+                                        request.getClientRequest().getTargetPackageName()),
+                                /* errorCode= */ errorCode,
+                                /* requestSizeBytes= */ request.getClientRequest()
+                                        .getRequestDataSize(),
+                                /* responseSizeBytes= */ responseSizeBytes,
+                                /* requestDurationMs= */ e2eRequestLatencyMillis,
+                                /* requestOverheadMs= */ requestOverheadMillis));
     }
 
     private int getPackageUid(String packageName) {
         try {
-            return mContext.getPackageManager().getPackageUid(packageName, 0);
+            return mPackageManager.getPackageUid(packageName, 0);
         } catch (PackageManager.NameNotFoundException e) {
             Slog.e(TAG, "Package uid not found for " + packageName);
         }
         return 0;
     }
+
+    /** Wraps a custom clock for easier testing. */
+    interface AppFunctionsLoggerClock {
+        long getCurrentTimeMillis();
+    }
 }
diff --git a/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java b/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
index a5ae7e310022..4cba8ecb2092 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
@@ -23,6 +23,7 @@ import android.app.appfunctions.IAppFunctionService;
 import android.app.appfunctions.ICancellationCallback;
 import android.app.appfunctions.IExecuteAppFunctionCallback;
 import android.app.appfunctions.SafeOneTimeExecuteAppFunctionCallback;
+import android.os.SystemClock;
 import android.util.Slog;
 
 import com.android.server.appfunctions.RemoteServiceCaller.RunServiceCallCallback;
@@ -52,7 +53,8 @@ public class RunAppFunctionServiceCallback implements RunServiceCallCallback<IAp
             @NonNull IAppFunctionService service,
             @NonNull ServiceUsageCompleteListener serviceUsageCompleteListener) {
         try {
-            mSafeExecuteAppFunctionCallback.setExecutionStartTimeMillis();
+            mSafeExecuteAppFunctionCallback.setExecutionStartTimeAfterBindMillis(
+                    SystemClock.elapsedRealtime());
             service.executeAppFunction(
                     mRequestInternal.getClientRequest(),
                     mRequestInternal.getCallingPackage(),
@@ -73,8 +75,7 @@ public class RunAppFunctionServiceCallback implements RunServiceCallCallback<IAp
         } catch (Exception e) {
             mSafeExecuteAppFunctionCallback.onError(
                     new AppFunctionException(
-                            AppFunctionException.ERROR_APP_UNKNOWN_ERROR,
-                            e.getMessage()));
+                            AppFunctionException.ERROR_APP_UNKNOWN_ERROR, e.getMessage()));
             serviceUsageCompleteListener.onCompleted();
         }
     }
@@ -83,7 +84,8 @@ public class RunAppFunctionServiceCallback implements RunServiceCallCallback<IAp
     public void onFailedToConnect() {
         Slog.e(TAG, "Failed to connect to service");
         mSafeExecuteAppFunctionCallback.onError(
-                new AppFunctionException(AppFunctionException.ERROR_APP_UNKNOWN_ERROR,
+                new AppFunctionException(
+                        AppFunctionException.ERROR_APP_UNKNOWN_ERROR,
                         "Failed to connect to AppFunctionService"));
     }