diff --git a/libs/auth/src/common/login-strategies/login.strategy.ts b/libs/auth/src/common/login-strategies/login.strategy.ts index 7ad5cd24353..1fe88c57f0c 100644 --- a/libs/auth/src/common/login-strategies/login.strategy.ts +++ b/libs/auth/src/common/login-strategies/login.strategy.ts @@ -1,3 +1,4 @@ +/* eslint-disable no-console */ import { BehaviorSubject, filter, firstValueFrom, timeout, Observable } from "rxjs"; import { ApiService } from "@bitwarden/common/abstractions/api.service"; @@ -120,6 +121,10 @@ export abstract class LoginStrategy { } const response = await this.apiService.postIdentityToken(tokenRequest); + // ⏱️ START TIMING - Response received from /connect/token + performance.mark("token-response-received"); + console.time("⏱️ Token→Sync Processing Time"); + if (response instanceof IdentityTwoFactorResponse) { return [await this.processTwoFactorResponse(response), response]; } else if (response instanceof IdentityTokenResponse) { @@ -176,60 +181,88 @@ export abstract class LoginStrategy { * @returns {Promise} - A promise that resolves the the UserId when the account information has been successfully saved. */ protected async saveAccountInformation(tokenResponse: IdentityTokenResponse): Promise { + console.time(" 💾 STATE WRITE: tokenService.decodeAccessToken()"); const accountInformation = await this.tokenService.decodeAccessToken(tokenResponse.accessToken); + console.timeEnd(" 💾 STATE WRITE: tokenService.decodeAccessToken()"); const userId = accountInformation.sub as UserId; + console.time(" 💾 STATE WRITE: accountService.addAccount()"); await this.accountService.addAccount(userId, { name: accountInformation.name, email: accountInformation.email ?? "", emailVerified: accountInformation.email_verified ?? false, }); + console.timeEnd(" 💾 STATE WRITE: accountService.addAccount()"); // User env must be seeded from currently set env before switching to the account // to avoid any incorrect emissions of the global default env. + console.time(" 💾 STATE WRITE: environmentService.seedUserEnvironment()"); await this.environmentService.seedUserEnvironment(userId); + console.timeEnd(" 💾 STATE WRITE: environmentService.seedUserEnvironment()"); + console.time(" 💾 STATE WRITE: accountService.switchAccount()"); await this.accountService.switchAccount(userId); + console.timeEnd(" 💾 STATE WRITE: accountService.switchAccount()"); + console.time(" 📡 OBSERVABLE: verifyAccountAdded()"); await this.verifyAccountAdded(userId); + console.timeEnd(" 📡 OBSERVABLE: verifyAccountAdded()"); // We must set user decryption options before retrieving vault timeout settings // as the user decryption options help determine the available timeout actions. + console.time(" 💾 STATE WRITE: userDecryptionOptionsService.setUserDecryptionOptions()"); await this.userDecryptionOptionsService.setUserDecryptionOptions( UserDecryptionOptions.fromResponse(tokenResponse), ); + console.timeEnd(" 💾 STATE WRITE: userDecryptionOptionsService.setUserDecryptionOptions()"); if (tokenResponse.userDecryptionOptions?.masterPasswordUnlock != null) { + console.time(" 💾 STATE WRITE: masterPasswordService.setMasterPasswordUnlockData()"); const masterPasswordUnlockData = tokenResponse.userDecryptionOptions.masterPasswordUnlock.toMasterPasswordUnlockData(); await this.masterPasswordService.setMasterPasswordUnlockData( masterPasswordUnlockData, userId, ); + console.timeEnd(" 💾 STATE WRITE: masterPasswordService.setMasterPasswordUnlockData()"); } + console.time(" 📖 STATE READ: vaultTimeoutSettingsService.getVaultTimeoutActionByUserId$()"); const vaultTimeoutAction = await firstValueFrom( this.vaultTimeoutSettingsService.getVaultTimeoutActionByUserId$(userId), ); + console.timeEnd( + " 📖 STATE READ: vaultTimeoutSettingsService.getVaultTimeoutActionByUserId$()", + ); + + console.time(" 📖 STATE READ: vaultTimeoutSettingsService.getVaultTimeoutByUserId$()"); const vaultTimeout = await firstValueFrom( this.vaultTimeoutSettingsService.getVaultTimeoutByUserId$(userId), ); + console.timeEnd(" 📖 STATE READ: vaultTimeoutSettingsService.getVaultTimeoutByUserId$()"); // User id will be derived from the access token. + console.time(" 💾 STATE WRITE: tokenService.setTokens()"); await this.tokenService.setTokens( tokenResponse.accessToken, vaultTimeoutAction as VaultTimeoutAction, vaultTimeout, tokenResponse.refreshToken, // Note: CLI login via API key sends undefined for refresh token. ); + console.timeEnd(" 💾 STATE WRITE: tokenService.setTokens()"); + console.time(" 💾 STATE WRITE: KdfConfigService.setKdfConfig()"); await this.KdfConfigService.setKdfConfig(userId as UserId, tokenResponse.kdfConfig); + console.timeEnd(" 💾 STATE WRITE: KdfConfigService.setKdfConfig()"); + console.time(" 💾 STATE WRITE: billingAccountProfileStateService.setHasPremium()"); await this.billingAccountProfileStateService.setHasPremium( accountInformation.premium ?? false, false, userId, ); + console.timeEnd(" 💾 STATE WRITE: billingAccountProfileStateService.setHasPremium()"); + return userId; } @@ -243,24 +276,45 @@ export abstract class LoginStrategy { } // Must come before setting keys, user key needs email to update additional keys. + console.log(""); + console.time("saveAccountInformation()"); const userId = await this.saveAccountInformation(response); + console.timeEnd("saveAccountInformation()"); + result.userId = userId; result.resetMasterPassword = response.resetMasterPassword; if (response.twoFactorToken != null) { // note: we can read email from access token b/c it was saved in saveAccountInformation + console.time("📖 STATE READ: tokenService.getEmail()"); const userEmail = await this.tokenService.getEmail(); + console.timeEnd("📖 STATE READ: tokenService.getEmail()"); + console.time("💾 STATE WRITE: tokenService.setTwoFactorToken()"); await this.tokenService.setTwoFactorToken(userEmail, response.twoFactorToken); + console.timeEnd("💾 STATE WRITE: tokenService.setTwoFactorToken()"); } + console.log(""); + console.time("setMasterKey()"); await this.setMasterKey(response, userId); + console.timeEnd("setMasterKey()"); + + console.log(""); + console.time("setUserKey()"); await this.setUserKey(response, userId); + console.timeEnd("setUserKey()"); + + console.log(""); + console.time("💾 STATE WRITE: keyService.setPrivateKey()"); await this.setPrivateKey(response, userId); + console.timeEnd("💾 STATE WRITE: keyService.setPrivateKey()"); // This needs to run after the keys are set because it checks for the existence of the encrypted private key + console.time("💾 STATE WRITE: super.processForceSetPasswordReason()"); await this.processForceSetPasswordReason(response.forcePasswordReset, userId); + console.timeEnd("💾 STATE WRITE: super.processForceSetPasswordReason()"); this.messagingService.send("loggedIn"); diff --git a/libs/auth/src/common/login-strategies/password-login.strategy.ts b/libs/auth/src/common/login-strategies/password-login.strategy.ts index 3482e73d5d7..0b1335e743f 100644 --- a/libs/auth/src/common/login-strategies/password-login.strategy.ts +++ b/libs/auth/src/common/login-strategies/password-login.strategy.ts @@ -1,5 +1,6 @@ // FIXME: Update this file to be type safe and remove this and next line // @ts-strict-ignore +/* eslint-disable no-console */ import { BehaviorSubject, firstValueFrom, map, Observable } from "rxjs"; import { Jsonify } from "type-fest"; @@ -101,7 +102,9 @@ export class PasswordLoginStrategy extends LoginStrategy { const [authResult, identityResponse] = await this.startLogIn(); + console.time("💾 STATE WRITE: evaluateMasterPasswordIfRequired()"); await this.evaluateMasterPasswordIfRequired(identityResponse, credentials, authResult); + console.timeEnd("💾 STATE WRITE: evaluateMasterPasswordIfRequired()"); return authResult; } @@ -114,8 +117,13 @@ export class PasswordLoginStrategy extends LoginStrategy { protected override async setMasterKey(response: IdentityTokenResponse, userId: UserId) { const { masterKey, localMasterKeyHash } = this.cache.value; + console.time(" 💾 STATE WRITE: masterPasswordService.setMasterKey()"); await this.masterPasswordService.setMasterKey(masterKey, userId); + console.timeEnd(" 💾 STATE WRITE: masterPasswordService.setMasterKey()"); + + console.time(" 💾 STATE WRITE: masterPasswordService.setMasterKeyHash()"); await this.masterPasswordService.setMasterKeyHash(localMasterKeyHash, userId); + console.timeEnd(" 💾 STATE WRITE: masterPasswordService.setMasterKeyHash()"); } protected override async setUserKey( @@ -128,16 +136,30 @@ export class PasswordLoginStrategy extends LoginStrategy { } if (response.key) { + console.time(" 💾 STATE WRITE: masterPasswordService.setMasterKeyEncryptedUserKey()"); await this.masterPasswordService.setMasterKeyEncryptedUserKey(response.key, userId); + console.timeEnd(" 💾 STATE WRITE: masterPasswordService.setMasterKeyEncryptedUserKey()"); } + console.time(" 📖 STATE READ: masterPasswordService.masterKey$()"); const masterKey = await firstValueFrom(this.masterPasswordService.masterKey$(userId)); + console.timeEnd(" 📖 STATE READ: masterPasswordService.masterKey$()"); + if (masterKey) { + console.time( + " 🔐 ENCRYPTION/DECRYPTION: masterPasswordService.decryptUserKeyWithMasterKey()", + ); const userKey = await this.masterPasswordService.decryptUserKeyWithMasterKey( masterKey, userId, ); + console.timeEnd( + " 🔐 ENCRYPTION/DECRYPTION: masterPasswordService.decryptUserKeyWithMasterKey()", + ); + + console.time(" 💾 STATE WRITE: keyService.setUserKey()"); await this.keyService.setUserKey(userKey, userId); + console.timeEnd(" 💾 STATE WRITE: keyService.setUserKey()"); } } diff --git a/libs/auth/src/common/services/login-strategies/login-strategy.service.ts b/libs/auth/src/common/services/login-strategies/login-strategy.service.ts index 6900e5e5872..dceb95ccd16 100644 --- a/libs/auth/src/common/services/login-strategies/login-strategy.service.ts +++ b/libs/auth/src/common/services/login-strategies/login-strategy.service.ts @@ -231,7 +231,10 @@ export class LoginStrategyService implements LoginStrategyServiceAbstraction { const result = await strategy?.logIn(ownedCredentials as any); if (result != null && !result.requiresTwoFactor && !result.requiresDeviceVerification) { + console.log(""); + console.time("💾 STATE WRITE: clearCache()"); await this.clearCache(); + console.timeEnd("💾 STATE WRITE: clearCache()"); } else { // Cache the strategy data so we can attempt again later with 2fa or device verification await this.loginStrategyCacheState.update((_) => strategy?.exportCache() ?? null); diff --git a/libs/auth/src/common/services/login-success-handler/default-login-success-handler.service.ts b/libs/auth/src/common/services/login-success-handler/default-login-success-handler.service.ts index 78003a4fca0..9f6d554f965 100644 --- a/libs/auth/src/common/services/login-success-handler/default-login-success-handler.service.ts +++ b/libs/auth/src/common/services/login-success-handler/default-login-success-handler.service.ts @@ -1,3 +1,4 @@ +/* eslint-disable no-console */ import { SsoLoginServiceAbstraction } from "@bitwarden/common/auth/abstractions/sso-login.service.abstraction"; import { FeatureFlag } from "@bitwarden/common/enums/feature-flag.enum"; import { ConfigService } from "@bitwarden/common/platform/abstractions/config/config.service"; @@ -19,6 +20,30 @@ export class DefaultLoginSuccessHandlerService implements LoginSuccessHandlerSer private logService: LogService, ) {} async run(userId: UserId): Promise { + // ⏱️ END TIMING - About to call /sync + console.log(""); + performance.mark("before-sync-call"); + console.timeEnd("⏱️ Token→Sync Processing Time"); + + // Calculate and display the duration + try { + const measure = performance.measure( + "token-to-sync-duration", + "token-response-received", + "before-sync-call", + ); + console.log( + `%c📊 Time between /connect/token response and /sync call: ${measure.duration.toFixed(2)}ms`, + "color: #27AE60; font-weight: bold; font-size: 14px", + ); + } catch (e) { + // Performance marks might not exist in some scenarios (e.g., 2FA flow) + } + + console.log(""); + console.log("%c🌐 POST /sync - Starting call now...", "color: #95A5A6"); + + // This is where /sync is actually called - we don't time this await this.syncService.fullSync(true, { skipTokenRefresh: true }); await this.userAsymmetricKeysRegenerationService.regenerateIfNeeded(userId); await this.loginEmailService.clearLoginEmail(); diff --git a/libs/common/src/platform/server-notifications/internal/default-server-notifications.service.ts b/libs/common/src/platform/server-notifications/internal/default-server-notifications.service.ts index efe0a8ae408..4180c5571a3 100644 --- a/libs/common/src/platform/server-notifications/internal/default-server-notifications.service.ts +++ b/libs/common/src/platform/server-notifications/internal/default-server-notifications.service.ts @@ -157,7 +157,7 @@ export class DefaultServerNotificationsService implements ServerNotificationsSer ); }, notSupported: () => { - this.logService.info("Using SignalR for server notifications"); + // this.logService.info("Using SignalR for server notifications"); return this.connectSignalR$(userId, notificationsUrl); }, }), diff --git a/libs/common/src/platform/server-notifications/internal/signalr-connection.service.ts b/libs/common/src/platform/server-notifications/internal/signalr-connection.service.ts index 2a9e7fc7141..5e9bc709f9e 100644 --- a/libs/common/src/platform/server-notifications/internal/signalr-connection.service.ts +++ b/libs/common/src/platform/server-notifications/internal/signalr-connection.service.ts @@ -45,25 +45,24 @@ class SignalRLogger implements ILogger { } log(logLevel: LogLevel, message: string): void { - const redactedMessage = `[SignalR] ${this.redactMessage(message)}`; - - switch (logLevel) { - case LogLevel.Critical: - this.logService.error(redactedMessage); - break; - case LogLevel.Error: - this.logService.error(redactedMessage); - break; - case LogLevel.Warning: - this.logService.warning(redactedMessage); - break; - case LogLevel.Information: - this.logService.info(redactedMessage); - break; - case LogLevel.Debug: - this.logService.debug(redactedMessage); - break; - } + // const redactedMessage = `[SignalR] ${this.redactMessage(message)}`; + // switch (logLevel) { + // case LogLevel.Critical: + // this.logService.error(redactedMessage); + // break; + // case LogLevel.Error: + // this.logService.error(redactedMessage); + // break; + // case LogLevel.Warning: + // this.logService.warning(redactedMessage); + // break; + // case LogLevel.Information: + // this.logService.info(redactedMessage); + // break; + // case LogLevel.Debug: + // this.logService.debug(redactedMessage); + // break; + // } } }