1 /*
2  * Copyright (C) 2022 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.server.biometrics.log;
18 
19 import android.annotation.NonNull;
20 import android.content.Context;
21 import android.hardware.SensorManager;
22 import android.hardware.biometrics.BiometricConstants;
23 import android.hardware.biometrics.BiometricsProtoEnums;
24 import android.hardware.face.FaceManager;
25 import android.hardware.fingerprint.FingerprintManager;
26 import android.util.Slog;
27 
28 import com.android.internal.annotations.VisibleForTesting;
29 import com.android.internal.util.FrameworkStatsLog;
30 import com.android.server.biometrics.AuthenticationStatsCollector;
31 import com.android.server.biometrics.Utils;
32 
33 /**
34  * Logger for all reported Biometric framework events.
35  */
36 public class BiometricLogger {
37 
38     public static final String TAG = "BiometricLogger";
39     public static final boolean DEBUG = false;
40 
41     private final int mStatsModality;
42     private final int mStatsAction;
43     private final int mStatsClient;
44     private final BiometricFrameworkStatsLogger mSink;
45     @NonNull private final AuthenticationStatsCollector mAuthenticationStatsCollector;
46     @NonNull private final ALSProbe mALSProbe;
47 
48     private long mFirstAcquireTimeMs;
49     private boolean mShouldLogMetrics = true;
50 
51     /** Get a new logger with all unknown fields (for operations that do not require logs). */
ofUnknown(@onNull Context context)52     public static BiometricLogger ofUnknown(@NonNull Context context) {
53         return new BiometricLogger(context, BiometricsProtoEnums.MODALITY_UNKNOWN,
54                 BiometricsProtoEnums.ACTION_UNKNOWN, BiometricsProtoEnums.CLIENT_UNKNOWN,
55                 null /* AuthenticationStatsCollector */);
56     }
57 
58     /**
59      * Creates a new logger for an instance of a biometric operation.
60      *
61      * Do not reuse across operations. Instead, create a new one or use
62      * {@link #swapAction(Context, int)}.
63      *
64      * @param context system_server context
65      * @param statsModality One of {@link BiometricsProtoEnums} MODALITY_* constants.
66      * @param statsAction One of {@link BiometricsProtoEnums} ACTION_* constants.
67      * @param statsClient One of {@link BiometricsProtoEnums} CLIENT_* constants.
68      */
BiometricLogger( @onNull Context context, int statsModality, int statsAction, int statsClient, AuthenticationStatsCollector authenticationStatsCollector)69     public BiometricLogger(
70             @NonNull Context context, int statsModality, int statsAction, int statsClient,
71             AuthenticationStatsCollector authenticationStatsCollector) {
72         this(statsModality, statsAction, statsClient,
73                 BiometricFrameworkStatsLogger.getInstance(),
74                 authenticationStatsCollector,
75                 context.getSystemService(SensorManager.class));
76     }
77 
78     @VisibleForTesting
BiometricLogger( int statsModality, int statsAction, int statsClient, BiometricFrameworkStatsLogger logSink, @NonNull AuthenticationStatsCollector statsCollector, SensorManager sensorManager)79     BiometricLogger(
80             int statsModality, int statsAction, int statsClient,
81             BiometricFrameworkStatsLogger logSink,
82             @NonNull AuthenticationStatsCollector statsCollector,
83             SensorManager sensorManager) {
84         mStatsModality = statsModality;
85         mStatsAction = statsAction;
86         mStatsClient = statsClient;
87         mSink = logSink;
88         mAuthenticationStatsCollector = statsCollector;
89         mALSProbe = new ALSProbe(sensorManager);
90     }
91 
92     /** Creates a new logger with the action replaced with the new action. */
swapAction(@onNull Context context, int statsAction)93     public BiometricLogger swapAction(@NonNull Context context, int statsAction) {
94         return new BiometricLogger(context, mStatsModality, statsAction, mStatsClient,
95                 null /* AuthenticationStatsCollector */);
96     }
97 
98     /** Disable logging metrics and only log critical events, such as system health issues. */
disableMetrics()99     public void disableMetrics() {
100         mShouldLogMetrics = false;
101         mALSProbe.destroy();
102     }
103 
104     /** {@link BiometricsProtoEnums} CLIENT_* constants */
getStatsClient()105     public int getStatsClient() {
106         return mStatsClient;
107     }
108 
shouldSkipLogging()109     private boolean shouldSkipLogging() {
110         boolean shouldSkipLogging = (mStatsModality == BiometricsProtoEnums.MODALITY_UNKNOWN
111                 || mStatsAction == BiometricsProtoEnums.ACTION_UNKNOWN);
112 
113         if (mStatsModality == BiometricsProtoEnums.MODALITY_UNKNOWN) {
114             Slog.w(TAG, "Unknown field detected: MODALITY_UNKNOWN, will not report metric");
115         }
116 
117         if (mStatsAction == BiometricsProtoEnums.ACTION_UNKNOWN) {
118             Slog.w(TAG, "Unknown field detected: ACTION_UNKNOWN, will not report metric");
119         }
120 
121         if (mStatsClient == BiometricsProtoEnums.CLIENT_UNKNOWN) {
122             Slog.w(TAG, "Unknown field detected: CLIENT_UNKNOWN");
123         }
124 
125         return shouldSkipLogging;
126     }
127 
128     /** Log an acquisition event. */
logOnAcquired(Context context, OperationContextExt operationContext, int acquiredInfo, int vendorCode, int targetUserId)129     public void logOnAcquired(Context context, OperationContextExt operationContext,
130             int acquiredInfo, int vendorCode, int targetUserId) {
131         if (!mShouldLogMetrics) {
132             return;
133         }
134 
135         final boolean isFace = mStatsModality == BiometricsProtoEnums.MODALITY_FACE;
136         final boolean isFingerprint = mStatsModality == BiometricsProtoEnums.MODALITY_FINGERPRINT;
137         if (isFace || isFingerprint) {
138             if ((isFingerprint && acquiredInfo == FingerprintManager.FINGERPRINT_ACQUIRED_START)
139                     || (isFace && acquiredInfo == FaceManager.FACE_ACQUIRED_START)) {
140                 mFirstAcquireTimeMs = System.currentTimeMillis();
141             }
142         } else if (acquiredInfo == BiometricConstants.BIOMETRIC_ACQUIRED_GOOD) {
143             if (mFirstAcquireTimeMs == 0) {
144                 mFirstAcquireTimeMs = System.currentTimeMillis();
145             }
146         }
147         if (DEBUG) {
148             Slog.v(TAG, "Acquired! Modality: " + mStatsModality
149                     + ", User: " + targetUserId
150                     + ", IsCrypto: " + operationContext.isCrypto()
151                     + ", Action: " + mStatsAction
152                     + ", Client: " + mStatsClient
153                     + ", AcquiredInfo: " + acquiredInfo
154                     + ", VendorCode: " + vendorCode);
155         }
156 
157         if (shouldSkipLogging()) {
158             return;
159         }
160 
161         mSink.acquired(operationContext,
162                 mStatsModality, mStatsAction, mStatsClient,
163                 Utils.isDebugEnabled(context, targetUserId),
164                 acquiredInfo, vendorCode, targetUserId);
165     }
166 
167     /** Log an error during an operation. */
logOnError(Context context, OperationContextExt operationContext, int error, int vendorCode, int targetUserId)168     public void logOnError(Context context, OperationContextExt operationContext,
169             int error, int vendorCode, int targetUserId) {
170         if (!mShouldLogMetrics) {
171             return;
172         }
173 
174         final long latency = mFirstAcquireTimeMs != 0
175                 ? (System.currentTimeMillis() - mFirstAcquireTimeMs) : -1;
176 
177         if (DEBUG) {
178             Slog.v(TAG, "Error! Modality: " + mStatsModality
179                     + ", User: " + targetUserId
180                     + ", IsCrypto: " + operationContext.isCrypto()
181                     + ", Action: " + mStatsAction
182                     + ", Client: " + mStatsClient
183                     + ", Error: " + error
184                     + ", VendorCode: " + vendorCode
185                     + ", Latency: " + latency);
186         } else {
187             Slog.v(TAG, "Error latency: " + latency);
188         }
189 
190         if (shouldSkipLogging()) {
191             return;
192         }
193 
194         mSink.error(operationContext,
195                 mStatsModality, mStatsAction, mStatsClient,
196                 Utils.isDebugEnabled(context, targetUserId), latency,
197                 error, vendorCode, targetUserId);
198     }
199 
200     /** Log authentication attempt. */
logOnAuthenticated(Context context, OperationContextExt operationContext, boolean authenticated, boolean requireConfirmation, int targetUserId, boolean isBiometricPrompt)201     public void logOnAuthenticated(Context context, OperationContextExt operationContext,
202             boolean authenticated, boolean requireConfirmation, int targetUserId,
203             boolean isBiometricPrompt) {
204         // Do not log metrics when fingerprint enrollment reason is ENROLL_FIND_SENSOR
205         if (!mShouldLogMetrics) {
206             return;
207         }
208 
209         mAuthenticationStatsCollector.authenticate(targetUserId, authenticated);
210 
211         int authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__UNKNOWN;
212         if (!authenticated) {
213             authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__REJECTED;
214         } else {
215             // Authenticated
216             if (isBiometricPrompt && requireConfirmation) {
217                 authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__PENDING_CONFIRMATION;
218             } else {
219                 authState = FrameworkStatsLog.BIOMETRIC_AUTHENTICATED__STATE__CONFIRMED;
220             }
221         }
222 
223         // Only valid if we have a first acquired time, otherwise set to -1
224         final long latency = mFirstAcquireTimeMs != 0
225                 ? (System.currentTimeMillis() - mFirstAcquireTimeMs)
226                 : -1;
227 
228         if (DEBUG) {
229             Slog.v(TAG, "Authenticated! Modality: " + mStatsModality
230                     + ", User: " + targetUserId
231                     + ", IsCrypto: " + operationContext.isCrypto()
232                     + ", Client: " + mStatsClient
233                     + ", RequireConfirmation: " + requireConfirmation
234                     + ", State: " + authState
235                     + ", Latency: " + latency
236                     + ", Lux: " + mALSProbe.getMostRecentLux());
237         } else {
238             Slog.v(TAG, "Authentication latency: " + latency);
239         }
240 
241         if (shouldSkipLogging()) {
242             return;
243         }
244 
245         mSink.authenticate(operationContext,
246                 mStatsModality, mStatsAction, mStatsClient,
247                 Utils.isDebugEnabled(context, targetUserId),
248                 latency, authState, requireConfirmation, targetUserId, mALSProbe);
249     }
250 
251     /** Log enrollment outcome. */
logOnEnrolled(int targetUserId, long latency, boolean enrollSuccessful)252     public void logOnEnrolled(int targetUserId, long latency, boolean enrollSuccessful) {
253         if (!mShouldLogMetrics) {
254             return;
255         }
256 
257         if (DEBUG) {
258             Slog.v(TAG, "Enrolled! Modality: " + mStatsModality
259                     + ", User: " + targetUserId
260                     + ", Client: " + mStatsClient
261                     + ", Latency: " + latency
262                     + ", Lux: " + mALSProbe.getMostRecentLux()
263                     + ", Success: " + enrollSuccessful);
264         } else {
265             Slog.v(TAG, "Enroll latency: " + latency);
266         }
267 
268         if (shouldSkipLogging()) {
269             return;
270         }
271 
272         mSink.enroll(mStatsModality, mStatsAction, mStatsClient,
273                 targetUserId, latency, enrollSuccessful, mALSProbe.getMostRecentLux());
274     }
275 
276     /** Report unexpected enrollment reported by the HAL. */
logUnknownEnrollmentInHal()277     public void logUnknownEnrollmentInHal() {
278         if (shouldSkipLogging()) {
279             return;
280         }
281 
282         mSink.reportUnknownTemplateEnrolledHal(mStatsModality);
283     }
284 
285     /** Report unknown enrollment in framework settings */
logUnknownEnrollmentInFramework()286     public void logUnknownEnrollmentInFramework() {
287         if (shouldSkipLogging()) {
288             return;
289         }
290 
291         mSink.reportUnknownTemplateEnrolledFramework(mStatsModality);
292     }
293 
294     /**
295      * Get a callback to start/stop ALS capture when the client runs. Do not create
296      * multiple callbacks since there is at most one light sensor (they will all share
297      * a single probe sampling from that sensor).
298      *
299      * If the probe should not run for the entire operation, do not set startWithClient and
300      * start/stop the problem when needed.
301      *
302      * @param startWithClient if probe should start automatically when the operation starts.
303      */
304     @NonNull
getAmbientLightProbe(boolean startWithClient)305     public CallbackWithProbe<Probe> getAmbientLightProbe(boolean startWithClient) {
306         return new CallbackWithProbe<>(mALSProbe, startWithClient);
307     }
308 }
309