From 540914fe82065d594c1efbf6495409fad575e2b8 Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:39 +0000 Subject: [PATCH 01/10] locksettings: zero-pad IDs when shown as hex When printing a 'long' ID as hex, use %016x instead of %x so that the width is always consistent, not shorter 1/16 of the time. This also matches the way the synthetic password state files are named. Bug: 268526331 Change-Id: I999606ff0d6a19641f32c4f4826476b4a839ad59 Merged-In: I999606ff0d6a19641f32c4f4826476b4a839ad59 (cherry picked from commit cec56be0add5916392078b82c108a8e6cf5f91d5) --- .../server/locksettings/LockSettingsService.java | 13 +++++++------ .../locksettings/SyntheticPasswordManager.java | 3 +++ 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 5a832b78487cd..7811ec6255e92 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -2958,7 +2958,7 @@ public class LockSettingsService extends ILockSettings.Stub { synchronized (mSpManager) { disableEscrowTokenOnNonManagedDevicesIfNeeded(userId); for (long handle : mSpManager.getPendingTokensForUser(userId)) { - Slog.i(TAG, TextUtils.formatSimple("activateEscrowTokens: %x %d ", handle, userId)); + Slogf.i(TAG, "activateEscrowTokens: %016x %d", handle, userId); mSpManager.createTokenBasedProtector(handle, sp, userId); } } @@ -3121,14 +3121,15 @@ public class LockSettingsService extends ILockSettings.Stub { pw.println("User " + userId); pw.increaseIndent(); synchronized (mSpManager) { - pw.println(TextUtils.formatSimple("LSKF-based SP protector ID: %x", + pw.println(TextUtils.formatSimple("LSKF-based SP protector ID: %016x", getCurrentLskfBasedProtectorId(userId))); - pw.println(TextUtils.formatSimple("LSKF last changed: %s (previous protector: %x)", - timestampToString(getLong(LSKF_LAST_CHANGED_TIME_KEY, 0, userId)), - getLong(PREV_LSKF_BASED_PROTECTOR_ID_KEY, 0, userId))); + pw.println(TextUtils.formatSimple( + "LSKF last changed: %s (previous protector: %016x)", + timestampToString(getLong(LSKF_LAST_CHANGED_TIME_KEY, 0, userId)), + getLong(PREV_LSKF_BASED_PROTECTOR_ID_KEY, 0, userId))); } try { - pw.println(TextUtils.formatSimple("SID: %x", + pw.println(TextUtils.formatSimple("SID: %016x", getGateKeeperService().getSecureUserId(userId))); } catch (RemoteException e) { // ignore. diff --git a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java index d070b416c53c0..eff5ad789e253 100644 --- a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java +++ b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java @@ -1658,6 +1658,9 @@ class SyntheticPasswordManager { } private String getProtectorKeyAlias(long protectorId) { + // Note, this arguably has a bug: %x should be %016x so that the protector ID is left-padded + // with zeroes, like how the synthetic password state files are named. It's too late to fix + // this, though, and it doesn't actually matter. return TextUtils.formatSimple("%s%x", PROTECTOR_KEY_ALIAS_PREFIX, protectorId); } From 816abbc2111afddcc5c22eb625c3c8c1543975c1 Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:40 +0000 Subject: [PATCH 02/10] locksettings: move credentialTypeToString to LockPatternUtils In preparation for using credentialTypeToString() from more places, move it to LockPatternUtils. Also change the strings returned to all upper-case, as this looks better in the contexts where it will be used. Bug: 268526331 Change-Id: Ic9ef28321bca793161182730d11a818378f8ab19 Merged-In: Ic9ef28321bca793161182730d11a818378f8ab19 (cherry picked from commit cacb0f37f6baa9a536c1c5583c0d6a7481ce0c73) --- .../internal/widget/LockPatternUtils.java | 15 ++++++++++++++ .../locksettings/LockSettingsService.java | 20 ++----------------- 2 files changed, 17 insertions(+), 18 deletions(-) diff --git a/core/java/com/android/internal/widget/LockPatternUtils.java b/core/java/com/android/internal/widget/LockPatternUtils.java index 59f6d2b294813..b86020eb90ea0 100644 --- a/core/java/com/android/internal/widget/LockPatternUtils.java +++ b/core/java/com/android/internal/widget/LockPatternUtils.java @@ -133,6 +133,21 @@ public class LockPatternUtils { }) public @interface CredentialType {} + public static String credentialTypeToString(int credentialType) { + switch (credentialType) { + case CREDENTIAL_TYPE_NONE: + return "NONE"; + case CREDENTIAL_TYPE_PATTERN: + return "PATTERN"; + case CREDENTIAL_TYPE_PIN: + return "PIN"; + case CREDENTIAL_TYPE_PASSWORD: + return "PASSWORD"; + default: + return "UNKNOWN_" + credentialType; + } + } + /** * Flag provided to {@link #verifyCredential(LockscreenCredential, int, int)} . If set, the * method will return a handle to the Gatekeeper Password in the diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 7811ec6255e92..38108f13a842b 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -33,7 +33,6 @@ import static android.os.UserHandle.USER_SYSTEM; import static com.android.internal.widget.LockPatternUtils.CREDENTIAL_TYPE_NONE; import static com.android.internal.widget.LockPatternUtils.CREDENTIAL_TYPE_PASSWORD; import static com.android.internal.widget.LockPatternUtils.CREDENTIAL_TYPE_PASSWORD_OR_PIN; -import static com.android.internal.widget.LockPatternUtils.CREDENTIAL_TYPE_PATTERN; import static com.android.internal.widget.LockPatternUtils.CREDENTIAL_TYPE_PIN; import static com.android.internal.widget.LockPatternUtils.CURRENT_LSKF_BASED_PROTECTOR_ID_KEY; import static com.android.internal.widget.LockPatternUtils.EscrowTokenStateChangeCallback; @@ -3090,21 +3089,6 @@ public class LockSettingsService extends ILockSettings.Stub { return new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date(timestamp)); } - private static String credentialTypeToString(int credentialType) { - switch (credentialType) { - case CREDENTIAL_TYPE_NONE: - return "None"; - case CREDENTIAL_TYPE_PATTERN: - return "Pattern"; - case CREDENTIAL_TYPE_PIN: - return "Pin"; - case CREDENTIAL_TYPE_PASSWORD: - return "Password"; - default: - return "Unknown " + credentialType; - } - } - @Override protected void dump(FileDescriptor fd, PrintWriter printWriter, String[] args) { if (!DumpUtils.checkDumpPermission(mContext, TAG, printWriter)) return; @@ -3134,10 +3118,10 @@ public class LockSettingsService extends ILockSettings.Stub { } catch (RemoteException e) { // ignore. } - // It's OK to dump the password type since anyone with physical access can just + // It's OK to dump the credential type since anyone with physical access can just // observe it from the keyguard directly. pw.println("Quality: " + getKeyguardStoredQuality(userId)); - pw.println("CredentialType: " + credentialTypeToString( + pw.println("CredentialType: " + LockPatternUtils.credentialTypeToString( getCredentialTypeInternal(userId))); pw.println("SeparateChallenge: " + getSeparateProfileChallengeEnabledInternal(userId)); pw.println(TextUtils.formatSimple("Metrics: %s", From 8ff87c636df6170a7acb979f1c9f9d578c9f972b Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:41 +0000 Subject: [PATCH 03/10] locksettings: only log FRP migration when actually done Instead of logging "Migrated migrated_frp" when the FRP credential migration is considered, which effectively means whenever the device boots up for the first time (regardless of whether the migration actually needed to be done or not), let's only log if the FRP credential migration is actually being done. Also make the message clearer. Bug: 268526331 Change-Id: I8a46c90902da982eb684e49fb4afee19387621c3 Merged-In: I8a46c90902da982eb684e49fb4afee19387621c3 (cherry picked from commit 0b76af4d8255b34ae746f93a27705f48e7473b16) --- .../com/android/server/locksettings/LockSettingsService.java | 1 - .../android/server/locksettings/SyntheticPasswordManager.java | 1 + 2 files changed, 1 insertion(+), 1 deletion(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 38108f13a842b..36e75c23a70c3 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -887,7 +887,6 @@ public class LockSettingsService extends ILockSettings.Stub { && !getBoolean("migrated_frp", false, 0)) { migrateFrpCredential(); setBoolean("migrated_frp", true, 0); - Slog.i(TAG, "Migrated migrated_frp."); } } diff --git a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java index eff5ad789e253..c322623f67630 100644 --- a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java +++ b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java @@ -964,6 +964,7 @@ class SyntheticPasswordManager { && LockPatternUtils.userOwnsFrpCredential(mContext, userInfo) && getCredentialType(protectorId, userInfo.id) != LockPatternUtils.CREDENTIAL_TYPE_NONE) { + Slog.i(TAG, "Migrating FRP credential to persistent data block"); PasswordData pwd = PasswordData.fromBytes(loadState(PASSWORD_DATA_NAME, protectorId, userInfo.id)); int weaverSlot = loadWeaverSlot(protectorId, userInfo.id); From fa5a4b7d39dc94cbea8881637fb27607a18f2725 Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:42 +0000 Subject: [PATCH 04/10] locksettings: only log profile key removal when actually done The message "Remove keystore profile key for user" is always being logged at INFO level when a user's locksettings state is removed. However, that step is only applicable for profiles, so usually it's irrelevant and is a no-op. It could serve as a hint that the user's locksettings state is being removed. However, there's already a proper log message for that. So, let's first check whether the user actually has a profile key, before attempting to remove it and logging that removal. Bug: 268526331 Change-Id: I90f46bc4cf5bfe096b0b037c5b88a9a9be2dcdd6 Merged-In: I90f46bc4cf5bfe096b0b037c5b88a9a9be2dcdd6 (cherry picked from commit deb0af00959376566112d688ac0fb6e7760ae171) --- .../server/locksettings/LockSettingsService.java | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 36e75c23a70c3..39d565c078ba5 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -2322,13 +2322,18 @@ public class LockSettingsService extends ILockSettings.Stub { } private void removeKeystoreProfileKey(int targetUserId) { - Slog.i(TAG, "Remove keystore profile key for user: " + targetUserId); + final String encryptAlias = PROFILE_KEY_NAME_ENCRYPT + targetUserId; + final String decryptAlias = PROFILE_KEY_NAME_DECRYPT + targetUserId; try { - mJavaKeyStore.deleteEntry(PROFILE_KEY_NAME_ENCRYPT + targetUserId); - mJavaKeyStore.deleteEntry(PROFILE_KEY_NAME_DECRYPT + targetUserId); + if (mJavaKeyStore.containsAlias(encryptAlias) || + mJavaKeyStore.containsAlias(decryptAlias)) { + Slogf.i(TAG, "Removing keystore profile key for user %d", targetUserId); + mJavaKeyStore.deleteEntry(encryptAlias); + mJavaKeyStore.deleteEntry(decryptAlias); + } } catch (KeyStoreException e) { - // We have tried our best to remove all keys - Slog.e(TAG, "Unable to remove keystore profile key for user:" + targetUserId, e); + // We have tried our best to remove the key. + Slogf.e(TAG, e, "Error removing keystore profile key for user %d", targetUserId); } } From cf5a081d019d1e11aa64decb6878456fa436fb8a Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:42 +0000 Subject: [PATCH 05/10] locksettings: clean up logging of escrow token operations Currently "Disabling escrow token on user" is logged *every time* a user's lockscreen credential is verified, if the user is not eligible for escrow tokens. Let's instead make disableEscrowTokenOnNonManagedDevicesIfNeeded() return early if the user has no escrow data, so it will only log if it does something. At the same time, be more verbose when something is actually done related to escrow tokens, as these are generally exceptional events. Bug: 268526331 Change-Id: I83cd783572d33954b95c9d7bb58916e75459809e Merged-In: I83cd783572d33954b95c9d7bb58916e75459809e (cherry picked from commit 57688444a0b52e7af45d84a4a70fa823508fe2c2) --- .../locksettings/LockSettingsService.java | 21 ++++++++++++++----- .../SyntheticPasswordManager.java | 5 +++++ 2 files changed, 21 insertions(+), 5 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 39d565c078ba5..389bf1257956e 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -2932,7 +2932,7 @@ public class LockSettingsService extends ILockSettings.Stub { private long addEscrowToken(@NonNull byte[] token, @TokenType int type, int userId, @NonNull EscrowTokenStateChangeCallback callback) { - if (DEBUG) Slog.d(TAG, "addEscrowToken: user=" + userId + ", type=" + type); + Slogf.i(TAG, "Adding escrow token for user %d", userId); synchronized (mSpManager) { // If the user has no LSKF, then the token can be activated immediately. Otherwise, the // token can't be activated until the SP is unlocked by another protector (normally the @@ -2950,18 +2950,20 @@ public class LockSettingsService extends ILockSettings.Stub { long handle = mSpManager.addPendingToken(token, type, userId, callback); if (sp != null) { // Activate the token immediately + Slogf.i(TAG, "Immediately activating escrow token %016x", handle); mSpManager.createTokenBasedProtector(handle, sp, userId); + } else { + Slogf.i(TAG, "Escrow token %016x will be activated when user is unlocked", handle); } return handle; } } private void activateEscrowTokens(SyntheticPassword sp, int userId) { - if (DEBUG) Slog.d(TAG, "activateEscrowTokens: user=" + userId); synchronized (mSpManager) { disableEscrowTokenOnNonManagedDevicesIfNeeded(userId); for (long handle : mSpManager.getPendingTokensForUser(userId)) { - Slogf.i(TAG, "activateEscrowTokens: %016x %d", handle, userId); + Slogf.i(TAG, "Activating escrow token %016x for user %d", handle, userId); mSpManager.createTokenBasedProtector(handle, sp, userId); } } @@ -3032,6 +3034,8 @@ public class LockSettingsService extends ILockSettings.Stub { @GuardedBy("mSpManager") private boolean setLockCredentialWithTokenInternalLocked(LockscreenCredential credential, long tokenHandle, byte[] token, int userId) { + Slogf.i(TAG, "Resetting lockscreen credential of user %d using escrow token %016x", + userId, tokenHandle); final AuthenticationResult result; result = mSpManager.unlockTokenBasedProtector(getGateKeeperService(), tokenHandle, token, userId); @@ -3054,8 +3058,9 @@ public class LockSettingsService extends ILockSettings.Stub { private boolean unlockUserWithToken(long tokenHandle, byte[] token, int userId) { AuthenticationResult authResult; synchronized (mSpManager) { + Slogf.i(TAG, "Unlocking user %d using escrow token %016x", userId, tokenHandle); if (!mSpManager.hasEscrowData(userId)) { - Slog.w(TAG, "Escrow token is disabled on the current user"); + Slogf.w(TAG, "Escrow token support is disabled on user %d", userId); return false; } authResult = mSpManager.unlockTokenBasedProtector(getGateKeeperService(), tokenHandle, @@ -3066,6 +3071,7 @@ public class LockSettingsService extends ILockSettings.Stub { } } + Slogf.i(TAG, "Unlocked synthetic password for user %d using escrow token", userId); onCredentialVerified(authResult.syntheticPassword, loadPasswordMetrics(authResult.syntheticPassword, userId), userId); return true; @@ -3183,6 +3189,11 @@ public class LockSettingsService extends ILockSettings.Stub { * if we are running an automotive build. */ private void disableEscrowTokenOnNonManagedDevicesIfNeeded(int userId) { + + if (!mSpManager.hasAnyEscrowData(userId)) { + return; + } + // TODO(b/258213147): Remove final long identity = Binder.clearCallingIdentity(); try { @@ -3227,7 +3238,7 @@ public class LockSettingsService extends ILockSettings.Stub { } // Disable escrow token permanently on all other device/user types. - Slog.i(TAG, "Disabling escrow token on user " + userId); + Slogf.i(TAG, "Permanently disabling support for escrow tokens on user %d", userId); mSpManager.destroyEscrowData(userId); } diff --git a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java index c322623f67630..fe15bce061dc6 100644 --- a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java +++ b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java @@ -744,6 +744,11 @@ class SyntheticPasswordManager { && hasState(SP_P1_NAME, NULL_PROTECTOR_ID, userId); } + public boolean hasAnyEscrowData(int userId) { + return hasState(SP_E0_NAME, NULL_PROTECTOR_ID, userId) + || hasState(SP_P1_NAME, NULL_PROTECTOR_ID, userId); + } + public void destroyEscrowData(int userId) { destroyState(SP_E0_NAME, NULL_PROTECTOR_ID, userId); destroyState(SP_P1_NAME, NULL_PROTECTOR_ID, userId); From 0889b6d805f6c3ac85ddf000d604bbfb864193d3 Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:43 +0000 Subject: [PATCH 06/10] locksettings: clean up logging of password history updates Currently the logging for password history updates consists only of the message "Initialized lock password salt for user". But that's only logged on the first update, and it's unclear that it's related to the password history. Let's replace it with a clearer message that is logged whenever a password is added to the password history. This doesn't change anything for the case where password history is disabled, which is the default setting. Bug: 268526331 Change-Id: Ibe6f679a17b887261711e0fd7da1b62a114ce7e6 Merged-In: Ibe6f679a17b887261711e0fd7da1b62a114ce7e6 (cherry picked from commit 61729d86bab407da02d8eeaac1b8f5893f0ae83b) --- .../com/android/server/locksettings/LockSettingsService.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 389bf1257956e..e8ea13d8ad8f7 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -1718,6 +1718,7 @@ public class LockSettingsService extends ILockSettings.Stub { if (passwordHistoryLength == 0) { passwordHistory = ""; } else { + Slogf.d(TAG, "Adding new password to password history for user %d", userHandle); final byte[] hashFactor = getHashFactor(password, userHandle); final byte[] salt = getSalt(userHandle).getBytes(); String hash = password.passwordToHistoryHash(salt, hashFactor); @@ -1749,7 +1750,6 @@ public class LockSettingsService extends ILockSettings.Stub { if (salt == 0) { salt = SecureRandomUtils.randomLong(); setLong(LockPatternUtils.LOCK_PASSWORD_SALT_KEY, salt, userId); - Slog.v(TAG, "Initialized lock password salt for user: " + userId); } return Long.toHexString(salt); } From ad578e9b91371ad22a5424c25b583ad3192f28fc Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:44 +0000 Subject: [PATCH 07/10] locksettings: clean up logging of cached GK password expiration When a cached GK password expires, use a much clearer log message. Also, don't log anything if the GK password was already explicitly removed by LockSettingsService.removeGatekeeperPasswordHandle(). Bug: 268526331 Change-Id: I734c9115bd8ea0a44ed6c03754e87341848a00f5 Merged-In: I734c9115bd8ea0a44ed6c03754e87341848a00f5 (cherry picked from commit 070e3d6ce3c7898bdd0d40abb338ea80c0d3e36f) --- .../android/server/locksettings/LockSettingsService.java | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index e8ea13d8ad8f7..c00561219e29c 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -2728,8 +2728,11 @@ public class LockSettingsService extends ILockSettings.Stub { final long finalHandle = handle; mHandler.postDelayed(() -> { synchronized (mGatekeeperPasswords) { - Slog.d(TAG, "Removing handle: " + finalHandle); - mGatekeeperPasswords.remove(finalHandle); + if (mGatekeeperPasswords.get(finalHandle) != null) { + Slogf.d(TAG, "Cached Gatekeeper password with handle %016x has expired", + finalHandle); + mGatekeeperPasswords.remove(finalHandle); + } } }, GK_PW_HANDLE_STORE_DURATION_MS); From 6318c7e12c130be2e7767c49e956ae2f5e56c9e8 Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:45 +0000 Subject: [PATCH 08/10] locksettings: improve logging of LSKF verification Improve the logging related to verifying the LSKF. We generally don't want to be super verbose here, but it does make sense to have an INFO message at the beginning and end. There was already a DEBUG message at the beginning and an INFO message near the end, but they were unclear, so replace them with clearer INFO messages. Bug: 268526331 Change-Id: Iaccbbd0d5a297bf97ff6ef31630eeec19fe3277b Merged-In: Iaccbbd0d5a297bf97ff6ef31630eeec19fe3277b (cherry picked from commit 18045f36e80f80aee4968c6a91c643c419bd8c6b) --- .../android/server/locksettings/LockSettingsService.java | 9 +++++---- .../server/locksettings/SyntheticPasswordManager.java | 5 +++-- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index c00561219e29c..29868aca0b497 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -1267,7 +1267,6 @@ public class LockSettingsService extends ILockSettings.Stub { } private void unlockKeystore(byte[] password, int userHandle) { - if (DEBUG) Slog.v(TAG, "Unlock keystore for user: " + userHandle); Authorization.onLockScreenEvent(false, userHandle, password, null); } @@ -1277,7 +1276,7 @@ public class LockSettingsService extends ILockSettings.Stub { NoSuchAlgorithmException, NoSuchPaddingException, InvalidKeyException, InvalidAlgorithmParameterException, IllegalBlockSizeException, BadPaddingException, CertificateException, IOException { - if (DEBUG) Slog.v(TAG, "Get child profile decrypted key"); + Slogf.d(TAG, "Decrypting password for tied profile %d", userId); byte[] storedData = mStorage.readChildProfileLock(userId); if (storedData == null) { throw new FileNotFoundException("Child profile lock file not found"); @@ -1326,7 +1325,6 @@ public class LockSettingsService extends ILockSettings.Stub { * {@link com.android.server.SystemServiceManager#unlockUser} */ private void unlockUser(@UserIdInt int userId) { - Slogf.i(TAG, "Unlocking user %d", userId); // TODO: make this method fully async so we can update UI with progress strings final boolean alreadyUnlocked = mUserManager.isUserUnlockingOrUnlocked(userId); final CountDownLatch latch = new CountDownLatch(1); @@ -2130,7 +2128,7 @@ public class LockSettingsService extends ILockSettings.Stub { Slog.e(TAG, "FRP credential can only be verified prior to provisioning."); return VerifyCredentialResponse.ERROR; } - Slog.d(TAG, "doVerifyCredential: user=" + userId); + Slogf.i(TAG, "Verifying lockscreen credential for user %d", userId); final AuthenticationResult authResult; VerifyCredentialResponse response; @@ -2164,6 +2162,7 @@ public class LockSettingsService extends ILockSettings.Stub { } } if (response.getResponseCode() == VerifyCredentialResponse.RESPONSE_OK) { + Slogf.i(TAG, "Successfully verified lockscreen credential for user %d", userId); onCredentialVerified(authResult.syntheticPassword, PasswordMetrics.computeForCredential(credential), userId); if ((flags & VERIFY_FLAG_REQUEST_GK_PW_HANDLE) != 0) { @@ -2910,6 +2909,7 @@ public class LockSettingsService extends ILockSettings.Stub { public byte[] getHashFactor(LockscreenCredential currentCredential, int userId) { checkPasswordReadPermission(); try { + Slogf.d(TAG, "Getting password history hash factor for user %d", userId); if (isProfileWithUnifiedLock(userId)) { try { currentCredential = getDecryptedPasswordForTiedProfile(userId); @@ -3473,6 +3473,7 @@ public class LockSettingsService extends ILockSettings.Stub { synchronized (mSpManager) { mSpManager.verifyChallenge(getGateKeeperService(), sp, 0L, userId); } + Slogf.i(TAG, "Restored synthetic password for user %d using reboot escrow", userId); onCredentialVerified(sp, loadPasswordMetrics(sp, userId), userId); } } diff --git a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java index fe15bce061dc6..b54ee7f36c47c 100644 --- a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java +++ b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java @@ -1176,8 +1176,9 @@ class SyntheticPasswordManager { storedType = pwd.credentialType; } if (!credential.checkAgainstStoredType(storedType)) { - Slog.e(TAG, TextUtils.formatSimple("Credential type mismatch: expected %d actual %d", - storedType, credential.getType())); + Slogf.e(TAG, "Credential type mismatch: stored type is %s but provided type is %s", + LockPatternUtils.credentialTypeToString(storedType), + LockPatternUtils.credentialTypeToString(credential.getType())); result.gkResponse = VerifyCredentialResponse.ERROR; return result; } From b56a4292011fe18cbcb63181131dda5974dc102f Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:46 +0000 Subject: [PATCH 09/10] locksettings: improve logging of SP and protector changes Improve the logging for synthetic password protectors being created and deleted, and the synthetic password itself being created. This includes the case where a user's LSKF is being changed. These are infrequent and important operations, so generally we should error on the side of being verbose for them. Bug: 268526331 Change-Id: I9cd91ecd3bb80b59fb367072d7f30dc90a5ee332 Merged-In: I9cd91ecd3bb80b59fb367072d7f30dc90a5ee332 (cherry picked from commit 72ba837864de6a6740a5c5a2646dad838a99d3ab) --- .../server/locksettings/LockSettingsService.java | 16 ++++++++-------- .../locksettings/SyntheticPasswordManager.java | 14 ++++++++++---- 2 files changed, 18 insertions(+), 12 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 29868aca0b497..5f34770e07b5c 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -380,7 +380,6 @@ public class LockSettingsService extends ILockSettings.Stub { */ private void tieProfileLockIfNecessary(int profileUserId, LockscreenCredential profileUserPassword) { - if (DEBUG) Slog.v(TAG, "Check child profile lock for user: " + profileUserId); // Only for profiles that shares credential with parent if (!isCredentialSharableWithParent(profileUserId)) { return; @@ -398,8 +397,7 @@ public class LockSettingsService extends ILockSettings.Stub { // as its parent. final int parentId = mUserManager.getProfileParent(profileUserId).id; if (!isUserSecure(parentId) && !profileUserPassword.isNone()) { - if (DEBUG) Slog.v(TAG, "Parent does not have a screen lock but profile has one"); - + Slogf.i(TAG, "Clearing password for profile user %d to match parent", profileUserId); setLockCredentialInternal(LockscreenCredential.createNone(), profileUserPassword, profileUserId, /* isLockTiedToParent= */ true); return; @@ -415,7 +413,6 @@ public class LockSettingsService extends ILockSettings.Stub { Slog.e(TAG, "Failed to talk to GateKeeper service", e); return; } - if (DEBUG) Slog.v(TAG, "Tie profile to parent now!"); try (LockscreenCredential unifiedProfilePassword = generateRandomProfilePassword()) { setLockCredentialInternal(unifiedProfilePassword, profileUserPassword, profileUserId, /* isLockTiedToParent= */ true); @@ -1634,7 +1631,6 @@ public class LockSettingsService extends ILockSettings.Stub { LockscreenCredential savedCredential, int userId, boolean isLockTiedToParent) { Objects.requireNonNull(credential); Objects.requireNonNull(savedCredential); - if (DEBUG) Slog.d(TAG, "setLockCredentialInternal: user=" + userId); synchronized (mSpManager) { if (savedCredential.isNone() && isProfileWithUnifiedLock(userId)) { // get credential from keystore when profile has unified lock @@ -1871,7 +1867,8 @@ public class LockSettingsService extends ILockSettings.Stub { @VisibleForTesting /** Note: this method is overridden in unit tests */ protected void tieProfileLockToParent(int profileUserId, int parentUserId, LockscreenCredential password) { - if (DEBUG) Slog.v(TAG, "tieProfileLockToParent for user: " + profileUserId); + Slogf.i(TAG, "Tying lock for profile user %d to parent user %d", profileUserId, + parentUserId); final byte[] iv; final byte[] ciphertext; final long parentSid; @@ -2680,7 +2677,7 @@ public class LockSettingsService extends ILockSettings.Stub { @VisibleForTesting SyntheticPassword initializeSyntheticPassword(int userId) { synchronized (mSpManager) { - Slog.i(TAG, "Initialize SyntheticPassword for user: " + userId); + Slogf.i(TAG, "Initializing synthetic password for user %d", userId); Preconditions.checkState(getCurrentLskfBasedProtectorId(userId) == SyntheticPasswordManager.NULL_PROTECTOR_ID, "Cannot reinitialize SP"); @@ -2691,6 +2688,7 @@ public class LockSettingsService extends ILockSettings.Stub { setCurrentLskfBasedProtectorId(protectorId, userId); setUserKeyProtection(userId, sp.deriveFileBasedEncryptionKey()); onSyntheticPasswordCreated(userId, sp); + Slogf.i(TAG, "Successfully initialized synthetic password for user %d", userId); return sp; } } @@ -2780,7 +2778,8 @@ public class LockSettingsService extends ILockSettings.Stub { @GuardedBy("mSpManager") private long setLockCredentialWithSpLocked(LockscreenCredential credential, SyntheticPassword sp, int userId) { - if (DEBUG) Slog.d(TAG, "setLockCredentialWithSpLocked: user=" + userId); + Slogf.i(TAG, "Changing lockscreen credential of user %d; newCredentialType=%s\n", + userId, LockPatternUtils.credentialTypeToString(credential.getType())); final int savedCredentialType = getCredentialTypeInternal(userId); final long oldProtectorId = getCurrentLskfBasedProtectorId(userId); final long newProtectorId = mSpManager.createLskfBasedProtector(getGateKeeperService(), @@ -2825,6 +2824,7 @@ public class LockSettingsService extends ILockSettings.Stub { } } mSpManager.destroyLskfBasedProtector(oldProtectorId, userId); + Slogf.i(TAG, "Successfully changed lockscreen credential of user %d", userId); return newProtectorId; } diff --git a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java index b54ee7f36c47c..1663b019d769a 100644 --- a/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java +++ b/services/core/java/com/android/server/locksettings/SyntheticPasswordManager.java @@ -791,11 +791,11 @@ class SyntheticPasswordManager { } Set usedSlots = getUsedWeaverSlots(); if (!usedSlots.contains(slot)) { - Slog.i(TAG, "Destroy weaver slot " + slot + " for user " + userId); + Slogf.i(TAG, "Erasing Weaver slot %d", slot); weaverEnroll(slot, null, null); mPasswordSlotManager.markSlotDeleted(slot); } else { - Slog.w(TAG, "Skip destroying reused weaver slot " + slot + " for user " + userId); + Slogf.i(TAG, "Weaver slot %d was already reused; not erasing it", slot); } } } @@ -863,11 +863,13 @@ class SyntheticPasswordManager { long sid = GateKeeper.INVALID_SECURE_USER_ID; final byte[] protectorSecret; + Slogf.i(TAG, "Creating LSKF-based protector %016x for user %d", protectorId, userId); + if (isWeaverAvailable()) { // Weaver is available, so make the protector use it to verify the LSKF. Do this even // if the LSKF is empty, as that gives us support for securely deleting the protector. int weaverSlot = getNextAvailableWeaverSlot(); - Slog.i(TAG, "Weaver enroll password to slot " + weaverSlot + " for user " + userId); + Slogf.i(TAG, "Enrolling LSKF for user %d into Weaver slot %d", userId, weaverSlot); byte[] weaverSecret = weaverEnroll(weaverSlot, stretchedLskfToWeaverKey(stretchedLskf), null); if (weaverSecret == null) { @@ -897,6 +899,7 @@ class SyntheticPasswordManager { } catch (RemoteException ignore) { Slog.w(TAG, "Failed to clear SID from gatekeeper"); } + Slogf.i(TAG, "Enrolling LSKF for user %d into Gatekeeper", userId); GateKeeperResponse response; try { response = gatekeeper.enroll(fakeUserId(userId), null, null, @@ -1098,9 +1101,10 @@ class SyntheticPasswordManager { Slog.w(TAG, "User is not escrowable"); return false; } + Slogf.i(TAG, "Creating token-based protector %016x for user %d", tokenHandle, userId); if (isWeaverAvailable()) { int slot = getNextAvailableWeaverSlot(); - Slog.i(TAG, "Weaver enroll token to slot " + slot + " for user " + userId); + Slogf.i(TAG, "Using Weaver slot %d for new token-based protector", slot); if (weaverEnroll(slot, null, tokenData.weaverSecret) == null) { Slog.e(TAG, "Failed to enroll weaver secret when activating token"); return false; @@ -1480,6 +1484,7 @@ class SyntheticPasswordManager { /** Destroy a token-based SP protector. */ public void destroyTokenBasedProtector(long protectorId, int userId) { + Slogf.i(TAG, "Destroying token-based protector %016x for user %d", protectorId, userId); SyntheticPasswordBlob blob = SyntheticPasswordBlob.fromBytes(loadState(SP_BLOB_NAME, protectorId, userId)); destroyProtectorCommon(protectorId, userId); @@ -1505,6 +1510,7 @@ class SyntheticPasswordManager { * Destroy an LSKF-based SP protector. This is used when the user's LSKF is changed. */ public void destroyLskfBasedProtector(long protectorId, int userId) { + Slogf.i(TAG, "Destroying LSKF-based protector %016x for user %d", protectorId, userId); destroyProtectorCommon(protectorId, userId); destroyState(PASSWORD_DATA_NAME, protectorId, userId); destroyState(PASSWORD_METRICS_NAME, protectorId, userId); From f69babfec42b9de411dbc1e7f1617757d8ebdd3c Mon Sep 17 00:00:00 2001 From: Eric Biggers Date: Mon, 27 Feb 2023 19:20:47 +0000 Subject: [PATCH 10/10] locksettings: miscellaneous logging cleanups Clean up a few log messages that didn't fit into any of the previous changes. This includes removing the last uses of the DEBUG field. Bug: 268526331 Change-Id: Iee462825434c5a5042e1ddc4dfbb95579d339d40 Merged-In: Iee462825434c5a5042e1ddc4dfbb95579d339d40 (cherry picked from commit 50e87895198fe140720f94ffb099310509a94be2) --- .../server/locksettings/LockSettingsService.java | 14 +++++--------- 1 file changed, 5 insertions(+), 9 deletions(-) diff --git a/services/core/java/com/android/server/locksettings/LockSettingsService.java b/services/core/java/com/android/server/locksettings/LockSettingsService.java index 5f34770e07b5c..4f28432a20a27 100644 --- a/services/core/java/com/android/server/locksettings/LockSettingsService.java +++ b/services/core/java/com/android/server/locksettings/LockSettingsService.java @@ -81,7 +81,6 @@ import android.hardware.fingerprint.Fingerprint; import android.hardware.fingerprint.FingerprintManager; import android.net.Uri; import android.os.Binder; -import android.os.Build; import android.os.Bundle; import android.os.Handler; import android.os.IBinder; @@ -116,7 +115,6 @@ import android.text.TextUtils; import android.util.ArrayMap; import android.util.ArraySet; import android.util.EventLog; -import android.util.Log; import android.util.LongSparseArray; import android.util.Slog; import android.util.SparseArray; @@ -200,7 +198,6 @@ public class LockSettingsService extends ILockSettings.Stub { private static final String TAG = "LockSettingsService"; private static final String PERMISSION = ACCESS_KEYGUARD_SECURE_STORAGE; private static final String BIOMETRIC_PERMISSION = MANAGE_BIOMETRIC; - private static final boolean DEBUG = Build.IS_DEBUGGABLE && Log.isLoggable(TAG, Log.DEBUG); private static final int PROFILE_KEY_IV_SIZE = 12; private static final String SEPARATE_PROFILE_CHALLENGE_KEY = "lockscreen.profilechallenge"; @@ -686,8 +683,8 @@ public class LockSettingsService extends ILockSettings.Stub { PendingIntent intent = PendingIntent.getActivity(mContext, 0, unlockIntent, PendingIntent.FLAG_UPDATE_CURRENT | PendingIntent.FLAG_MUTABLE_UNAUDITED); - Slog.d(TAG, TextUtils.formatSimple("showing encryption notification, user: %d; reason: %s", - user.getIdentifier(), reason)); + Slogf.d(TAG, "Showing encryption notification for user %d; reason: %s", + user.getIdentifier(), reason); showEncryptionNotification(user, title, message, detail, intent); } @@ -731,7 +728,7 @@ public class LockSettingsService extends ILockSettings.Stub { } private void hideEncryptionNotification(UserHandle userHandle) { - Slog.d(TAG, "hide encryption notification, user: " + userHandle.getIdentifier()); + Slogf.d(TAG, "Hiding encryption notification for user %d", userHandle.getIdentifier()); mNotificationManager.cancelAsUser(null, SystemMessage.NOTE_FBE_ENCRYPTED_NOTIFICATION, userHandle); } @@ -1029,7 +1026,7 @@ public class LockSettingsService extends ILockSettings.Stub { private void enforceFrpResolved() { final int mainUserId = mInjector.getUserManagerInternal().getMainUserId(); if (mainUserId < 0) { - Slog.i(TAG, "No Main user on device; skip enforceFrpResolved"); + Slog.d(TAG, "No Main user on device; skipping enforceFrpResolved"); return; } final ContentResolver cr = mContext.getContentResolver(); @@ -1995,7 +1992,7 @@ public class LockSettingsService extends ILockSettings.Stub { @Override public void resetKeyStore(int userId) { checkWritePermission(); - if (DEBUG) Slog.v(TAG, "Reset keystore for user: " + userId); + Slogf.d(TAG, "Resetting keystore for user %d", userId); List profileUserIds = new ArrayList<>(); List profileUserDecryptedPasswords = new ArrayList<>(); final List profiles = mUserManager.getProfiles(userId); @@ -2032,7 +2029,6 @@ public class LockSettingsService extends ILockSettings.Stub { int piUserId = profileUserIds.get(i); LockscreenCredential piUserDecryptedPassword = profileUserDecryptedPasswords.get(i); if (piUserId != -1 && piUserDecryptedPassword != null) { - if (DEBUG) Slog.v(TAG, "Restore tied profile lock"); tieProfileLockToParent(piUserId, userId, piUserDecryptedPassword); } if (piUserDecryptedPassword != null) {