Add diagnostic logging option to help with advanced troubleshooting (#…

…3809)

* Add diagnostic logging option to help troubleshoot issues

* Use LogOutputChannel implementation

* More diagnostic logging tweaks

* Fix linting errors

* Remove redundant warning label from log output

* Respond to PR comments

* Additional diagnostics refactor

* Refactor to allow logging system info once and only once when debug logging is enabled

* Refactor to move diagnostics out of the runtime code

* More changes for PR

* Use similar pattern for onCommand callback

package.json

@@ -2894,7 +2894,7 @@
         ]
     },
     "engines": {
-        "vscode": "^1.67.0"
+        "vscode": "^1.74.0"
     },
     "capabilities": {
         "virtualWorkspaces": false,
@@ -2939,7 +2939,7 @@
         "@types/node": "16.x",
         "@types/node-fetch": "^2.5.12",
         "@types/semver": "^7.3.9",
-        "@types/vscode": "1.67.0",
+        "@types/vscode": "1.74.0",
         "@types/xml2js": "^0.4.8",
         "@typescript-eslint/eslint-plugin": "^5.19.0",
         "@typescript-eslint/parser": "^5.19.0",

src/commands/registries/azure/DockerAssignAcrPullRoleStep.ts

@@ -22,7 +22,7 @@ export class DockerAssignAcrPullRoleStep extends AzureWizardExecuteStep<IAppServ
 
     public async execute(context: IAppServiceWizardContext, progress: Progress<{ message?: string; increment?: number }>): Promise<void> {
         const message: string = localize('vscode-docker.commands.registries.azure.deployImage.assigningPullRole', 'Granting permission for App Service to pull image from ACR...');
-        ext.outputChannel.appendLine(message);
+        ext.outputChannel.info(message);
         progress.report({ message: message });
 
         const azExtAzureUtils = await getAzExtAzureUtils();

src/commands/registries/azure/DockerSiteCreateStep.ts

@@ -29,7 +29,7 @@ export class DockerSiteCreateStep extends AzureWizardExecuteStep<IAppServiceCont
 
     public async execute(context: IAppServiceContainerWizardContext, progress: Progress<{ message?: string; increment?: number }>): Promise<void> {
         const creatingNewApp: string = localize('vscode-docker.commands.registries.azure.deployImage.creatingWebApp', 'Creating web app "{0}"...', context.newSiteName);
-        ext.outputChannel.appendLine(creatingNewApp);
+        ext.outputChannel.info(creatingNewApp);
         progress.report({ message: creatingNewApp });
         const siteConfig = await this.getNewSiteConfig(context);
 

src/commands/registries/azure/DockerWebhookCreateStep.ts

@@ -37,10 +37,10 @@ export class DockerWebhookCreateStep extends AzureWizardExecuteStep<IAppServiceW
         const appUri: string = (await siteClient.getWebAppPublishCredential()).scmUri;
         if (this._treeItem.parent instanceof AzureRepositoryTreeItem) {
             const creatingNewWebhook: string = localize('vscode-docker.commands.registries.azure.dockerWebhook.creatingWebhook', 'Creating webhook for web app "{0}"...', context.newSiteName);
-            ext.outputChannel.appendLine(creatingNewWebhook);
+            ext.outputChannel.info(creatingNewWebhook);
             progress.report({ message: creatingNewWebhook });
             const webhook = await this.createWebhookForApp(context, this._treeItem, context.site, appUri);
-            ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.dockerWebhook.createdWebhook', 'Created webhook "{0}" with scope "{1}", id: "{2}" and location: "{3}"', webhook.name, webhook.scope, webhook.id, webhook.location));
+            ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.dockerWebhook.createdWebhook', 'Created webhook "{0}" with scope "{1}", id: "{2}" and location: "{3}"', webhook.name, webhook.scope, webhook.id, webhook.location));
         } else if (this._treeItem.parent instanceof DockerHubRepositoryTreeItem) {
             // point to dockerhub to create a webhook
             // http://cloud.docker.com/repository/docker/<registryName>/<repoName>/webHooks

src/commands/registries/azure/deployImageToAzure.ts

@@ -67,7 +67,7 @@ export async function deployImageToAzure(context: IActionContext, node?: RemoteT
     const site: Site = nonNullProp(wizardContext, 'site');
     const siteUri: string = `https://${site.defaultHostName}`;
     const createdNewWebApp: string = localize('vscode-docker.commands.registries.azure.deployImage.created', 'Successfully created web app "{0}": {1}', site.name, siteUri);
-    ext.outputChannel.appendLine(createdNewWebApp);
+    ext.outputChannel.info(createdNewWebApp);
 
     const openSite: string = localize('vscode-docker.commands.registries.azure.deployImage.openSite', 'Open Site');
     // don't wait

src/commands/registries/azure/tasks/scheduleRunRequest.ts

@@ -65,7 +65,7 @@ export async function scheduleRunRequest(context: IActionContext, requestType: '
         }
 
         const uploadedSourceLocation: string = await uploadSourceCode(await node.getClient(context), node.registryName, node.resourceGroup, rootUri, tarFilePath);
-        ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.uploaded', 'Uploaded source code from {0}', tarFilePath));
+        ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.uploaded', 'Uploaded source code from {0}', tarFilePath));
 
         let runRequest: AcrDockerBuildRequest | AcrFileTaskRunRequest;
         if (requestType === 'DockerBuildRequest') {
@@ -87,11 +87,11 @@ export async function scheduleRunRequest(context: IActionContext, requestType: '
         }
 
         // Schedule the run and Clean up.
-        ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.setUp', 'Set up run request'));
+        ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.setUp', 'Set up run request'));
 
         const client = await node.getClient(context);
         const run = await client.registries.beginScheduleRunAndWait(node.resourceGroup, node.registryName, runRequest);
-        ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.scheduledRun', 'Scheduled run {0}', run.runId));
+        ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.scheduledRun', 'Scheduled run {0}', run.runId));
 
         void streamLogs(context, node, run);
 
@@ -134,21 +134,21 @@ async function quickPickImageName(context: IActionContext, rootFolder: vscode.Wo
 }
 
 async function uploadSourceCode(client: ContainerRegistryManagementClient, registryName: string, resourceGroupName: string, rootFolder: vscode.Uri, tarFilePath: string): Promise<string> {
-    ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.sendingSource', '   Sending source code to temp file'));
+    ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.sendingSource', '   Sending source code to temp file'));
     const source: string = rootFolder.fsPath;
     let items = await fse.readdir(source);
     items = items.filter(i => !(i in vcsIgnoreList));
     // tslint:disable-next-line:no-unsafe-any
     tar.c({ cwd: source }, items).pipe(fse.createWriteStream(tarFilePath));
 
-    ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.gettingBuildSourceUploadUrl', '   Getting build source upload URL'));
+    ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.gettingBuildSourceUploadUrl', '   Getting build source upload URL'));
     const sourceUploadLocation = await client.registries.getBuildSourceUploadUrl(resourceGroupName, registryName);
     const uploadUrl: string = sourceUploadLocation.uploadUrl;
     const relativePath: string = sourceUploadLocation.relativePath;
 
     const storageBlob = await getStorageBlob();
     const blobClient = new storageBlob.BlockBlobClient(uploadUrl);
-    ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.creatingBlockBlob', '   Creating block blob'));
+    ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.creatingBlockBlob', '   Creating block blob'));
     await blobClient.uploadFile(tarFilePath);
 
     return relativePath;
@@ -185,7 +185,7 @@ async function streamLogs(context: IActionContext, node: AzureRegistryTreeItem,
                 const content = bufferToString(contentBuffer);
 
                 if (content) {
-                    ext.outputChannel.appendLine(content);
+                    ext.outputChannel.info(content);
                 }
 
                 if (properties?.metadata?.complete) {
@@ -202,7 +202,7 @@ function getTempSourceArchivePath(): string {
     /* tslint:disable-next-line:insecure-random */
     const id: number = Math.floor(Math.random() * Math.pow(10, idPrecision));
     const archive = `sourceArchive${id}.tar.gz`;
-    ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.azure.tasks.settingUpTempFile', 'Setting up temp file with \'{0}\'', archive));
+    ext.outputChannel.info(localize('vscode-docker.commands.registries.azure.tasks.settingUpTempFile', 'Setting up temp file with \'{0}\'', archive));
     const tarFilePath: string = path.join(os.tmpdir(), archive);
     return tarFilePath;
 }

src/commands/registries/logInToDockerCli.ts

@@ -30,7 +30,7 @@ export async function logInToDockerCli(context: IActionContext, node?: RegistryT
     }
 
     if (!username || !password) {
-        ext.outputChannel.appendLine(localize('vscode-docker.commands.registries.logIn.skipping', 'WARNING: Skipping login for "{0}" because it does not require authentication.', creds.registryPath));
+        ext.outputChannel.warn(localize('vscode-docker.commands.registries.logIn.skipping', 'Skipping login for "{0}" because it does not require authentication.', creds.registryPath));
     } else {
         const progressOptions: vscode.ProgressOptions = {
             location: vscode.ProgressLocation.Notification,
@@ -49,7 +49,7 @@ export async function logInToDockerCli(context: IActionContext, node?: RegistryT
                         stdInPipe: stream.Readable.from(password),
                     }
                 );
-                ext.outputChannel.appendLine('Login succeeded.');
+                ext.outputChannel.info('Login succeeded.');
             } catch (err) {
                 const error = parseError(err);
 

src/debugging/DockerDebugConfigurationProvider.ts

@@ -163,8 +163,8 @@ export class DockerDebugConfigurationProvider implements DebugConfigurationProvi
                 }
 
                 if (portMappings.length > 0) {
-                    ext.outputChannel.appendLine(localize('vscode-docker.debug.configProvider.portMappings', 'The application is listening on the following port(s) (Host => Container):'));
-                    ext.outputChannel.appendLine(portMappings.join('\n'));
+                    ext.outputChannel.info(localize('vscode-docker.debug.configProvider.portMappings', 'The application is listening on the following port(s) (Host => Container):'));
+                    ext.outputChannel.info(portMappings.join('\n'));
                 }
             } catch {
                 // Best effort

src/debugging/netcore/VsDbgHelper.ts

@@ -65,11 +65,11 @@ async function getLatestAcquisitionScriptIfNecessary(): Promise<boolean> {
         return false;
     }
 
-    ext.outputChannel.appendLine(localize('vscode-docker.debugging.netCore.vsDbgHelper.acquiringScript', 'Acquiring latest VsDbg install script...'));
+    ext.outputChannel.info(localize('vscode-docker.debugging.netCore.vsDbgHelper.acquiringScript', 'Acquiring latest VsDbg install script...'));
     await streamToFile(acquisition.url, acquisition.scriptPath);
 
     await ext.context.globalState.update(scriptAcquiredDateKey, Date.now());
-    ext.outputChannel.appendLine(localize('vscode-docker.debugging.netCore.vsDbgHelper.scriptAcquired', 'Script acquired.'));
+    ext.outputChannel.info(localize('vscode-docker.debugging.netCore.vsDbgHelper.scriptAcquired', 'Script acquired.'));
     return true;
 }
 
@@ -85,13 +85,13 @@ async function executeAcquisitionScriptIfNecessary(runtime: VsDbgRuntime, versio
 
     const command = acquisition.getShellCommand(runtime, version);
 
-    ext.outputChannel.appendLine(localize('vscode-docker.debugging.netCore.vsDbgHelper.installingDebugger', 'Installing VsDbg, Runtime = {0}, Version = {1}...', runtime, version));
-    ext.outputChannel.appendLine(command);
+    ext.outputChannel.info(localize('vscode-docker.debugging.netCore.vsDbgHelper.installingDebugger', 'Installing VsDbg, Runtime = {0}, Version = {1}...', runtime, version));
+    ext.outputChannel.info(command);
 
     await execAsync(command, {}, (output: string) => {
-        ext.outputChannel.append(output);
+        ext.outputChannel.info(output);
     });
 
     await ext.context.globalState.update(scriptExecutedDateKey, Date.now());
-    ext.outputChannel.appendLine(localize('vscode-docker.debugging.netCore.vsDbgHelper.debuggerInstalled', 'VsDbg installed, Runtime = {0}, Version = {1}...', runtime, version));
+    ext.outputChannel.info(localize('vscode-docker.debugging.netCore.vsDbgHelper.debuggerInstalled', 'VsDbg installed, Runtime = {0}, Version = {1}...', runtime, version));
 }

src/extension.ts

@@ -4,7 +4,7 @@
  *--------------------------------------------------------------------------------------------*/
 
 import { TelemetryEvent } from '@microsoft/compose-language-service/lib/client/TelemetryEvent';
-import { IActionContext, UserCancelledError, callWithTelemetryAndErrorHandling, createAzExtOutputChannel, createExperimentationService, registerErrorHandler, registerEvent, registerReportIssueCommand, registerUIExtensionVariables } from '@microsoft/vscode-azext-utils';
+import { IActionContext, UserCancelledError, callWithTelemetryAndErrorHandling, createExperimentationService, registerErrorHandler, registerEvent, registerReportIssueCommand, registerUIExtensionVariables } from '@microsoft/vscode-azext-utils';
 import * as path from 'path';
 import * as vscode from 'vscode';
 import { ConfigurationParams, DidChangeConfigurationNotification, DocumentSelector, LanguageClient, LanguageClientOptions, Middleware, ServerOptions, TransportKind } from 'vscode-languageclient/node';
@@ -26,6 +26,8 @@ import { ContainerRuntimeManager } from './runtimes/ContainerRuntimeManager';
 import { OrchestratorRuntimeManager } from './runtimes/OrchestratorRuntimeManager';
 import { AutoConfigurableDockerClient } from './runtimes/clients/AutoConfigurableDockerClient';
 import { AutoConfigurableDockerComposeClient } from './runtimes/clients/AutoConfigurableDockerComposeClient';
+import { AzExtLogOutputChannelWrapper } from './utils/AzExtLogOutputChannelWrapper';
+import { logDockerEnvironment, logSystemInfo } from './utils/diagnostics';
 
 export type KeyInfo = { [keyName: string]: string };
 
@@ -42,10 +44,11 @@ const DOCUMENT_SELECTOR: DocumentSelector = [
     { language: 'dockerfile', scheme: 'file' }
 ];
 
+
 function initializeExtensionVariables(ctx: vscode.ExtensionContext): void {
     ext.context = ctx;
 
-    ext.outputChannel = createAzExtOutputChannel('Docker', ext.prefix);
+    ext.outputChannel = new AzExtLogOutputChannelWrapper(vscode.window.createOutputChannel('Docker', { log: true }), ext.prefix);
     ctx.subscriptions.push(ext.outputChannel);
 
     registerUIExtensionVariables(ext);
@@ -68,6 +71,8 @@ export async function activateInternal(ctx: vscode.ExtensionContext, perfStats:
             process.env.VSCODE_DOCKER_TEAM === '1' ? tas.TargetPopulation.Team : undefined // If VSCODE_DOCKER_TEAM isn't set, let @microsoft/vscode-azext-utils decide target population
         );
 
+        logSystemInfo(ext.outputChannel);
+
         // Disabled for now
         // (new SurveyManager()).activate();
 
@@ -151,6 +156,7 @@ function registerEnvironmentVariableContributions(): void {
         actionContext.errorHandling.suppressDisplay = true;
 
         if (e.affectsConfiguration('docker.environment')) {
+            logDockerEnvironment(ext.outputChannel);
             setEnvironmentVariableContributions();
         }
     });

src/extensionVariables.ts

@@ -3,7 +3,7 @@
  *  Licensed under the MIT License. See LICENSE.md in the project root for license information.
  *--------------------------------------------------------------------------------------------*/
 
-import { AzExtTreeDataProvider, AzExtTreeItem, IAzExtOutputChannel, IExperimentationServiceAdapter } from '@microsoft/vscode-azext-utils';
+import { AzExtTreeDataProvider, AzExtTreeItem, IExperimentationServiceAdapter } from '@microsoft/vscode-azext-utils';
 import { ExtensionContext, TreeView } from 'vscode';
 import { ContainerRuntimeManager } from './runtimes/ContainerRuntimeManager';
 import { IActivityMeasurementService } from './telemetry/ActivityMeasurementService';
@@ -15,14 +15,15 @@ import { RegistriesTreeItem } from './tree/registries/RegistriesTreeItem';
 import { VolumesTreeItem } from './tree/volumes/VolumesTreeItem';
 import { OrchestratorRuntimeManager } from './runtimes/OrchestratorRuntimeManager';
 import { runWithDefaults as runWithDefaultsImpl, streamWithDefaults as streamWithDefaultsImpl } from './runtimes/runners/runWithDefaults';
+import { AzExtLogOutputChannelWrapper } from './utils/AzExtLogOutputChannelWrapper';
 
 /**
  * Namespace for common variables used throughout the extension. They must be initialized in the activate() method of extension.ts
  */
 // eslint-disable-next-line @typescript-eslint/no-namespace
 export namespace ext {
     export let context: ExtensionContext;
-    export let outputChannel: IAzExtOutputChannel;
+    export let outputChannel: AzExtLogOutputChannelWrapper;
 
     export let experimentationService: IExperimentationServiceAdapter;
     export let activityMeasurementService: IActivityMeasurementService;

src/runtimes/clients/AutoConfigurableDockerClient.ts

@@ -4,6 +4,8 @@
  *--------------------------------------------------------------------------------------------*/
 
 import * as vscode from 'vscode';
+import { ext } from '../../extensionVariables';
+import { logCommandPath } from '../../utils/diagnostics';
 import { DockerClient } from '../docker';
 import { AutoConfigurableClient } from './AutoConfigurableClient';
 
@@ -17,5 +19,9 @@ export class AutoConfigurableDockerClient extends DockerClient implements AutoCo
         const config = vscode.workspace.getConfiguration('docker');
         const dockerCommand = config.get<string | undefined>('dockerPath') || 'docker';
         this.commandName = dockerCommand;
+
+        ext.outputChannel.debug(`docker.dockerPath: ${this.commandName}`);
+
+        logCommandPath(ext.outputChannel, this.commandName);
     }
 }

src/runtimes/clients/AutoConfigurableDockerComposeClient.ts

@@ -57,7 +57,7 @@ export class AutoConfigurableDockerComposeClient extends DockerComposeClient imp
             // User has not set a compose command, so we will attempt to autodetect it
 
             try {
-                ext.outputChannel.appendLine('Attempting to autodetect Docker Compose command...');
+                ext.outputChannel.info('Attempting to autodetect Docker Compose command...');
                 await execAsync('docker compose version');
 
                 // If successful, then assume we can use compose V2