From 7fca2368af0c55fc4203186c259ada234d28b475 Mon Sep 17 00:00:00 2001
From: Kevin Chyn <kchyn@google.com>
Date: Thu, 20 Jun 2019 17:20:42 -0700
Subject: [PATCH] Log the amount of time between authentication and error

Fixes: 135705310

Test: Checked logs
Change-Id: I1d9b26befc30f233052504c7c74b17ea0a3d5671
---
 cmds/statsd/src/atoms.proto                        |  2 ++
 .../server/biometrics/BiometricService.java        | 14 ++++++++++++--
 .../android/server/biometrics/LoggableMonitor.java | 12 ++++++++++--
 3 files changed, 24 insertions(+), 4 deletions(-)

diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto
index 8c94e29877c85..8d90185cb1cbd 100644
--- a/cmds/statsd/src/atoms.proto
+++ b/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;
 }
 
 /**
diff --git a/services/core/java/com/android/server/biometrics/BiometricService.java b/services/core/java/com/android/server/biometrics/BiometricService.java
index a09fdd28f475c..df6f73b914a86 100644
--- a/services/core/java/com/android/server/biometrics/BiometricService.java
+++ b/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;
diff --git a/services/core/java/com/android/server/biometrics/LoggableMonitor.java b/services/core/java/com/android/server/biometrics/LoggableMonitor.java
index 9c040884772c1..9e1d5196365b1 100644
--- a/services/core/java/com/android/server/biometrics/LoggableMonitor.java
+++ b/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,