Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e4b76fc2 authored by Joanne Chung's avatar Joanne Chung
Browse files

Add hotword detection metrics. 

Bug: 207717787
Test: build & boot pass.
Test: manual. Both trust and no-trust still work.
Test: manual. In nornal case, log with expected values, see bug for
details. Log expected value for some error cases (not all are tested)
by local changes.

Change-Id: Iaa778616eca4cfad83a94297d9cd6116bb9577e7
parent 54d7eb44

services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java

+144 −18
Original line number Diff line number Diff line
@@ -23,6 +23,25 @@ import static android.service.voice.HotwordDetectionService.AUDIO_SOURCE_MICROPH 
import static android.service.voice.HotwordDetectionService.INITIALIZATION_STATUS_UNKNOWN;

import static android.service.voice.HotwordDetectionService.KEY_INITIALIZATION_STATUS;



import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_ERROR;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_SUCCESS;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_NO_VALUE;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_OVER_MAX_CUSTOM_VALUE;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_TIMEOUT;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_RESTARTED__REASON__AUDIO_SERVICE_DIED;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTION_SERVICE_RESTARTED__REASON__SCHEDULE;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENTS__EVENT__CALLBACK_UPDATE_STATE_AFTER_TIMEOUT;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENTS__EVENT__ON_CONNECTED;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_BIND_SERVICE;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_BIND_SERVICE_FAIL;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_UPDATE_STATE;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__NORMAL_DETECTOR;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__TRUSTED_DETECTOR_DSP;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECTED;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_EXCEPTION;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_TIMEOUT;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__KEYPHRASE_TRIGGER;

import static com.android.internal.util.FrameworkStatsLog.HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__REJECTED;

import static com.android.server.voiceinteraction.SoundTriggerSessionPermissionsDecorator.enforcePermissionForPreflight;



import android.annotation.NonNull;
@@ -92,13 +111,25 @@ final class HotwordDetectionConnection { 
    static final boolean DEBUG = false;



    // TODO: These constants need to be refined.

    private static final long VALIDATION_TIMEOUT_MILLIS = 3000;

    private static final long VALIDATION_TIMEOUT_MILLIS = 4000;

    private static final long MAX_UPDATE_TIMEOUT_MILLIS = 6000;

    private static final Duration MAX_UPDATE_TIMEOUT_DURATION =

            Duration.ofMillis(MAX_UPDATE_TIMEOUT_MILLIS);

    private static final long RESET_DEBUG_HOTWORD_LOGGING_TIMEOUT_MILLIS = 60 * 60 * 1000; // 1 hour

    private static final int MAX_ISOLATED_PROCESS_NUMBER = 10;



    // Hotword metrics

    private static final int METRICS_INIT_UNKNOWN_TIMEOUT =

            HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_TIMEOUT;

    private static final int METRICS_INIT_UNKNOWN_NO_VALUE =

            HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_NO_VALUE;

    private static final int METRICS_INIT_UNKNOWN_OVER_MAX_CUSTOM_VALUE =

            HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_UNKNOWN_OVER_MAX_CUSTOM_VALUE;

    private static final int METRICS_INIT_CALLBACK_STATE_ERROR =

            HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_ERROR;

    private static final int METRICS_INIT_CALLBACK_STATE_SUCCESS =

            HOTWORD_DETECTION_SERVICE_INIT_RESULT_REPORTED__RESULT__CALLBACK_INIT_STATE_SUCCESS;



    private final Executor mAudioCopyExecutor = Executors.newCachedThreadPool();

    // TODO: This may need to be a Handler(looper)

    private final ScheduledExecutorService mScheduledExecutorService =
@@ -107,17 +138,20 @@ final class HotwordDetectionConnection { 
    private final IBinder.DeathRecipient mAudioServerDeathRecipient = this::audioServerDied;

    private final @NonNull ServiceConnectionFactory mServiceConnectionFactory;

    private final IHotwordRecognitionStatusCallback mCallback;

    private final int mDetectorType;



    final Object mLock;

    final int mVoiceInteractionServiceUid;

    final ComponentName mDetectionComponentName;

    final int mUser;

    final Context mContext;



    volatile HotwordDetectionServiceIdentity mIdentity;

    private IMicrophoneHotwordDetectionVoiceInteractionCallback mSoftwareCallback;

    private Instant mLastRestartInstant;



    private ScheduledFuture<?> mCancellationTaskFuture;

    private ScheduledFuture<?> mCancellationKeyPhraseDetectionFuture;

    private ScheduledFuture<?> mDebugHotwordLoggingTimeoutFuture = null;



    /** Identity used for attributing app ops when delivering data to the Interactor. */
@@ -133,7 +167,6 @@ final class HotwordDetectionConnection { 
    private @NonNull ServiceConnection mRemoteHotwordDetectionService;

    private IBinder mAudioFlinger;

    private boolean mDebugHotwordLogging = false;

    private final int mDetectorType;



    HotwordDetectionConnection(Object lock, Context context, int voiceInteractionServiceUid,

            Identity voiceInteractorIdentity, ComponentName serviceName, int userId,
@@ -169,6 +202,8 @@ final class HotwordDetectionConnection { 
            Slog.v(TAG, "Time to restart the process, TTL has passed");

            synchronized (mLock) {

                restartProcessLocked();

                HotwordMetricsLogger.writeServiceRestartEvent(mDetectorType,

                        HOTWORD_DETECTION_SERVICE_RESTARTED__REASON__SCHEDULE);

            }

        }, 30, 30, TimeUnit.MINUTES);

    }
@@ -201,6 +236,8 @@ final class HotwordDetectionConnection { 
            // We restart the process instead of simply sending over the new binder, to avoid race

            // conditions with audio reading in the service.

            restartProcessLocked();

            HotwordMetricsLogger.writeServiceRestartEvent(mDetectorType,

                    HOTWORD_DETECTION_SERVICE_RESTARTED__REASON__AUDIO_SERVICE_DIED);

        }

    }
@@ -220,26 +257,32 @@ final class HotwordDetectionConnection { 
                    future.complete(null);

                    if (mUpdateStateAfterStartFinished.getAndSet(true)) {

                        Slog.w(TAG, "call callback after timeout");

                        HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                                HOTWORD_DETECTOR_EVENTS__EVENT__CALLBACK_UPDATE_STATE_AFTER_TIMEOUT,

                                mVoiceInteractionServiceUid);

                        return;

                    }

                    int status = bundle != null ? bundle.getInt(

                            KEY_INITIALIZATION_STATUS,

                            INITIALIZATION_STATUS_UNKNOWN)

                            : INITIALIZATION_STATUS_UNKNOWN;

                    // Add the protection to avoid unexpected status

                    if (status > HotwordDetectionService.getMaxCustomInitializationStatus()

                            && status != INITIALIZATION_STATUS_UNKNOWN) {

                        status = INITIALIZATION_STATUS_UNKNOWN;

                    }

                    Pair<Integer, Integer> statusResultPair = getInitStatusAndMetricsResult(bundle);

                    int status = statusResultPair.first;

                    int initResultMetricsResult = statusResultPair.second;

                    try {

                        mCallback.onStatusReported(status);

                        HotwordMetricsLogger.writeServiceInitResultEvent(mDetectorType,

                                initResultMetricsResult);

                    } catch (RemoteException e) {

                        // TODO: Add a new atom for RemoteException case, the error doesn't very

                        // correct here

                        Slog.w(TAG, "Failed to report initialization status: " + e);

                        HotwordMetricsLogger.writeServiceInitResultEvent(mDetectorType,

                                METRICS_INIT_CALLBACK_STATE_ERROR);

                    }

                }

            };

            try {

                service.updateState(options, sharedMemory, statusCallback);

                HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                        HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_UPDATE_STATE,

                        mVoiceInteractionServiceUid);

            } catch (RemoteException e) {

                // TODO: (b/181842909) Report an error to voice interactor

                Slog.w(TAG, "Failed to updateState for HotwordDetectionService", e);
@@ -254,8 +297,12 @@ final class HotwordDetectionConnection { 
                        }

                        try {

                            mCallback.onStatusReported(INITIALIZATION_STATUS_UNKNOWN);

                            HotwordMetricsLogger.writeServiceInitResultEvent(mDetectorType,

                                    METRICS_INIT_UNKNOWN_TIMEOUT);

                        } catch (RemoteException e) {

                            Slog.w(TAG, "Failed to report initialization status UNKNOWN", e);

                            HotwordMetricsLogger.writeServiceInitResultEvent(mDetectorType,

                                    METRICS_INIT_CALLBACK_STATE_ERROR);

                        }

                    } else if (err != null) {

                        Slog.w(TAG, "Failed to update state: " + err);
@@ -265,6 +312,23 @@ final class HotwordDetectionConnection { 
                });

    }



    private static Pair<Integer, Integer> getInitStatusAndMetricsResult(Bundle bundle) {

        if (bundle == null) {

            return new Pair<>(INITIALIZATION_STATUS_UNKNOWN, METRICS_INIT_UNKNOWN_NO_VALUE);

        }

        int status = bundle.getInt(KEY_INITIALIZATION_STATUS, INITIALIZATION_STATUS_UNKNOWN);

        if (status > HotwordDetectionService.getMaxCustomInitializationStatus()

                && status != INITIALIZATION_STATUS_UNKNOWN) {

            return new Pair<>(INITIALIZATION_STATUS_UNKNOWN,

                    METRICS_INIT_UNKNOWN_OVER_MAX_CUSTOM_VALUE);

        }

        // TODO: should guard against negative here

        int metricsResult = status == INITIALIZATION_STATUS_UNKNOWN

                ? METRICS_INIT_CALLBACK_STATE_ERROR

                : METRICS_INIT_CALLBACK_STATE_SUCCESS;

        return new Pair<>(status, metricsResult);

    }



    private boolean isBound() {

        synchronized (mLock) {

            return mRemoteHotwordDetectionService.isBound();
@@ -481,12 +545,31 @@ final class HotwordDetectionConnection { 
                    Slog.d(TAG, "onDetected");

                }

                synchronized (mLock) {

                    // TODO: If the dsp trigger comes in after the timeout, we will log both events.

                    // Because we don't enforce the timeout yet. We should add some synchronizations

                    // within the runnable to prevent the race condition to log both events.

                    if (mCancellationKeyPhraseDetectionFuture != null) {

                        mCancellationKeyPhraseDetectionFuture.cancel(true);

                    }

                    HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                            mDetectorType,

                            HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECTED);

                    if (!mValidatingDspTrigger) {

                        Slog.i(TAG, "Ignoring #onDetected due to a process restart");

                        HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                                mDetectorType,

                                HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_EXCEPTION);

                        return;

                    }

                    mValidatingDspTrigger = false;

                    try {

                        enforcePermissionsForDataDelivery();

                    } catch (SecurityException e) {

                        HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                                mDetectorType,

                                HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_EXCEPTION);

                        throw e;

                    }

                    externalCallback.onKeyphraseDetected(recognitionEvent, result);

                    if (result != null) {

                        Slog.i(TAG, "Egressed " + HotwordDetectedResult.getUsageSize(result)
@@ -504,8 +587,17 @@ final class HotwordDetectionConnection { 
                    Slog.d(TAG, "onRejected");

                }

                synchronized (mLock) {

                    if (mCancellationKeyPhraseDetectionFuture != null) {

                        mCancellationKeyPhraseDetectionFuture.cancel(true);

                    }

                    HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                            mDetectorType,

                            HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__REJECTED);

                    if (!mValidatingDspTrigger) {

                        Slog.i(TAG, "Ignoring #onRejected due to a process restart");

                        HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                                mDetectorType,

                                HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_EXCEPTION);

                        return;

                    }

                    mValidatingDspTrigger = false;
@@ -520,11 +612,20 @@ final class HotwordDetectionConnection { 
        synchronized (mLock) {

            mValidatingDspTrigger = true;

            mRemoteHotwordDetectionService.run(

                    service -> service.detectFromDspSource(

                    service -> {

                        // TODO: avoid allocate every time

                        mCancellationKeyPhraseDetectionFuture = mScheduledExecutorService.schedule(

                                () -> HotwordMetricsLogger

                                        .writeKeyphraseTriggerEvent(mDetectorType,

                                        HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__DETECT_TIMEOUT),

                                VALIDATION_TIMEOUT_MILLIS,

                                TimeUnit.MILLISECONDS);

                        service.detectFromDspSource(

                                recognitionEvent,

                                recognitionEvent.getCaptureFormat(),

                                VALIDATION_TIMEOUT_MILLIS,

                            internalCallback));

                                internalCallback);

                    });

        }

    }
@@ -625,10 +726,16 @@ final class HotwordDetectionConnection { 
            }

            final boolean useHotwordDetectionService = mHotwordDetectionConnection != null;

            if (useHotwordDetectionService) {

                HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                        HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__TRUSTED_DETECTOR_DSP,

                        HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__KEYPHRASE_TRIGGER);

                mRecognitionEvent = recognitionEvent;

                mHotwordDetectionConnection.detectFromDspSource(

                        recognitionEvent, mExternalCallback);

            } else {

                HotwordMetricsLogger.writeKeyphraseTriggerEvent(

                        HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__DETECTOR_TYPE__NORMAL_DETECTOR,

                        HOTWORD_DETECTOR_KEYPHRASE_TRIGGERED__RESULT__KEYPHRASE_TRIGGER);

                mExternalCallback.onKeyphraseDetected(recognitionEvent, null);

            }

        }
@@ -793,6 +900,7 @@ final class HotwordDetectionConnection { 


        private boolean mRespectServiceConnectionStatusChanged = true;

        private boolean mIsBound = false;

        private boolean mIsLoggedFirstConnect = false;



        ServiceConnection(@NonNull Context context,

                @NonNull Intent intent, int bindingFlags, int userId,
@@ -816,6 +924,12 @@ final class HotwordDetectionConnection { 
                    return;

                }

                mIsBound = connected;

                if (connected && !mIsLoggedFirstConnect) {

                    mIsLoggedFirstConnect = true;

                    HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                            HOTWORD_DETECTOR_EVENTS__EVENT__ON_CONNECTED,

                            mVoiceInteractionServiceUid);

                }

            }

        }
@@ -846,13 +960,25 @@ final class HotwordDetectionConnection { 
        protected boolean bindService(

                @NonNull android.content.ServiceConnection serviceConnection) {

            try {

                return mContext.bindIsolatedService(

                HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                        HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_BIND_SERVICE,

                        mVoiceInteractionServiceUid);

                boolean bindResult = mContext.bindIsolatedService(

                        mIntent,

                        Context.BIND_AUTO_CREATE | Context.BIND_FOREGROUND_SERVICE | mBindingFlags,

                        "hotword_detector_" + mInstanceNumber,

                        mExecutor,

                        serviceConnection);

                if (!bindResult) {

                    HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                            HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_BIND_SERVICE_FAIL,

                            mVoiceInteractionServiceUid);

                }

                return bindResult;

            } catch (IllegalArgumentException e) {

                HotwordMetricsLogger.writeDetectorEvent(mDetectorType,

                        HOTWORD_DETECTOR_EVENTS__EVENT__REQUEST_BIND_SERVICE_FAIL,

                        mVoiceInteractionServiceUid);

                Slog.wtf(TAG, "Can't bind to the hotword detection service!", e);

                return false;

            }

services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordMetricsLogger.java

+91 −6

File changed.

Preview size limit exceeded, changes collapsed.

services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java

+24 −0
Original line number Diff line number Diff line
@@ -462,24 +462,33 @@ class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConne 
            IHotwordRecognitionStatusCallback callback,

            int detectorType) {

        Slog.v(TAG, "updateStateLocked");

        int voiceInteractionServiceUid = mInfo.getServiceInfo().applicationInfo.uid;

        if (mHotwordDetectionComponentName == null) {

            Slog.w(TAG, "Hotword detection service name not found");

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new IllegalStateException("Hotword detection service name not found");

        }

        ServiceInfo hotwordDetectionServiceInfo = getServiceInfoLocked(

                mHotwordDetectionComponentName, mUser);

        if (hotwordDetectionServiceInfo == null) {

            Slog.w(TAG, "Hotword detection service info not found");

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new IllegalStateException("Hotword detection service info not found");

        }

        if (!isIsolatedProcessLocked(hotwordDetectionServiceInfo)) {

            Slog.w(TAG, "Hotword detection service not in isolated process");

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new IllegalStateException("Hotword detection service not in isolated process");

        }

        if (!Manifest.permission.BIND_HOTWORD_DETECTION_SERVICE.equals(

                hotwordDetectionServiceInfo.permission)) {

            Slog.w(TAG, "Hotword detection service does not require permission "

                    + Manifest.permission.BIND_HOTWORD_DETECTION_SERVICE);

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new SecurityException("Hotword detection service does not require permission "

                    + Manifest.permission.BIND_HOTWORD_DETECTION_SERVICE);

        }
@@ -488,17 +497,23 @@ class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConne 
                mInfo.getServiceInfo().packageName) == PackageManager.PERMISSION_GRANTED) {

            Slog.w(TAG, "Voice interaction service should not hold permission "

                    + Manifest.permission.BIND_HOTWORD_DETECTION_SERVICE);

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new SecurityException("Voice interaction service should not hold permission "

                    + Manifest.permission.BIND_HOTWORD_DETECTION_SERVICE);

        }



        if (sharedMemory != null && !sharedMemory.setProtect(OsConstants.PROT_READ)) {

            Slog.w(TAG, "Can't set sharedMemory to be read-only");

            logDetectorCreateEventIfNeeded(callback, detectorType, false,

                    voiceInteractionServiceUid);

            throw new IllegalStateException("Can't set sharedMemory to be read-only");

        }



        mDetectorType = detectorType;



        logDetectorCreateEventIfNeeded(callback, detectorType, true,

                voiceInteractionServiceUid);

        if (mHotwordDetectionConnection == null) {

            mHotwordDetectionConnection = new HotwordDetectionConnection(mServiceStub, mContext,

                    mInfo.getServiceInfo().applicationInfo.uid, voiceInteractorIdentity,
@@ -509,6 +524,15 @@ class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConne 
        }

    }



    private void logDetectorCreateEventIfNeeded(IHotwordRecognitionStatusCallback callback,

            int detectorType, boolean isCreated, int voiceInteractionServiceUid) {

        if (callback != null) {

            HotwordMetricsLogger.writeDetectorCreateEvent(detectorType, true,

                    voiceInteractionServiceUid);

        }



    }



    public void shutdownHotwordDetectionServiceLocked() {

        if (DEBUG) {

            Slog.d(TAG, "shutdownHotwordDetectionServiceLocked");