Improve verbose logging (#18147)

* added verbose logging

* refactor logger

* added more info to logs

* add azure loggingLevel, fix logging logic, remove unused code

* fix typescript error

* mask pii data

* fix pii logging

* log tenants

* fix error function

* remove extra info and add else

* use wrapper functions for writing logs, update settings description

* change default to error, change description for pii, refactor

* fix pii logging
This commit is contained in:
Christopher Suh
2022-02-02 14:39:09 -08:00
committed by GitHub
parent e40c31559a
commit cb11c2bb22
6 changed files with 82 additions and 17 deletions

View File

@@ -110,6 +110,20 @@
"type": "boolean",
"default": false,
"description": "%config.piiLogging%"
},
"azure.loggingLevel": {
"type": "string",
"description": "%config.loggingLevel%",
"default": "Error",
"enum": [
"Off",
"Critical",
"Error",
"Warning",
"Information",
"Verbose",
"All"
]
}
}
}

View File

@@ -30,5 +30,7 @@
"config.azureCodeGrantMethod": "Code Grant Method",
"config.azureDeviceCodeMethod": "Device Code Method",
"config.noSystemKeychain": "Disable system keychain integration. Credentials will be stored in a flat file in the user's home directory.",
"config.piiLogging": "Should Personally Identifiable Information (PII) be logged in the console view locally"
"config.piiLogging": "Should Personally Identifiable Information (PII) be logged in the Azure Accounts output channel and the output channel log file.",
"config.loggingLevel": "[Optional] The verbosity of logging for the Azure Accounts extension."
}

View File

@@ -88,6 +88,7 @@ export abstract class AzureAuth implements vscode.Disposable {
public async startLogin(): Promise<AzureAccount | azdata.PromptFailedResult> {
let loginComplete: Deferred<void, Error>;
try {
Logger.verbose('Starting login');
const result = await this.login(this.commonTenant, this.metadata.settings.microsoftResource);
loginComplete = result.authComplete;
if (!result?.response) {
@@ -100,6 +101,7 @@ export abstract class AzureAuth implements vscode.Disposable {
loginComplete?.resolve();
return account;
} catch (ex) {
Logger.error('Login failed');
if (ex instanceof AzureAuthError) {
if (loginComplete) {
loginComplete.reject(ex);
@@ -108,6 +110,9 @@ export abstract class AzureAuth implements vscode.Disposable {
void vscode.window.showErrorMessage(ex.message);
Logger.error(ex.originalMessageAndException);
}
} else {
Logger.error(ex);
}
return {
canceled: false
@@ -145,6 +150,7 @@ export abstract class AzureAuth implements vscode.Disposable {
} else {
Logger.error(ex);
}
Logger.error(ex);
account.isStale = true;
return account;
}
@@ -158,13 +164,13 @@ export abstract class AzureAuth implements vscode.Disposable {
public async getAccountSecurityToken(account: AzureAccount, tenantId: string, azureResource: azdata.AzureResource): Promise<Token | undefined> {
if (account.isStale === true) {
Logger.log('Account was stale. No tokens being fetched.');
Logger.error('Account was stale. No tokens being fetched.');
return undefined;
}
const resource = this.resources.find(s => s.azureResourceId === azureResource);
if (!resource) {
Logger.log('Invalid resource, not fetching', azureResource);
Logger.error('Invalid resource, not fetching', azureResource);
return undefined;
}
@@ -181,7 +187,7 @@ export abstract class AzureAuth implements vscode.Disposable {
if (cachedTokens?.accessToken) {
let expiry = Number(cachedTokens.expiresOn);
if (Number.isNaN(expiry)) {
Logger.log('Expiration time was not defined. This is expected on first launch');
Logger.error('Expiration time was not defined. This is expected on first launch');
expiry = 0;
}
const currentTime = new Date().getTime() / 1000;
@@ -255,9 +261,11 @@ export abstract class AzureAuth implements vscode.Disposable {
}
public async getToken(tenant: Tenant, resource: Resource, postData: AuthorizationCodePostData | TokenPostData | RefreshTokenPostData): Promise<OAuthTokenResponse> {
Logger.verbose('Fetching token');
const tokenUrl = `${this.loginEndpointUrl}${tenant.id}/oauth2/token`;
const response = await this.makePostRequest(tokenUrl, postData);
Logger.pii('Token: ', [{ name: 'access token', objOrArray: response.data }, { name: 'refresh token', objOrArray: response.data }],
[{ name: 'access token', value: response.data.access_token }, { name: 'refresh token', value: response.data.refresh_token }]);
if (response.data.error === 'interaction_required') {
return this.handleInteractionRequired(tenant, resource);
}
@@ -340,8 +348,10 @@ export abstract class AzureAuth implements vscode.Disposable {
const tenantUri = url.resolve(this.metadata.settings.armResource.endpoint, 'tenants?api-version=2019-11-01');
try {
Logger.verbose('Fetching tenants', tenantUri);
const tenantResponse = await this.makeGetRequest(tenantUri, token.token);
const tenants: Tenant[] = tenantResponse.data.value.map((tenantInfo: TenantResponse) => {
Logger.verbose(`Tenant: ${tenantInfo.displayName}`);
return {
id: tenantInfo.tenantId,
displayName: tenantInfo.displayName ? tenantInfo.displayName : localize('azureWorkAccountDisplayName', "Work or school account"),
@@ -358,7 +368,7 @@ export abstract class AzureAuth implements vscode.Disposable {
return tenants;
} catch (ex) {
Logger.log(ex);
Logger.error(`Error fetching tenants :${ex}`);
throw new Error('Error retrieving tenant information');
}
}
@@ -373,7 +383,9 @@ export abstract class AzureAuth implements vscode.Disposable {
throw new AzureAuthError(msg, 'Adding account to cache failed', undefined);
}
try {
Logger.pii(`Saving access token`, [{ name: 'access_token', objOrArray: accessToken }], []);
await this.tokenCache.saveCredential(`${accountKey.accountId}_access_${resource.id}_${tenant.id}`, JSON.stringify(accessToken));
Logger.pii(`Saving refresh token`, [{ name: 'refresh_token', objOrArray: refreshToken }], []);
await this.tokenCache.saveCredential(`${accountKey.accountId}_refresh_${resource.id}_${tenant.id}`, JSON.stringify(refreshToken));
this.memdb.set(`${accountKey.accountId}_${tenant.id}_${resource.id}`, expiresOn);
} catch (ex) {
@@ -395,6 +407,7 @@ export abstract class AzureAuth implements vscode.Disposable {
let refreshTokenString: string;
let expiresOn: string;
try {
Logger.info('Fetching saved token');
accessTokenString = await this.tokenCache.getCredential(`${accountKey.accountId}_access_${resource.id}_${tenant.id}`);
refreshTokenString = await this.tokenCache.getCredential(`${accountKey.accountId}_refresh_${resource.id}_${tenant.id}`);
expiresOn = this.memdb.get(`${accountKey.accountId}_${tenant.id}_${resource.id}`);
@@ -405,7 +418,7 @@ export abstract class AzureAuth implements vscode.Disposable {
try {
if (!accessTokenString) {
Logger.log('No access token found');
Logger.error('No access token found');
return undefined;
}
const accessToken: AccessToken = JSON.parse(accessTokenString);
@@ -502,6 +515,12 @@ export abstract class AzureAuth implements vscode.Disposable {
//#region data modeling
public createAccount(tokenClaims: TokenClaims, key: string, tenants: Tenant[]): AzureAccount {
Logger.verbose(`Token Claims: ${tokenClaims.name}`);
tenants.forEach((tenant) => {
Logger.verbose(
`Tenant ID: ${tenant.id}
Tenant Name: ${tenant.displayName}`);
});
// Determine if this is a microsoft account
let accountIssuer = 'unknown';

View File

@@ -146,7 +146,7 @@ export class AzureAccountProvider implements azdata.AccountProvider, vscode.Disp
}
if (this.authMappings.size === 0) {
Logger.log('No auth method was enabled.');
Logger.error('No auth method was enabled.');
void vscode.window.showErrorMessage(noAuthAvailable);
return { canceled: true };
}
@@ -163,7 +163,7 @@ export class AzureAccountProvider implements azdata.AccountProvider, vscode.Disp
const pick = await vscode.window.showQuickPick(options, { canPickMany: false });
if (!pick) {
Logger.log('No auth method was selected.');
Logger.error('No auth method was selected.');
void vscode.window.showErrorMessage(noAuthSelected);
return { canceled: true };
}

View File

@@ -279,3 +279,4 @@ function updatePiiLoggingLevel() {
const piiLogging: boolean = vscode.workspace.getConfiguration(constants.extensionConfigSectionName).get('piiLogging');
Logger.piiLogging = piiLogging;
}

View File

@@ -6,22 +6,49 @@
import * as vscode from 'vscode';
import * as loc from '../localizedConstants';
export enum LogLevel {
'Pii',
'Off',
'Critical',
'Error',
'Warning',
'Information',
'Verbose',
'All',
}
export class Logger {
public static channel: vscode.OutputChannel = vscode.window.createOutputChannel(loc.extensionName);
private static _piiLogging: boolean = false;
public static config = vscode.workspace.getConfiguration('azure');
static log(msg: any, ...vals: any[]) {
const fullMessage = `${msg} - ${vals.map(v => JSON.stringify(v)).join(' - ')}`;
this.channel.appendLine(fullMessage);
public static shouldLog(logLevel: LogLevel): Boolean {
return logLevel <= LogLevel[Logger.config.loggingLevel as keyof typeof LogLevel];
}
static error(msg: any, ...vals: any[]) {
const fullMessage = `${msg} - ${vals.map(v => JSON.stringify(v)).join(' - ')}`;
this.channel.appendLine(fullMessage);
private static write(logLevel: LogLevel, msg: any, ...vals: any[]) {
if (this.shouldLog(logLevel) || logLevel === LogLevel.Pii) {
const fullMessage = `[${LogLevel[logLevel]}]: ${msg} - ${vals.map(v => JSON.stringify(v)).join(' - ')}`;
this.channel.appendLine(fullMessage);
}
}
public static error(msg: any, ...vals: any[]) {
this.write(LogLevel.Error, msg, vals);
}
public static info(msg: any, ...vals: any[]) {
this.write(LogLevel.Information, msg, vals);
}
public static verbose(msg: any, ...vals: any[]) {
this.write(LogLevel.Verbose, msg, vals);
}
/**
* Logs a message containing PII (when enabled). Provides the ability to sanitize or shorten values to hide information or reduce the amount logged.
* @param msg The initial message to log
@@ -36,7 +63,7 @@ export class Logger {
...objsToSanitize.map(obj => `${obj.name}=${sanitize(obj.objOrArray)}`),
...stringsToShorten.map(str => `${str.name}=${shorten(str.value)}`)
].join(' ');
Logger.log(msg, vals);
Logger.write(LogLevel.Pii, msg, vals);
}
}
@@ -69,6 +96,8 @@ function sanitizeImpl(obj: any): string {
shortenIfExists(obj, 'token');
shortenIfExists(obj, 'refresh_token');
shortenIfExists(obj, 'access_token');
shortenIfExists(obj, 'code');
shortenIfExists(obj, 'id_token');
return JSON.stringify(obj);
}