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

Commit 0f01549d authored by Joe Bolinger's avatar Joe Bolinger
Browse files

Add timeout to all ALS logging. 

There are cases where the logger is not being disabled at the end of an operation, possibly due to a scheduler lifecycle bug. The timeout is a safeguard to ensure disable is always called after ALS logging is enabled.

Fix: 233656407
Test: atest BiometricLoggerTest ALSProbeTest
Test: manual (auth on lock scren & verify logs)
Test: manual (kill hal and verify watch dog: adb shell ps | grep biometrics.face-service | awk '{print $2}' | xargs adb shell kill -9)

Change-Id: I27ee27a046ed97912ec4b675feecf882f550a0a2
parent 638d4593

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

0 → 100644
+163 −0
Original line number Diff line number Diff line 
/*

 * 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.DurationMillisLong;

import android.annotation.NonNull;

import android.annotation.Nullable;

import android.hardware.Sensor;

import android.hardware.SensorEvent;

import android.hardware.SensorEventListener;

import android.hardware.SensorManager;

import android.os.Handler;

import android.os.Looper;

import android.util.Slog;



import com.android.internal.annotations.VisibleForTesting;

import com.android.server.biometrics.sensors.BaseClientMonitor;



import java.util.concurrent.TimeUnit;



/** Probe for ambient light. */

final class ALSProbe implements Probe {

    private static final String TAG = "ALSProbe";



    @Nullable

    private final SensorManager mSensorManager;

    @Nullable

    private final Sensor mLightSensor;

    @NonNull

    private final Handler mTimer;

    @DurationMillisLong

    private long mMaxSubscriptionTime = -1;



    private boolean mEnabled = false;

    private boolean mDestroyed = false;

    private volatile float mLastAmbientLux = -1;



    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.

        }

    };



    /**

     * Create a probe with a 1-minute max sampling time.

     *

     * @param sensorManager Sensor manager

     */

    ALSProbe(@NonNull SensorManager sensorManager) {

        this(sensorManager, new Handler(Looper.getMainLooper()),

                TimeUnit.MINUTES.toMillis(1));

    }



    /**

     * Create a probe with a given max sampling time.

     *

     * Note: The max time is a workaround for potential scheduler bugs where

     * {@link BaseClientMonitor#destroy()} is not called due to an abnormal lifecycle. Clients

     * should ensure that {@link #disable()} and {@link #destroy()} are called appropriately and

     * avoid relying on this timeout to unsubscribe from the sensor when it is not needed.

     *

     * @param sensorManager Sensor manager

     * @param handler Timeout handler

     * @param maxTime The max amount of time to subscribe to events. If this time is exceeded

     *                {@link #disable()} will be called and no sampling will occur until {@link

     *                #enable()} is called again.

     */

    @VisibleForTesting

    ALSProbe(@Nullable SensorManager sensorManager, @NonNull Handler handler,

            @DurationMillisLong long maxTime) {

        mSensorManager = sensorManager;

        mLightSensor = sensorManager != null

                ? sensorManager.getDefaultSensor(Sensor.TYPE_LIGHT) : null;

        mTimer = handler;

        mMaxSubscriptionTime = maxTime;



        if (mSensorManager == null || mLightSensor == null) {

            Slog.w(TAG, "No sensor - probe disabled");

            mDestroyed = true;

        }

    }



    @Override

    public synchronized void enable() {

        if (!mDestroyed) {

            enableLightSensorLoggingLocked();

        }

    }



    @Override

    public synchronized void disable() {

        if (!mDestroyed) {

            disableLightSensorLoggingLocked();

        }

    }



    @Override

    public synchronized void destroy() {

        disable();

        mDestroyed = true;

    }



    /** The most recent lux reading. */

    public float getCurrentLux() {

        return mLastAmbientLux;

    }



    private void enableLightSensorLoggingLocked() {

        if (!mEnabled) {

            mEnabled = true;

            mLastAmbientLux = -1;

            mSensorManager.registerListener(mLightSensorListener, mLightSensor,

                    SensorManager.SENSOR_DELAY_NORMAL);

            Slog.v(TAG, "Enable ALS: " + mLightSensorListener.hashCode());

        }



        resetTimerLocked(true /* start */);

    }



    private void disableLightSensorLoggingLocked() {

        resetTimerLocked(false /* start */);



        if (mEnabled) {

            mEnabled = false;

            mLastAmbientLux = -1;

            mSensorManager.unregisterListener(mLightSensorListener);

            Slog.v(TAG, "Disable ALS: " + mLightSensorListener.hashCode());

        }

    }



    private void resetTimerLocked(boolean start) {

        mTimer.removeCallbacksAndMessages(this /* token */);

        if (start && mMaxSubscriptionTime > 0) {

            mTimer.postDelayed(this::onTimeout, this /* token */, mMaxSubscriptionTime);

        }

    }



    private void onTimeout() {

        Slog.e(TAG, "Max time exceeded for ALS logger - disabling: "

                + mLightSensorListener.hashCode());

        disable();

    }

}

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

+17 −106
Original line number Diff line number Diff line
@@ -17,21 +17,15 @@ 
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;
@@ -43,61 +37,16 @@ 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;

    @NonNull private final ALSProbe mALSProbe;



    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,
@@ -105,6 +54,11 @@ public class BiometricLogger { 
    }



    /**

     * Creates a new logger for an instance of a biometric operation.

     *

     * Do not reuse across operations. Instead, create a new one or use

     * {@link #swapAction(Context, int)}.

     *

     * @param context system_server context

     * @param statsModality One of {@link BiometricsProtoEnums} MODALITY_* constants.

     * @param statsAction One of {@link BiometricsProtoEnums} ACTION_* constants.
@@ -125,7 +79,7 @@ public class BiometricLogger { 
        mStatsAction = statsAction;

        mStatsClient = statsClient;

        mSink = logSink;

        mSensorManager = sensorManager;

        mALSProbe = new ALSProbe(sensorManager);

    }



    /** Creates a new logger with the action replaced with the new action. */
@@ -136,6 +90,7 @@ public class BiometricLogger { 
    /** Disable logging metrics and only log critical events, such as system health issues. */

    public void disableMetrics() {

        mShouldLogMetrics = false;

        mALSProbe.destroy();

    }



    /** {@link BiometricsProtoEnums} CLIENT_* constants */
@@ -265,7 +220,7 @@ public class BiometricLogger { 
                    + ", RequireConfirmation: " + requireConfirmation

                    + ", State: " + authState

                    + ", Latency: " + latency

                    + ", Lux: " + mLastAmbientLux);

                    + ", Lux: " + mALSProbe.getCurrentLux());

        } else {

            Slog.v(TAG, "Authentication latency: " + latency);

        }
@@ -276,7 +231,7 @@ public class BiometricLogger { 


        mSink.authenticate(operationContext, mStatsModality, mStatsAction, mStatsClient,

                Utils.isDebugEnabled(context, targetUserId),

                latency, authState, requireConfirmation, targetUserId, mLastAmbientLux);

                latency, authState, requireConfirmation, targetUserId, mALSProbe.getCurrentLux());

    }



    /** Log enrollment outcome. */
@@ -290,7 +245,7 @@ public class BiometricLogger { 
                    + ", User: " + targetUserId

                    + ", Client: " + mStatsClient

                    + ", Latency: " + latency

                    + ", Lux: " + mLastAmbientLux

                    + ", Lux: " + mALSProbe.getCurrentLux()

                    + ", Success: " + enrollSuccessful);

        } else {

            Slog.v(TAG, "Enroll latency: " + latency);
@@ -301,7 +256,7 @@ public class BiometricLogger { 
        }



        mSink.enroll(mStatsModality, mStatsAction, mStatsClient,

                targetUserId, latency, enrollSuccessful, mLastAmbientLux);

                targetUserId, latency, enrollSuccessful, mALSProbe.getCurrentLux());

    }



    /** Report unexpected enrollment reported by the HAL. */
@@ -323,7 +278,9 @@ public class BiometricLogger { 
    }



    /**

     * Get a callback to start/stop ALS capture when a client runs.

     * Get a callback to start/stop ALS capture when the client runs. Do not create

     * multiple callbacks since there is at most one light sensor (they will all share

     * a single probe sampling from that sensor).

     *

     * If the probe should not run for the entire operation, do not set startWithClient and

     * start/stop the problem when needed.
@@ -331,53 +288,7 @@ public class BiometricLogger { 
     * @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()));

            }

        }

    public CallbackWithProbe<Probe> getAmbientLightProbe(boolean startWithClient) {

        return new CallbackWithProbe<>(mALSProbe, startWithClient);

    }

}

services/core/java/com/android/server/biometrics/sensors/face/aidl/FaceAuthenticationClient.java

+1 −1
Original line number Diff line number Diff line
@@ -131,7 +131,7 @@ class FaceAuthenticationClient extends AuthenticationClient<AidlSession> 
    @Override

    protected ClientMonitorCallback wrapCallbackForStart(@NonNull ClientMonitorCallback callback) {

        return new ClientMonitorCompositeCallback(

                getLogger().createALSCallback(true /* startWithClient */), callback);

                getLogger().getAmbientLightProbe(true /* startWithClient */), callback);

    }



    @Override

services/core/java/com/android/server/biometrics/sensors/face/aidl/FaceEnrollClient.java

+1 −1
Original line number Diff line number Diff line
@@ -115,7 +115,7 @@ public class FaceEnrollClient extends EnrollClient<AidlSession> { 
    @Override

    protected ClientMonitorCallback wrapCallbackForStart(@NonNull ClientMonitorCallback callback) {

        return new ClientMonitorCompositeCallback(mPreviewHandleDeleterCallback,

                getLogger().createALSCallback(true /* startWithClient */), callback);

                getLogger().getAmbientLightProbe(true /* startWithClient */), callback);

    }



    @Override

services/core/java/com/android/server/biometrics/sensors/face/hidl/FaceAuthenticationClient.java

+1 −1
Original line number Diff line number Diff line
@@ -101,7 +101,7 @@ class FaceAuthenticationClient extends AuthenticationClient<IBiometricsFace> { 
    @Override

    protected ClientMonitorCallback wrapCallbackForStart(@NonNull ClientMonitorCallback callback) {

        return new ClientMonitorCompositeCallback(

                getLogger().createALSCallback(true /* startWithClient */), callback);

                getLogger().getAmbientLightProbe(true /* startWithClient */), callback);

    }



    @Override