Add more Azure account logging (microsoft#16847)

* logging 1 * More logging * more logging * Handle each tenant separately. * cleanup
karlb-dev · Aug 20, 2021 · ccaf111 · ccaf111
1 parent 5b3fbaa
commit ccaf111
Show file tree

Hide file tree

Showing 4 changed files with 85 additions and 10 deletions.
diff --git a/extensions/azurecore/src/account-provider/auths/azureAuth.ts b/extensions/azurecore/src/account-provider/auths/azureAuth.ts
@@ -231,6 +231,7 @@ export abstract class AzureAuth implements vscode.Disposable {
 	 * @param refreshToken
 	 */
 	public async refreshToken(tenant: Tenant, resource: Resource, refreshToken: RefreshToken | undefined): Promise<OAuthTokenResponse> {
+		Logger.pii('Refreshing token', [{ name: 'token', objOrArray: refreshToken }], []);
 		if (refreshToken) {
 			const postData: RefreshTokenPostData = {
 				grant_type: 'refresh_token',
@@ -333,7 +334,6 @@ export abstract class AzureAuth implements vscode.Disposable {
 		const tenantUri = url.resolve(this.metadata.settings.armResource.endpoint, 'tenants?api-version=2019-11-01');
 		try {
 			const tenantResponse = await this.makeGetRequest(tenantUri, token.token);
-			Logger.pii('getTenants', tenantResponse.data);
 			const tenants: Tenant[] = tenantResponse.data.value.map((tenantInfo: TenantResponse) => {
 				return {
 					id: tenantInfo.tenantId,
@@ -362,7 +362,7 @@ export abstract class AzureAuth implements vscode.Disposable {
 	private async saveToken(tenant: Tenant, resource: Resource, accountKey: azdata.AccountKey, { accessToken, refreshToken, expiresOn }: OAuthTokenResponse) {
 		const msg = localize('azure.cacheErrorAdd', "Error when adding your account to the cache.");
 		if (!tenant.id || !resource.id) {
-			Logger.pii('Tenant ID or resource ID was undefined', tenant, resource);
+			Logger.pii('Tenant ID or resource ID was undefined', [], [], tenant, resource);
 			throw new AzureAuthError(msg, 'Adding account to cache failed', undefined);
 		}
 		try {
@@ -380,7 +380,7 @@ export abstract class AzureAuth implements vscode.Disposable {
 		const parseMsg = localize('azure.cacheErrorParse', "Error when parsing your account from the cache");
 
 		if (!tenant.id || !resource.id) {
-			Logger.pii('Tenant ID or resource ID was undefined', tenant, resource);
+			Logger.pii('Tenant ID or resource ID was undefined', [], [], tenant, resource);
 			throw new AzureAuthError(getMsg, 'Getting account from cache failed', undefined);
 		}
 
@@ -398,14 +398,15 @@ export abstract class AzureAuth implements vscode.Disposable {
 
 		try {
 			if (!accessTokenString) {
+				Logger.log('No access token found');
 				return undefined;
 			}
 			const accessToken: AccessToken = JSON.parse(accessTokenString);
 			let refreshToken: RefreshToken;
 			if (refreshTokenString) {
 				refreshToken = JSON.parse(refreshTokenString);
 			}
-
+			Logger.pii('GetSavedToken ', [{ name: 'access', objOrArray: accessToken }, { name: 'refresh', objOrArray: refreshToken }], [], `expiresOn=${expiresOn}`);
 			return {
 				accessToken, refreshToken, expiresOn
 			};
@@ -568,7 +569,7 @@ export abstract class AzureAuth implements vscode.Disposable {
 
 		// Intercept response and print out the response for future debugging
 		const response = await axios.post(url, qs.stringify(postData), config);
-		Logger.pii(url, postData, response.data);
+		Logger.pii('POST request ', [{ name: 'data', objOrArray: postData }, { name: 'response', objOrArray: response.data }], [], url);
 		return response;
 	}
 
@@ -582,7 +583,7 @@ export abstract class AzureAuth implements vscode.Disposable {
 		};
 
 		const response = await axios.get(url, config);
-		Logger.pii(url, response.data);
+		Logger.pii('GET request ', [{ name: 'response', objOrArray: response.data.value ?? response.data }], [], url,);
 		return response;
 	}
 

diff --git a/extensions/azurecore/src/account-provider/azureAccountProvider.ts b/extensions/azurecore/src/account-provider/azureAccountProvider.ts
@@ -114,6 +114,7 @@ export class AzureAccountProvider implements azdata.AccountProvider, vscode.Disp
 	private async _getAccountSecurityToken(account: AzureAccount, tenantId: string, resource: azdata.AzureResource): Promise<Token | undefined> {
 		await this.initCompletePromise;
 		const azureAuth = this.getAuthMethod(undefined);
+		Logger.pii(`Getting account security token for ${JSON.stringify(account.key)} (tenant ${tenantId}). Auth Method = ${azureAuth.userFriendlyName}`, [], []);
 		return azureAuth?.getAccountSecurityToken(account, tenantId, resource);
 	}
 

diff --git a/extensions/azurecore/src/utils/Logger.ts b/extensions/azurecore/src/utils/Logger.ts
@@ -3,21 +3,39 @@
  *  Licensed under the Source EULA. See License.txt in the project root for license information.
  *--------------------------------------------------------------------------------------------*/
 
+import * as vscode from 'vscode';
+import * as loc from '../localizedConstants';
+
 export class Logger {
+
+	public static channel: vscode.OutputChannel = vscode.window.createOutputChannel(loc.extensionName);
+
 	private static _piiLogging: boolean = false;
 
 	static log(msg: any, ...vals: any[]) {
 		const fullMessage = `${msg} - ${vals.map(v => JSON.stringify(v)).join(' - ')}`;
-		console.log(fullMessage);
+		this.channel.appendLine(fullMessage);
 	}
 
 	static error(msg: any, ...vals: any[]) {
 		const fullMessage = `${msg} - ${vals.map(v => JSON.stringify(v)).join(' - ')}`;
-		console.error(fullMessage);
+		this.channel.appendLine(fullMessage);
 	}
 
-	static pii(msg: any, ...vals: any[]) {
+	/**
+	 * 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
+	 * @param objsToSanitize Set of objects we want to sanitize
+	 * @param stringsToShorten Set of strings to shorten
+	 * @param vals Any other values to add on to the end of the log message
+	 */
+	static pii(msg: any, objsToSanitize: { name: string, objOrArray: any | any[] }[], stringsToShorten: { name: string, value: string }[], ...vals: any[]) {
 		if (this.piiLogging) {
+			msg = [
+				msg,
+				...objsToSanitize.map(obj => `${obj.name}=${sanitize(obj.objOrArray)}`),
+				...stringsToShorten.map(str => `${str.name}=${shorten(str.value)}`)
+			].join(' ');
 			Logger.log(msg, vals);
 		}
 	}
@@ -30,3 +48,52 @@ export class Logger {
 		return this._piiLogging;
 	}
 }
+
+/**
+ * Sanitizes a given object for logging to the output window, removing/shortening any PII or unneeded values
+ * @param objOrArray The object to sanitize for output logging
+ * @returns The stringified version of the sanitized object
+ */
+function sanitize(objOrArray: any): string {
+	if (Array.isArray(objOrArray)) {
+		return JSON.stringify(objOrArray.map(o => sanitizeImpl(o)));
+	} else {
+		return sanitizeImpl(objOrArray);
+	}
+}
+
+function sanitizeImpl(obj: any): string {
+	obj = Object.assign({}, obj);
+	delete obj.domains; // very long and not really useful
+	// shorten all tokens since we don't usually need the exact values and there's security concerns if they leaked
+	shortenIfExists(obj, 'token');
+	shortenIfExists(obj, 'refresh_token');
+	shortenIfExists(obj, 'access_token');
+	return JSON.stringify(obj);
+}
+
+/**
+ * Shortens the given string property on an object if it exists, otherwise does nothing
+ * @param obj The object possibly containing the property
+ * @param property The name of the property to shorten - if it exists
+ */
+function shortenIfExists(obj: any, property: string): void {
+	if (obj[property]) {
+		obj[property] = shorten(obj[property]);
+	}
+}
+
+/**
+ * Shortens a given string - if it's longer than 6 characters will return the first 3 characters
+ * followed by a ... followed by the last 3 characters. Returns the original string if 6 characters
+ * or less.
+ * @param str The string to shorten
+ * @returns Shortened string in the form 'xxx...xxx'
+ */
+function shorten(str?: string): string | undefined {
+	// Don't shorten if adding the ... wouldn't make the string shorter
+	if (!str || str.length < 10) {
+		return str;
+	}
+	return `${str.substr(0, 3)}...${str.slice(-3)}`;
+}
diff --git a/src/sql/workbench/services/accountManagement/browser/accountDialog.ts b/src/sql/workbench/services/accountManagement/browser/accountDialog.ts
@@ -305,8 +305,10 @@ export class AccountDialog extends Modal {
 	// PRIVATE HELPERS /////////////////////////////////////////////////////
 	private addProvider(newProvider: AccountProviderAddedEventParams) {
 
+		this.logService.debug(`Adding new provider ${newProvider.addedProvider.id}`);
 		// Skip adding the provider if it already exists
 		if (this._providerViewsMap.get(newProvider.addedProvider.id)) {
+			this.logService.debug(`Provider ${newProvider.addedProvider.id} is already registered!`);
 			return;
 		}
 
@@ -364,14 +366,17 @@ export class AccountDialog extends Modal {
 
 		this.layout();
 
+		this.logService.debug(`Storing view for provider ${newProvider.addedProvider.id}`);
 		// Store the view for the provider and action
 		this._providerViewsMap.set(newProvider.addedProvider.id, { view: providerView, addAccountAction: addAccountAction });
 	}
 
 	private removeProvider(removedProvider: azdata.AccountProviderMetadata) {
+		this.logService.debug(`Removing provider ${removedProvider.id}`);
 		// Skip removing the provider if it doesn't exist
 		const providerView = this._providerViewsMap.get(removedProvider.id);
 		if (!providerView || !providerView.view) {
+			this.logService.warn(`Provider ${removedProvider.id} doesn't exist while removing`);
 			return;
 		}
 
@@ -381,6 +386,7 @@ export class AccountDialog extends Modal {
 
 		// Remove the list view from our internal map
 		this._providerViewsMap.delete(removedProvider.id);
+		this.logService.debug(`Provider ${removedProvider.id} removed`);
 		this.layout();
 	}
 
@@ -427,8 +433,8 @@ export class AccountDialog extends Modal {
 	}
 
 	private async runAddAccountAction() {
+		this.logService.debug(`Adding account - providers ${JSON.stringify(Iterable.consume(this._providerViewsMap.keys()))}`);
 		const vals = Iterable.consume(this._providerViewsMap.values())[0];
-
 		let pickedValue: string | undefined;
 		if (vals.length === 0) {
 			this._notificationService.error(localize('accountDialog.noCloudsRegistered', "You have no clouds enabled. Go to Settings -> Search Azure Account Configuration -> Enable at least one cloud"));