diff options
author | 2024-12-20 17:32:08 +0000 | |
---|---|---|
committer | 2024-12-23 06:30:09 -0800 | |
commit | f54823d138ccbb9b3339eeb173d6b7e820f945b0 (patch) | |
tree | 4961fa5ef7d1ee08852739eaee062c3344a8cb0a | |
parent | 9f05161c64320212c90ebf5404d2a836f510c8c2 (diff) |
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
6 files changed, 265 insertions, 64 deletions
diff --git a/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java b/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java index e527de209a75..88001fc6cc3c 100644 --- a/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java +++ b/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java @@ -19,7 +19,6 @@ package android.app.appfunctions; import android.annotation.NonNull; import android.annotation.Nullable; import android.os.RemoteException; -import android.os.SystemClock; import android.util.Log; import java.util.Objects; @@ -40,8 +39,7 @@ public class SafeOneTimeExecuteAppFunctionCallback { @NonNull private final IExecuteAppFunctionCallback mCallback; - @Nullable - private final CompletionCallback mCompletionCallback; + @Nullable private final CompletionCallback mCompletionCallback; private final AtomicLong mExecutionStartTimeAfterBindMillis = new AtomicLong(); @@ -49,7 +47,8 @@ public class SafeOneTimeExecuteAppFunctionCallback { this(callback, /* completionCallback= */ null); } - public SafeOneTimeExecuteAppFunctionCallback(@NonNull IExecuteAppFunctionCallback callback, + public SafeOneTimeExecuteAppFunctionCallback( + @NonNull IExecuteAppFunctionCallback callback, @Nullable CompletionCallback completionCallback) { mCallback = Objects.requireNonNull(callback); mCompletionCallback = completionCallback; @@ -64,8 +63,8 @@ public class SafeOneTimeExecuteAppFunctionCallback { try { mCallback.onSuccess(result); if (mCompletionCallback != null) { - mCompletionCallback.finalizeOnSuccess(result, - mExecutionStartTimeAfterBindMillis.get()); + mCompletionCallback.finalizeOnSuccess( + result, mExecutionStartTimeAfterBindMillis.get()); } } catch (RemoteException ex) { // Failed to notify the other end. Ignore. @@ -82,8 +81,8 @@ public class SafeOneTimeExecuteAppFunctionCallback { try { mCallback.onError(error); if (mCompletionCallback != null) { - mCompletionCallback.finalizeOnError(error, - mExecutionStartTimeAfterBindMillis.get()); + mCompletionCallback.finalizeOnError( + error, mExecutionStartTimeAfterBindMillis.get()); } } catch (RemoteException ex) { // Failed to notify the other end. Ignore. @@ -103,9 +102,10 @@ public class SafeOneTimeExecuteAppFunctionCallback { * Sets the execution start time of the request. Used to calculate the overhead latency of * requests. */ - public void setExecutionStartTimeMillis() { - if (!mExecutionStartTimeAfterBindMillis.compareAndSet(0, SystemClock.elapsedRealtime())) { - Log.w(TAG, "Ignore subsequent calls to setExecutionStartTimeMillis()"); + public void setExecutionStartTimeAfterBindMillis(long executionStartTimeAfterBindMillis) { + if (!mExecutionStartTimeAfterBindMillis.compareAndSet( + 0, executionStartTimeAfterBindMillis)) { + Log.w(TAG, "Ignore subsequent calls to setExecutionStartTimeAfterBindMillis()"); } } @@ -115,8 +115,8 @@ public class SafeOneTimeExecuteAppFunctionCallback { */ public interface CompletionCallback { /** Called after {@link IExecuteAppFunctionCallback#onSuccess}. */ - void finalizeOnSuccess(@NonNull ExecuteAppFunctionResponse result, - long executionStartTimeMillis); + void finalizeOnSuccess( + @NonNull ExecuteAppFunctionResponse result, long executionStartTimeMillis); /** Called after {@link IExecuteAppFunctionCallback#onError}. */ void finalizeOnError(@NonNull AppFunctionException error, long executionStartTimeMillis); 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")); } diff --git a/services/tests/appfunctions/Android.bp b/services/tests/appfunctions/Android.bp index 836f90b992d6..e48abc24ecf3 100644 --- a/services/tests/appfunctions/Android.bp +++ b/services/tests/appfunctions/Android.bp @@ -33,18 +33,20 @@ android_test { ], static_libs: [ + "androidx.core_core-ktx", "androidx.test.core", - "androidx.test.runner", "androidx.test.ext.truth", - "androidx.core_core-ktx", + "androidx.test.rules", + "androidx.test.runner", + "frameworks-base-testutils", "kotlin-test", "kotlinx_coroutines_test", + "mockito-kotlin2", + "mockito-target-extended-minus-junit4", "platform-test-annotations", "services.appfunctions", "servicestests-core-utils", "truth", - "frameworks-base-testutils", - "androidx.test.rules", ], libs: [ diff --git a/services/tests/appfunctions/src/com/android/server/appfunctions/AppFunctionsLoggingTest.kt b/services/tests/appfunctions/src/com/android/server/appfunctions/AppFunctionsLoggingTest.kt new file mode 100644 index 000000000000..896d2a21d0ac --- /dev/null +++ b/services/tests/appfunctions/src/com/android/server/appfunctions/AppFunctionsLoggingTest.kt @@ -0,0 +1,139 @@ +/* + * Copyright (C) 2024 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 com.android.server.appfunctions + +import android.app.appfunctions.AppFunctionException +import android.app.appfunctions.ExecuteAppFunctionAidlRequest +import android.app.appfunctions.ExecuteAppFunctionRequest +import android.app.appfunctions.ExecuteAppFunctionResponse +import android.app.appfunctions.IAppFunctionService +import android.app.appfunctions.IExecuteAppFunctionCallback +import android.app.appfunctions.SafeOneTimeExecuteAppFunctionCallback +import android.app.appsearch.GenericDocument +import android.content.Context +import android.content.pm.PackageManager +import android.os.UserHandle +import androidx.test.core.app.ApplicationProvider +import androidx.test.ext.junit.runners.AndroidJUnit4 +import com.android.dx.mockito.inline.extended.ExtendedMockito +import com.android.modules.utils.testing.ExtendedMockitoRule +import com.google.common.util.concurrent.MoreExecutors +import org.junit.Before +import org.junit.Rule +import org.junit.Test +import org.junit.runner.RunWith +import org.mockito.kotlin.any +import org.mockito.kotlin.eq +import org.mockito.kotlin.mock +import org.mockito.kotlin.whenever + + +/** + * Tests that AppFunctionsStatsLog logs AppFunctionsRequestReported with the expected values. + */ +@RunWith(AndroidJUnit4::class) +class AppFunctionsLoggingTest { + @get:Rule + val mExtendedMockitoRule: ExtendedMockitoRule = + ExtendedMockitoRule.Builder(this) + .mockStatic(AppFunctionsStatsLog::class.java) + .build() + private val mContext: Context get() = ApplicationProvider.getApplicationContext() + private val mMockPackageManager = mock<PackageManager>() + private val mAppFunctionsLoggerWrapper = + AppFunctionsLoggerWrapper( + mMockPackageManager, + MoreExecutors.directExecutor(), + { TEST_CURRENT_TIME_MILLIS }) + private lateinit var mSafeCallback: SafeOneTimeExecuteAppFunctionCallback + + private val mServiceImpl = + AppFunctionManagerServiceImpl( + mContext, + mock<RemoteServiceCaller<IAppFunctionService>>(), + mock<CallerValidator>(), + mock<ServiceHelper>(), + ServiceConfigImpl(), + mAppFunctionsLoggerWrapper) + + private val mRequestInternal = ExecuteAppFunctionAidlRequest( + ExecuteAppFunctionRequest.Builder(TEST_TARGET_PACKAGE, TEST_FUNCTION_ID).build(), + UserHandle.CURRENT, TEST_CALLING_PKG, TEST_INITIAL_REQUEST_TIME_MILLIS + ) + + @Before + fun setup() { + whenever(mMockPackageManager.getPackageUid(eq(TEST_TARGET_PACKAGE), any<Int>())).thenReturn(TEST_TARGET_UID) + mSafeCallback = mServiceImpl.initializeSafeExecuteAppFunctionCallback(mRequestInternal, mock<IExecuteAppFunctionCallback>(), TEST_CALLING_UID) + mSafeCallback.setExecutionStartTimeAfterBindMillis(TEST_EXECUTION_TIME_AFTER_BIND_MILLIS) + } + + @Test + fun testOnSuccess_logsSuccessResponse() { + val response = + ExecuteAppFunctionResponse(GenericDocument.Builder<GenericDocument.Builder<*>>("", "", "") + .setPropertyLong("longProperty", 42L).setPropertyString("stringProperty", "text").build()) + + mSafeCallback.onResult(response) + + ExtendedMockito.verify { + AppFunctionsStatsLog.write( + /* atomId= */ eq<Int>(AppFunctionsStatsLog.APP_FUNCTIONS_REQUEST_REPORTED), + /* callerPackageUid= */ eq<Int>(TEST_CALLING_UID), + /* targetPackageUid= */ eq<Int>(TEST_TARGET_UID), + /* errorCode= */ eq<Int>(AppFunctionsLoggerWrapper.SUCCESS_RESPONSE_CODE), + /* requestSizeBytes= */ eq<Int>(mRequestInternal.clientRequest.requestDataSize), + /* responseSizeBytes= */ eq<Int>(response.responseDataSize), + /* requestDurationMs= */ eq<Long>(TEST_EXPECTED_E2E_DURATION_MILLIS), + /* requestOverheadMs= */ eq<Long>(TEST_EXPECTED_OVERHEAD_DURATION_MILLIS) + ) + } + } + + @Test + fun testOnError_logsFailureResponse() { + mSafeCallback.onError(AppFunctionException(AppFunctionException.ERROR_DENIED, "Error: permission denied")) + + ExtendedMockito.verify { + AppFunctionsStatsLog.write( + /* atomId= */ eq<Int>(AppFunctionsStatsLog.APP_FUNCTIONS_REQUEST_REPORTED), + /* callerPackageUid= */ eq<Int>(TEST_CALLING_UID), + /* targetPackageUid= */ eq<Int>(TEST_TARGET_UID), + /* errorCode= */ eq<Int>(AppFunctionException.ERROR_DENIED), + /* requestSizeBytes= */ eq<Int>(mRequestInternal.clientRequest.requestDataSize), + /* responseSizeBytes= */ eq<Int>(0), + /* requestDurationMs= */ eq<Long>(TEST_EXPECTED_E2E_DURATION_MILLIS), + /* requestOverheadMs= */ eq<Long>(TEST_EXPECTED_OVERHEAD_DURATION_MILLIS) + ) + } + } + + private companion object { + const val TEST_CALLING_PKG = "com.android.trusted.caller" + const val TEST_CALLING_UID = 12345 + const val TEST_TARGET_PACKAGE = "com.android.trusted.target" + const val TEST_TARGET_UID = 54321 + const val TEST_FUNCTION_ID = "com.android.valid.target.doSomething" + + const val TEST_INITIAL_REQUEST_TIME_MILLIS = 10L + const val TEST_EXECUTION_TIME_AFTER_BIND_MILLIS = 20L + const val TEST_CURRENT_TIME_MILLIS = 50L + const val TEST_EXPECTED_E2E_DURATION_MILLIS = + TEST_CURRENT_TIME_MILLIS - TEST_INITIAL_REQUEST_TIME_MILLIS + const val TEST_EXPECTED_OVERHEAD_DURATION_MILLIS = + TEST_EXECUTION_TIME_AFTER_BIND_MILLIS - TEST_INITIAL_REQUEST_TIME_MILLIS + } +} |