From 9bc1d495ee37754c96de81e36e1b8305eb9f1b56 Mon Sep 17 00:00:00 2001 From: Kevin Chyn Date: Fri, 21 Jun 2019 15:31:50 -0700 Subject: [PATCH] Dump buffer of authentication events for bugreports Last 100 events, plus total accumulated latencies for accept, reject, and individual errors since last boot. Fixes: 134429201 Test: adb shell dumpsys face Change-Id: Idc34143a8e5de1036bb2d82767cf748c15b74822 --- .../biometrics/AuthenticationClient.java | 6 + .../server/biometrics/LoggableMonitor.java | 4 + .../server/biometrics/face/FaceService.java | 127 +++++++++++++++++- .../fingerprint/FingerprintService.java | 3 +- 4 files changed, 136 insertions(+), 4 deletions(-) diff --git a/services/core/java/com/android/server/biometrics/AuthenticationClient.java b/services/core/java/com/android/server/biometrics/AuthenticationClient.java index b899d028869bb..4a9ccdee05223 100644 --- a/services/core/java/com/android/server/biometrics/AuthenticationClient.java +++ b/services/core/java/com/android/server/biometrics/AuthenticationClient.java @@ -46,6 +46,7 @@ public abstract class AuthenticationClient extends ClientMonitor { // authentication while the device is already locked out. In that case, the client is created // but not started yet. The user shouldn't receive the error haptics in this case. private boolean mStarted; + private long mStartTimeMs; /** * This method is called when authentication starts. @@ -75,6 +76,10 @@ public abstract class AuthenticationClient extends ClientMonitor { mRequireConfirmation = requireConfirmation; } + protected long getStartTimeMs() { + return mStartTimeMs; + } + @Override public void binderDied() { super.binderDied(); @@ -228,6 +233,7 @@ public abstract class AuthenticationClient extends ClientMonitor { mStarted = true; onStart(); try { + mStartTimeMs = System.currentTimeMillis(); final int result = getDaemonWrapper().authenticate(mOpId, getGroupId()); if (result != 0) { Slog.w(getLogTag(), "startAuthentication failed, result=" + result); diff --git a/services/core/java/com/android/server/biometrics/LoggableMonitor.java b/services/core/java/com/android/server/biometrics/LoggableMonitor.java index 9e1d5196365b1..6c7cbc166241f 100644 --- a/services/core/java/com/android/server/biometrics/LoggableMonitor.java +++ b/services/core/java/com/android/server/biometrics/LoggableMonitor.java @@ -33,6 +33,10 @@ public abstract class LoggableMonitor { private long mFirstAcquireTimeMs; + protected long getFirstAcquireTimeMs() { + return mFirstAcquireTimeMs; + } + /** * Only valid for AuthenticationClient. * @return true if the client is authenticating for a crypto operation. diff --git a/services/core/java/com/android/server/biometrics/face/FaceService.java b/services/core/java/com/android/server/biometrics/face/FaceService.java index 1ee0a0b505d27..90edcb500f8b3 100644 --- a/services/core/java/com/android/server/biometrics/face/FaceService.java +++ b/services/core/java/com/android/server/biometrics/face/FaceService.java @@ -79,7 +79,9 @@ import java.io.IOException; import java.io.PrintWriter; import java.util.ArrayList; import java.util.Arrays; +import java.util.HashMap; import java.util.List; +import java.util.Map; /** * A service to manage multiple clients that want to access the face HAL API. @@ -100,6 +102,104 @@ public class FaceService extends BiometricServiceBase { private static final String NOTIFICATION_TAG = "FaceService"; private static final int NOTIFICATION_ID = 1; + /** + * Events for bugreports. + */ + public static final class AuthenticationEvent { + private long mStartTime; + private long mLatency; + // Only valid if mError is 0 + private boolean mAuthenticated; + private int mError; + // Only valid if mError is ERROR_VENDOR + private int mVendorError; + + AuthenticationEvent(long startTime, long latency, boolean authenticated, int error, + int vendorError) { + mStartTime = startTime; + mLatency = latency; + mAuthenticated = authenticated; + mError = error; + mVendorError = vendorError; + } + + public String toString(Context context) { + return "Start: " + mStartTime + + "\tLatency: " + mLatency + + "\tAuthenticated: " + mAuthenticated + + "\tError: " + mError + + "\tVendorCode: " + mVendorError + + "\t" + FaceManager.getErrorString(context, mError, mVendorError); + } + } + + /** + * Keep a short historical buffer of stats, with an aggregated usage time. + */ + private class UsageStats { + static final int EVENT_LOG_SIZE = 100; + + Context mContext; + List mAuthenticationEvents; + + int acceptCount; + int rejectCount; + Map mErrorCount; + + long acceptLatency; + long rejectLatency; + Map mErrorLatency; + + UsageStats(Context context) { + mAuthenticationEvents = new ArrayList<>(); + mErrorCount = new HashMap<>(); + mErrorLatency = new HashMap<>(); + mContext = context; + } + + void addEvent(AuthenticationEvent event) { + if (mAuthenticationEvents.size() >= EVENT_LOG_SIZE) { + mAuthenticationEvents.remove(0); + } + mAuthenticationEvents.add(event); + + if (event.mAuthenticated) { + acceptCount++; + acceptLatency += event.mLatency; + } else if (event.mError == 0) { + rejectCount++; + rejectLatency += event.mLatency; + } else { + mErrorCount.put(event.mError, mErrorCount.getOrDefault(event.mError, 0) + 1); + mErrorLatency.put(event.mError, + mErrorLatency.getOrDefault(event.mError, 0l) + event.mLatency); + } + } + + void print(PrintWriter pw) { + pw.println("Events since last reboot: " + mAuthenticationEvents.size()); + for (int i = 0; i < mAuthenticationEvents.size(); i++) { + pw.println(mAuthenticationEvents.get(i).toString(mContext)); + } + + // Dump aggregated usage stats + // TODO: Remove or combine with json dump in a future release + pw.println("Accept\tCount: " + acceptCount + "\tLatency: " + acceptLatency + + "\tAverage: " + (acceptCount > 0 ? acceptLatency / acceptCount : 0)); + pw.println("Reject\tCount: " + rejectCount + "\tLatency: " + rejectLatency + + "\tAverage: " + (rejectCount > 0 ? rejectLatency / rejectCount : 0)); + + for (Integer key : mErrorCount.keySet()) { + final int count = mErrorCount.get(key); + pw.println("Error" + key + "\tCount: " + count + + "\tLatency: " + mErrorLatency.getOrDefault(key, 0l) + + "\tAverage: " + (count > 0 ? mErrorLatency.getOrDefault(key, 0l) / count + : 0) + + "\t" + FaceManager.getErrorString(mContext, key, 0 /* vendorCode */)); + } + } + } + private final class FaceAuthClient extends AuthenticationClientImpl { private int mLastAcquire; @@ -131,6 +231,13 @@ public class FaceService extends BiometricServiceBase { boolean authenticated, ArrayList token) { final boolean result = super.onAuthenticated(identifier, authenticated, token); + mUsageStats.addEvent(new AuthenticationEvent( + getStartTimeMs(), + System.currentTimeMillis() - getStartTimeMs() /* latency */, + authenticated, + 0 /* error */, + 0 /* vendorError */)); + // For face, the authentication lifecycle ends either when // 1) Authenticated == true // 2) Error occurred @@ -140,6 +247,18 @@ public class FaceService extends BiometricServiceBase { return result || !authenticated; } + @Override + public boolean onError(long deviceId, int error, int vendorCode) { + mUsageStats.addEvent(new AuthenticationEvent( + getStartTimeMs(), + System.currentTimeMillis() - getStartTimeMs() /* latency */, + false /* authenticated */, + error, + vendorCode)); + + return super.onError(deviceId, error, vendorCode); + } + @Override public int[] getAcquireIgnorelist() { if (isBiometricPrompt()) { @@ -690,6 +809,7 @@ public class FaceService extends BiometricServiceBase { @GuardedBy("this") private IBiometricsFace mDaemon; + private UsageStats mUsageStats; // One of the AuthenticationClient constants private int mCurrentUserLockoutMode; @@ -900,6 +1020,8 @@ public class FaceService extends BiometricServiceBase { public FaceService(Context context) { super(context); + mUsageStats = new UsageStats(context); + mNotificationManager = getContext().getSystemService(NotificationManager.class); mBiometricPromptIgnoreList = getContext().getResources() @@ -1169,8 +1291,9 @@ public class FaceService extends BiometricServiceBase { Slog.e(TAG, "dump formatting failure", e); } pw.println(dump); - pw.println("HAL Deaths: " + mHALDeathCount); - mHALDeathCount = 0; + pw.println("HAL deaths since last reboot: " + mHALDeathCount); + + mUsageStats.print(pw); } private void dumpProto(FileDescriptor fd) { diff --git a/services/core/java/com/android/server/biometrics/fingerprint/FingerprintService.java b/services/core/java/com/android/server/biometrics/fingerprint/FingerprintService.java index 24fd1b7a6daf7..28336f4598630 100644 --- a/services/core/java/com/android/server/biometrics/fingerprint/FingerprintService.java +++ b/services/core/java/com/android/server/biometrics/fingerprint/FingerprintService.java @@ -1035,8 +1035,7 @@ public class FingerprintService extends BiometricServiceBase { Slog.e(TAG, "dump formatting failure", e); } pw.println(dump); - pw.println("HAL Deaths: " + mHALDeathCount); - mHALDeathCount = 0; + pw.println("HAL deaths since last reboot: " + mHALDeathCount); } private void dumpProto(FileDescriptor fd) {