Log the amount of time between authentication and error
Fixes: 135705310
Test: Checked logs
Change-Id: I1d9b26befc30f233052504c7c74b17ea0a3d5671
diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto
index 8c94e29..8d90185 100644
--- a/cmds/statsd/src/atoms.proto
+++ b/cmds/statsd/src/atoms.proto
@@ -3282,6 +3282,8 @@
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 a09fdd2..df6f73b 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 @@
// the authentication.
byte[] mTokenEscrow;
+ // Timestamp when authentication started
+ private long mStartTimeMs;
// Timestamp when hardware authentication occurred
private long mAuthenticatedTimeMs;
@@ -1076,6 +1078,9 @@
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 @@
+ ", 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 @@
BiometricsProtoEnums.CLIENT_BIOMETRIC_PROMPT,
error,
0 /* vendorCode */,
- Utils.isDebugEnabled(getContext(), mCurrentAuthSession.mUserId));
+ Utils.isDebugEnabled(getContext(), mCurrentAuthSession.mUserId),
+ latency);
}
}
@@ -1422,6 +1429,9 @@
&& 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 9c04088..9e1d519 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 @@
}
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 @@
+ ", 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 @@
statsClient(),
error,
vendorCode,
- Utils.isDebugEnabled(context, targetUserId));
+ Utils.isDebugEnabled(context, targetUserId),
+ latency);
}
protected final void logOnAuthenticated(Context context, boolean authenticated,