bitwarden/browser
1
0
Fork 0
mirror of https://github.com/bitwarden/browser synced 2026-02-03 02:03:53 +00:00
Code Issues Releases Wiki Activity

add logging

Browse Source
This commit is contained in:
rr-bw
2025-11-10 07:56:34 -08:00
parent 2f3f2c2105
commit ad6e2f4292
6 changed files with 123 additions and 20 deletions
Download Patch File Download Diff File Expand all files Collapse all files

54
libs/auth/src/common/login-strategies/login.strategy.ts
View File

@@ -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<UserId>} - A promise that resolves the the UserId when the account information has been successfully saved.
*/
protected async saveAccountInformation(tokenResponse: IdentityTokenResponse): Promise<UserId> {
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");

22
libs/auth/src/common/login-strategies/password-login.strategy.ts
View File

@@ -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()");
}
}

3
libs/auth/src/common/services/login-strategies/login-strategy.service.ts
View File

@@ -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);

25
libs/auth/src/common/services/login-success-handler/default-login-success-handler.service.ts
View File

@@ -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<void> {
// ⏱️ 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();

2
libs/common/src/platform/server-notifications/internal/default-server-notifications.service.ts
View File

@@ -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);
},
}),

37
libs/common/src/platform/server-notifications/internal/signalr-connection.service.ts
View File

@@ -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;
// }
}
}