Log the amount of time between authentication and error

Fixes: 135705310

Test: Checked logs
Change-Id: I1d9b26befc30f233052504c7c74b17ea0a3d5671

cmds/statsd/src/atoms.proto

@@ -3282,6 +3282,8 @@ message BiometricErrorOccurred {
     optional int32 error_info_vendor = 7;
     // Dictates if this message should trigger additional debugging.
     optional bool debug = 8;
+    // Time spent during the authentication attempt.
+    optional int64 latency_millis = 9;
 }
 
 /**

services/core/java/com/android/server/biometrics/BiometricService.java

@@ -170,6 +170,8 @@ public class BiometricService extends SystemService {
         // the authentication.
         byte[] mTokenEscrow;
 
+        // Timestamp when authentication started
+        private long mStartTimeMs;
         // Timestamp when hardware authentication occurred
         private long mAuthenticatedTimeMs;
 
@@ -1076,6 +1078,9 @@ public class BiometricService extends SystemService {
                     latency,
                     Utils.isDebugEnabled(getContext(), mCurrentAuthSession.mUserId));
         } else {
+
+            final long latency = System.currentTimeMillis() - mCurrentAuthSession.mStartTimeMs;
+
             int error = reason == BiometricPrompt.DISMISSED_REASON_NEGATIVE
                     ? BiometricConstants.BIOMETRIC_ERROR_NEGATIVE_BUTTON
                     : reason == BiometricPrompt.DISMISSED_REASON_USER_CANCEL
@@ -1087,7 +1092,8 @@ public class BiometricService extends SystemService {
                         + ", IsCrypto: " + mCurrentAuthSession.isCrypto()
                         + ", Action: " + BiometricsProtoEnums.ACTION_AUTHENTICATE
                         + ", Client: " + BiometricsProtoEnums.CLIENT_BIOMETRIC_PROMPT
-                        + ", Error: " + error);
+                        + ", Error: " + error
+                        + ", Latency: " + latency);
             }
             // Auth canceled
             StatsLog.write(StatsLog.BIOMETRIC_ERROR_OCCURRED,
@@ -1098,7 +1104,8 @@ public class BiometricService extends SystemService {
                     BiometricsProtoEnums.CLIENT_BIOMETRIC_PROMPT,
                     error,
                     0 /* vendorCode */,
-                    Utils.isDebugEnabled(getContext(), mCurrentAuthSession.mUserId));
+                    Utils.isDebugEnabled(getContext(), mCurrentAuthSession.mUserId),
+                    latency);
         }
     }
 
@@ -1422,6 +1429,9 @@ public class BiometricService extends SystemService {
                     && mCurrentAuthSession.mState == STATE_AUTH_PAUSED;
 
             mCurrentAuthSession = mPendingAuthSession;
+
+            // Time starts when lower layers are ready to start the client.
+            mCurrentAuthSession.mStartTimeMs = System.currentTimeMillis();
             mPendingAuthSession = null;
 
             mCurrentAuthSession.mState = STATE_AUTH_STARTED;

services/core/java/com/android/server/biometrics/LoggableMonitor.java

@@ -94,6 +94,10 @@ public abstract class LoggableMonitor {
     }
 
     protected final void logOnError(Context context, int error, int vendorCode, int targetUserId) {
+
+        final long latency = mFirstAcquireTimeMs != 0
+                ? (System.currentTimeMillis() - mFirstAcquireTimeMs) : -1;
+
         if (DEBUG) {
             Slog.v(TAG, "Error! Modality: " + statsModality()
                     + ", User: " + targetUserId
@@ -101,7 +105,10 @@ public abstract class LoggableMonitor {
                     + ", Action: " + statsAction()
                     + ", Client: " + statsClient()
                     + ", Error: " + error
-                    + ", VendorCode: " + vendorCode);
+                    + ", VendorCode: " + vendorCode
+                    + ", Latency: " + latency);
+        } else {
+            Slog.v(TAG, "Error latency: " + latency);
         }
         StatsLog.write(StatsLog.BIOMETRIC_ERROR_OCCURRED,
                 statsModality(),
@@ -111,7 +118,8 @@ public abstract class LoggableMonitor {
                 statsClient(),
                 error,
                 vendorCode,
-                Utils.isDebugEnabled(context, targetUserId));
+                Utils.isDebugEnabled(context, targetUserId),
+                latency);
     }
 
     protected final void logOnAuthenticated(Context context, boolean authenticated,