services/core/java/com/android/server/biometrics/log/BiometricLogger.java

/*
 * Copyright (C) 2022 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.biometrics.log;

import android.annotation.NonNull;
import android.annotation.Nullable;
import android.content.Context;
import android.hardware.Sensor;
import android.hardware.SensorEvent;
import android.hardware.SensorEventListener;
import android.hardware.SensorManager;
import android.hardware.biometrics.BiometricConstants;
import android.hardware.biometrics.BiometricsProtoEnums;
import android.hardware.biometrics.common.OperationContext;
import android.hardware.face.FaceManager;
import android.hardware.fingerprint.FingerprintManager;
import android.util.Log;
import android.util.Slog;

import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.util.FrameworkStatsLog;
import com.android.server.biometrics.Utils;

/**
 * Logger for all reported Biometric framework events.
 */
public class BiometricLogger {

    public static final String TAG = "BiometricLogger";
    public static final boolean DEBUG = false;
    private static final Object sLock = new Object();

    @GuardedBy("sLock")
    private static int sAlsCounter;

    private final int mStatsModality;
    private final int mStatsAction;
    private final int mStatsClient;
    private final BiometricFrameworkStatsLogger mSink;
    @NonNull private final SensorManager mSensorManager;

    private long mFirstAcquireTimeMs;
    private boolean mLightSensorEnabled = false;
    private boolean mShouldLogMetrics = true;

    private class ALSProbe implements Probe {
        private boolean mDestroyed = false;

        @Override
        public synchronized void enable() {
            if (!mDestroyed) {
                setLightSensorLoggingEnabled(getAmbientLightSensor(mSensorManager));
            }
        }

        @Override
        public synchronized void disable() {
            if (!mDestroyed) {
                setLightSensorLoggingEnabled(null);
            }
        }

        @Override
        public synchronized void destroy() {
            disable();
            mDestroyed = true;
        }
    }

    // report only the most recent value
    // consider com.android.server.display.utils.AmbientFilter or similar if need arises
    private volatile float mLastAmbientLux = 0;

    private final SensorEventListener mLightSensorListener = new SensorEventListener() {
        @Override
        public void onSensorChanged(SensorEvent event) {
            mLastAmbientLux = event.values[0];
        }

        @Override
        public void onAccuracyChanged(Sensor sensor, int accuracy) {
            // Not used.
        }
    };

    /** Get a new logger with all unknown fields (for operations that do not require logs). */
    public static BiometricLogger ofUnknown(@NonNull Context context) {
        return new BiometricLogger(context, BiometricsProtoEnums.MODALITY_UNKNOWN,
                BiometricsProtoEnums.ACTION_UNKNOWN, BiometricsProtoEnums.CLIENT_UNKNOWN);
    }

    /**
     * @param context system_server context
     * @param statsModality One of {@link BiometricsProtoEnums} MODALITY_* constants.
     * @param statsAction One of {@link BiometricsProtoEnums} ACTION_* constants.
     * @param statsClient One of {@link BiometricsProtoEnums} CLIENT_* constants.
     */
    public BiometricLogger(
            @NonNull Context context, int statsModality, int statsAction, int statsClient) {
        this(statsModality, statsAction, statsClient,
                BiometricFrameworkStatsLogger.getInstance(),
                context.getSystemService(SensorManager.class));
    }

    @VisibleForTesting
    BiometricLogger(
            int statsModality, int statsAction, int statsClient,
            BiometricFrameworkStatsLogger logSink, SensorManager sensorManager) {
        mStatsModality = statsModality;
        mStatsAction = statsAction;
        mStatsClient = statsClient;
        mSink = logSink;
        mSensorManager = sensorManager;
    }

    /** Creates a new logger with the action replaced with the new action. */
    public BiometricLogger swapAction(@NonNull Context context, int statsAction) {
        return new BiometricLogger(context, mStatsModality, statsAction, mStatsClient);
    }

    /** Disable logging metrics and only log critical events, such as system health issues. */
    public void disableMetrics() {
        mShouldLogMetrics = false;
    }

    /** {@link BiometricsProtoEnums} CLIENT_* constants */
    public int getStatsClient() {
        return mStatsClient;
    }

    private boolean shouldSkipLogging() {
        boolean shouldSkipLogging = (mStatsModality == BiometricsProtoEnums.MODALITY_UNKNOWN
                || mStatsAction == BiometricsProtoEnums.ACTION_UNKNOWN);

        if (mStatsModality == BiometricsProtoEnums.MODALITY_UNKNOWN) {
            Slog.w(TAG, "Unknown field detected: MODALITY_UNKNOWN, will not report metric");
        }

        if (mStatsAction == BiometricsProtoEnums.ACTION_UNKNOWN) {
            Slog.w(TAG, "Unknown field detected: ACTION_UNKNOWN, will not report metric");
        }

        if (mStatsClient == BiometricsProtoEnums.CLIENT_UNKNOWN) {
            Slog.w(TAG, "Unknown field detected: CLIENT_UNKNOWN");
        }

        return shouldSkipLogging;
    }

    /** Log an acquisition event. */
    public void logOnAcquired(Context context, OperationContext operationContext,
            int acquiredInfo, int vendorCode, int targetUserId) {
        if (!mShouldLogMetrics) {
            return;
        }

        final boolean isFace = mStatsModality == BiometricsProtoEnums.MODALITY_FACE;
        final boolean isFingerprint = mStatsModality == BiometricsProtoEnums.MODALITY_FINGERPRINT;
        if (isFace || isFingerprint) {
            if ((isFingerprint && acquiredInfo == FingerprintManager.FINGERPRINT_ACQUIRED_START)
                    || (isFace && acquiredInfo == FaceManager.FACE_ACQUIRED_START)) {
                mFirstAcquireTimeMs = System.currentTimeMillis();
            }
        } else if (acquiredInfo == BiometricConstants.BIOMETRIC_ACQUIRED_GOOD) {
            if (mFirstAcquireTimeMs == 0) {
                mFirstAcquireTimeMs = System.currentTimeMillis();
            }
        }
        if (DEBUG) {
            Slog.v(TAG, "Acquired! Modality: " + mStatsModality
                    + ", User: " + targetUserId
                    + ", IsCrypto: " + operationContext.isCrypto
                    + ", Action: " + mStatsAction
                    + ", Client: " + mStatsClient
                    + ", AcquiredInfo: " + acquiredInfo
                    + ", VendorCode: " + vendorCode);
        }

        if (shouldSkipLogging()) {
            return;
        }

        mSink.acquired(operationContext, mStatsModality, mStatsAction, mStatsClient,
                Utils.isDebugEnabled(context, targetUserId),
                acquiredInfo, vendorCode, targetUserId);
    }

    /** Log an error during an operation. */
    public void logOnError(Context context, OperationContext operationContext,
            int error, int vendorCode, int targetUserId) {
        if (!mShouldLogMetrics) {
            return;
        }

        final long latency = mFirstAcquireTimeMs != 0
                ? (System.currentTimeMillis() - mFirstAcquireTimeMs) : -1;

        if (DEBUG) {
            Slog.v(TAG, "Error! Modality: " + mStatsModality
                    + ", User: " + targetUserId
                    + ", IsCrypto: " + operationContext.isCrypto
                    + ", Action: " + mStatsAction
                    + ", Client: " + mStatsClient
                    + ", Error: " + error
                    + ", VendorCode: " + vendorCode
                    + ", Latency: " + latency);
        } else {
            Slog.v(TAG, "Error latency: " + latency);
        }

        if (shouldSkipLogging()) {
            return;
        }

        mSink.error(operationContext, mStatsModality, mStatsAction, mStatsClient,
                Utils.isDebugEnabled(context, targetUserId), latency,
                error, vendorCode, targetUserId);
    }

    /** Log authentication attempt. */
    public void logOnAuthenticated(Context context, OperationContext operationContext,
            boolean authenticated, boolean requireConfirmation,
            int targetUserId, boolean isBiometricPrompt) {
        if (!mShouldLogMetrics) {
            return;
        }

        int authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__UNKNOWN;
        if (!authenticated) {
            authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__REJECTED;
        } else {
            // Authenticated
            if (isBiometricPrompt && requireConfirmation) {
                authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__PENDING_CONFIRMATION;
            } else {
                authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__CONFIRMED;
            }
        }

        // Only valid if we have a first acquired time, otherwise set to -1
        final long latency = mFirstAcquireTimeMs != 0
                ? (System.currentTimeMillis() - mFirstAcquireTimeMs)
                : -1;

        if (DEBUG) {
            Slog.v(TAG, "Authenticated! Modality: " + mStatsModality
                    + ", User: " + targetUserId
                    + ", IsCrypto: " + operationContext.isCrypto
                    + ", Client: " + mStatsClient
                    + ", RequireConfirmation: " + requireConfirmation
                    + ", State: " + authState
                    + ", Latency: " + latency
                    + ", Lux: " + mLastAmbientLux);
        } else {
            Slog.v(TAG, "Authentication latency: " + latency);
        }

        if (shouldSkipLogging()) {
            return;
        }

        mSink.authenticate(operationContext, mStatsModality, mStatsAction, mStatsClient,
                Utils.isDebugEnabled(context, targetUserId),
                latency, authState, requireConfirmation, targetUserId, mLastAmbientLux);
    }

    /** Log enrollment outcome. */
    public void logOnEnrolled(int targetUserId, long latency, boolean enrollSuccessful) {
        if (!mShouldLogMetrics) {
            return;
        }

        if (DEBUG) {
            Slog.v(TAG, "Enrolled! Modality: " + mStatsModality
                    + ", User: " + targetUserId
                    + ", Client: " + mStatsClient
                    + ", Latency: " + latency
                    + ", Lux: " + mLastAmbientLux
                    + ", Success: " + enrollSuccessful);
        } else {
            Slog.v(TAG, "Enroll latency: " + latency);
        }

        if (shouldSkipLogging()) {
            return;
        }

        mSink.enroll(mStatsModality, mStatsAction, mStatsClient,
                targetUserId, latency, enrollSuccessful, mLastAmbientLux);
    }

    /** Report unexpected enrollment reported by the HAL. */
    public void logUnknownEnrollmentInHal() {
        if (shouldSkipLogging()) {
            return;
        }

        mSink.reportUnknownTemplateEnrolledHal(mStatsModality);
    }

    /** Report unknown enrollment in framework settings */
    public void logUnknownEnrollmentInFramework() {
        if (shouldSkipLogging()) {
            return;
        }

        mSink.reportUnknownTemplateEnrolledFramework(mStatsModality);
    }

    /**
     * Get a callback to start/stop ALS capture when a client runs.
     *
     * If the probe should not run for the entire operation, do not set startWithClient and
     * start/stop the problem when needed.
     *
     * @param startWithClient if probe should start automatically when the operation starts.
     */
    @NonNull
    public CallbackWithProbe<Probe> createALSCallback(boolean startWithClient) {
        return new CallbackWithProbe<>(new ALSProbe(), startWithClient);
    }

    /** The sensor to use for ALS logging. */
    @Nullable
    protected Sensor getAmbientLightSensor(@NonNull SensorManager sensorManager) {
        return mShouldLogMetrics ? sensorManager.getDefaultSensor(Sensor.TYPE_LIGHT) : null;
    }

    private void setLightSensorLoggingEnabled(@Nullable Sensor lightSensor) {
        if (DEBUG) {
            Slog.v(TAG, "capturing ambient light using: "
                    + (lightSensor != null ? lightSensor : "[disabled]"));
        }

        if (lightSensor != null) {
            if (!mLightSensorEnabled) {
                mLightSensorEnabled = true;
                mLastAmbientLux = 0;
                int localAlsCounter;
                synchronized (sLock) {
                    localAlsCounter = sAlsCounter++;
                }

                if (localAlsCounter == 0) {
                    mSensorManager.registerListener(mLightSensorListener, lightSensor,
                            SensorManager.SENSOR_DELAY_NORMAL);
                } else {
                    Slog.e(TAG, "Ignoring request to subscribe to ALSProbe due to non-zero ALS"
                            + " counter: " + localAlsCounter);
                    Slog.e(TAG, Log.getStackTraceString(new Throwable()));
                }
            }
        } else {
            mLightSensorEnabled = false;
            mLastAmbientLux = 0;
            mSensorManager.unregisterListener(mLightSensorListener);
            int localAlsCounter;
            synchronized (sLock) {
                localAlsCounter = --sAlsCounter;
            }
            if (localAlsCounter != 0) {
                Slog.e(TAG, "Non-zero ALS counter after unsubscribing from ALSProbe: "
                        + localAlsCounter);
                Slog.e(TAG, Log.getStackTraceString(new Throwable()));
            }
        }
    }
}