Log commands run by the discovery component in the output channel (#17670)

* Log commands run by the discovery component in the output channel

* Remove outdated comments

Author: Kartik Raj

news/3 Code Health/16732.md

@@ -0,0 +1 @@
+Log commands run by the discovery component in the output channel.

src/client/common/configSettings.ts

@@ -16,7 +16,6 @@ import {
 import { LanguageServerType } from '../activation/types';
 import './extensions';
 import { IInterpreterAutoSelectionProxyService } from '../interpreter/autoSelection/types';
-import { LogLevel } from '../logging/levels';
 import { sendTelemetryEvent } from '../telemetry';
 import { EventName } from '../telemetry/constants';
 import { sendSettingTelemetry } from '../telemetry/envFileTelemetry';
@@ -36,12 +35,10 @@ import {
     IFormattingSettings,
     IInterpreterPathService,
     ILintingSettings,
-    ILoggingSettings,
     IPythonSettings,
     ISortImportSettings,
     ITensorBoardSettings,
     ITerminalSettings,
-    LoggingLevelSettingType,
     Resource,
 } from './types';
 import { debounceSync } from './utils/decorators';
@@ -137,8 +134,6 @@ export class PythonSettings implements IPythonSettings {
 
     public languageServerIsDefault = true;
 
-    public logging: ILoggingSettings = { level: LogLevel.Error };
-
     protected readonly changed = new EventEmitter<void>();
 
     private workspaceRoot: Resource;
@@ -305,15 +300,6 @@ export class PythonSettings implements IPythonSettings {
         this.devOptions = systemVariables.resolveAny(pythonSettings.get<any[]>('devOptions'))!;
         this.devOptions = Array.isArray(this.devOptions) ? this.devOptions : [];
 
-        // eslint-disable-next-line @typescript-eslint/no-explicit-any
-        const loggingSettings = systemVariables.resolveAny(pythonSettings.get<any>('logging'))!;
-        loggingSettings.level = convertSettingTypeToLogLevel(loggingSettings.level);
-        if (this.logging) {
-            Object.assign<ILoggingSettings, ILoggingSettings>(this.logging, loggingSettings);
-        } else {
-            this.logging = loggingSettings;
-        }
-
         const lintingSettings = systemVariables.resolveAny(pythonSettings.get<ILintingSettings>('linting'))!;
         if (this.linting) {
             Object.assign<ILintingSettings, ILintingSettings>(this.linting, lintingSettings);
@@ -709,23 +695,3 @@ function isValidPythonPath(pythonPath: string): boolean {
         path.basename(getOSType() === OSType.Windows ? pythonPath.toLowerCase() : pythonPath).startsWith('python')
     );
 }
-
-function convertSettingTypeToLogLevel(setting: LoggingLevelSettingType | undefined): LogLevel | 'off' {
-    switch (setting) {
-        case 'info': {
-            return LogLevel.Info;
-        }
-        case 'warn': {
-            return LogLevel.Warn;
-        }
-        case 'off': {
-            return 'off';
-        }
-        case 'debug': {
-            return LogLevel.Debug;
-        }
-        default: {
-            return LogLevel.Error;
-        }
-    }
-}

src/client/common/platform/fs-paths.ts

@@ -134,9 +134,9 @@ export class FileSystemPathUtils implements IFileSystemPathUtils {
     }
 
     public getDisplayName(filename: string, cwd?: string): string {
-        if (cwd && filename.startsWith(cwd)) {
+        if (cwd && isParentPath(filename, cwd)) {
             return `.${this.paths.sep}${this.raw.relative(cwd, filename)}`;
-        } else if (filename.startsWith(this.home)) {
+        } else if (isParentPath(filename, this.home)) {
             return `~${this.paths.sep}${this.raw.relative(this.home, filename)}`;
         } else {
             return filename;
@@ -154,6 +154,12 @@ export function normCasePath(filePath: string): string {
  * @param parentPath The potential parent path to check for
  */
 export function isParentPath(filePath: string, parentPath: string): boolean {
+    if (!parentPath.endsWith(nodepath.sep)) {
+        parentPath += nodepath.sep;
+    }
+    if (!filePath.endsWith(nodepath.sep)) {
+        filePath += nodepath.sep;
+    }
     return normCasePath(filePath).startsWith(normCasePath(parentPath));
 }
 

src/client/common/process/logger.ts

@@ -17,22 +17,26 @@ export class ProcessLogger implements IProcessLogger {
         @inject(IPathUtils) private readonly pathUtils: IPathUtils,
     ) {}
 
-    public logProcess(file: string, args: string[], options?: SpawnOptions) {
+    public logProcess(fileOrCommand: string, args?: string[], options?: SpawnOptions) {
         if (!isTestExecution() && isCI && process.env.UITEST_DISABLE_PROCESS_LOGGING) {
             // Added to disable logging of process execution commands during UI Tests.
             // Used only during UI Tests (hence this setting need not be exposed as a valid setting).
             return;
         }
-        const argsList = args.reduce((accumulator, current, index) => {
-            let formattedArg = this.pathUtils.getDisplayName(current).toCommandArgument();
-            if (current[0] === "'" || current[0] === '"') {
-                formattedArg = `${current[0]}${this.pathUtils.getDisplayName(current.substr(1))}`;
-            }
-
+        // Note: Single quotes maybe converted to double quotes for printing purposes.
+        let commandList: string[];
+        if (!args) {
+            // It's a quoted command.
+            commandList = fileOrCommand.split('" "').map((s) => s.trimQuotes());
+        } else {
+            commandList = [fileOrCommand, ...args].map((s) => s.trimQuotes());
+        }
+        const command = commandList.reduce((accumulator, current, index) => {
+            const formattedArg = this.pathUtils.getDisplayName(current).toCommandArgument();
             return index === 0 ? formattedArg : `${accumulator} ${formattedArg}`;
         }, '');
 
-        const info = [`> ${this.pathUtils.getDisplayName(file)} ${argsList}`];
+        const info = [`> ${command}`];
         if (options && options.cwd) {
             info.push(`${Logging.currentWorkingDirectory()} ${this.pathUtils.getDisplayName(options.cwd)}`);
         }

src/client/common/process/proc.ts

@@ -58,6 +58,7 @@ export class ProcessService extends EventEmitter implements IProcessService {
     }
 
     public shellExec(command: string, options: ShellOptions = {}): Promise<ExecutionResult<string>> {
+        this.emit('exec', command, undefined, options);
         return shellExec(command, options, this.env, this.processesToKill);
     }
 }

src/client/common/process/types.ts

@@ -40,7 +40,12 @@ export type ExecutionResult<T extends string | Buffer> = {
 
 export const IProcessLogger = Symbol('IProcessLogger');
 export interface IProcessLogger {
-    logProcess(file: string, ars: string[], options?: SpawnOptions): void;
+    /**
+     * Pass `args` as `undefined` if first argument is supposed to be a shell command.
+     * Note it is assumed that command args are always quoted and respect
+     * `String.prototype.toCommandArgument()` prototype.
+     */
+    logProcess(fileOrCommand: string, args?: string[], options?: SpawnOptions): void;
 }
 
 export interface IProcessService extends IDisposable {

src/client/common/types.ts

@@ -19,7 +19,6 @@ import {
     WorkspaceEdit,
 } from 'vscode';
 import { LanguageServerType } from '../activation/types';
-import { LogLevel } from '../logging/levels';
 import type { ExtensionChannels } from './insidersBuild/types';
 import type { InterpreterUri, ModuleInstallFlags } from './installer/types';
 import { EnvironmentVariables } from './variables/types';
@@ -189,7 +188,6 @@ export interface IPythonSettings {
     readonly languageServer: LanguageServerType;
     readonly languageServerIsDefault: boolean;
     readonly defaultInterpreterPath: string;
-    readonly logging: ILoggingSettings;
     readonly tensorBoard: ITensorBoardSettings | undefined;
     initialize(): void;
 }
@@ -224,11 +222,6 @@ export interface IMypyCategorySeverity {
     readonly note: DiagnosticSeverity;
 }
 
-export type LoggingLevelSettingType = 'off' | 'error' | 'warn' | 'info' | 'debug';
-
-export interface ILoggingSettings {
-    readonly level: LogLevel | 'off';
-}
 export interface ILintingSettings {
     readonly enabled: boolean;
     readonly ignorePatterns: string[];

src/client/extensionActivation.ts

@@ -46,6 +46,7 @@ import * as pythonEnvironments from './pythonEnvironments';
 import { ActivationResult, ExtensionState } from './components';
 import { Components } from './extensionInit';
 import { setDefaultLanguageServer } from './activation/common/defaultlanguageServer';
+import { getLoggingLevel } from './logging/settings';
 
 export async function activateComponents(
     // `ext` is passed to any extra activation funcs.
@@ -111,12 +112,13 @@ async function activateLegacy(ext: ExtensionState): Promise<ActivationResult> {
     const extensions = serviceContainer.get<IExtensions>(IExtensions);
     await setDefaultLanguageServer(extensions, serviceManager);
 
-    const configuration = serviceManager.get<IConfigurationService>(IConfigurationService);
-    // We should start logging using the log level as soon as possible, so set it as soon as we can access the level.
-    // `IConfigurationService` may depend any of the registered types, so doing it after all registrations are finished.
-    // XXX Move this *after* abExperiments is activated?
-    setLoggingLevel(configuration.getSettings().logging.level);
+    // Note we should not trigger any extension related code which logs, until we have set logging level. So we cannot
+    // use configurations service to get level setting. Instead, we use Workspace service to query for setting as it
+    // directly queries VSCode API.
+    setLoggingLevel(getLoggingLevel());
 
+    // `IConfigurationService` may depend any of the registered types, so doing it after all registrations are finished.
+    const configuration = serviceManager.get<IConfigurationService>(IConfigurationService);
     const languageServerType = configuration.getSettings().languageServer;
 
     // Language feature registrations.

src/client/logging/settings.ts

@@ -0,0 +1,38 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+'use strict';
+
+import { WorkspaceService } from '../common/application/workspace';
+import { LogLevel } from './levels';
+
+type LoggingLevelSettingType = 'off' | 'error' | 'warn' | 'info' | 'debug';
+
+/**
+ * Uses Workspace service to query for `python.logging.level` setting and returns it.
+ */
+export function getLoggingLevel(): LogLevel | 'off' {
+    const workspace = new WorkspaceService();
+    const value = workspace.getConfiguration('python').get<LoggingLevelSettingType>('logging.level');
+    return convertSettingTypeToLogLevel(value);
+}
+
+function convertSettingTypeToLogLevel(setting: LoggingLevelSettingType | undefined): LogLevel | 'off' {
+    switch (setting) {
+        case 'info': {
+            return LogLevel.Info;
+        }
+        case 'warn': {
+            return LogLevel.Warn;
+        }
+        case 'off': {
+            return 'off';
+        }
+        case 'debug': {
+            return LogLevel.Debug;
+        }
+        default: {
+            return LogLevel.Error;
+        }
+    }
+}

src/client/pythonEnvironments/base/info/interpreter.ts

@@ -73,7 +73,7 @@ export async function getInterpreterInfo(python: PythonExecInfo): Promise<Interp
     const argv = [info.command, ...info.args];
 
     // Concat these together to make a set of quoted strings
-    const quoted = argv.reduce((p, c) => (p ? `${p} "${c}"` : `"${c.replace('\\', '\\\\')}"`), '');
+    const quoted = argv.reduce((p, c) => (p ? `${p} "${c}"` : `"${c}"`), '');
 
     // Try shell execing the command, followed by the arguments. This will make node kill the process if it
     // takes too long.

src/client/pythonEnvironments/common/environmentManagers/conda.ts

@@ -9,7 +9,6 @@ import { parseVersion } from '../../base/info/pythonVersion';
 
 import { getRegistryInterpreters } from '../windowsUtils';
 import { EnvironmentType, PythonEnvironment } from '../../info';
-import { IDisposable } from '../../../common/types';
 import { cache } from '../../../common/utils/decorators';
 import { isTestExecution } from '../../../common/constants';
 
@@ -353,19 +352,8 @@ export class Conda {
     @cache(30_000, true, 10_000)
     // eslint-disable-next-line class-methods-use-this
     private async getInfoCached(command: string): Promise<CondaInfo> {
-        const disposables = new Set<IDisposable>();
-        const result = await exec(command, ['info', '--json'], { timeout: 50000 }, disposables);
+        const result = await exec(command, ['info', '--json'], { timeout: 50000 });
         traceVerbose(`conda info --json: ${result.stdout}`);
-
-        // Ensure the process we started is cleaned up.
-        disposables.forEach((p) => {
-            try {
-                p.dispose();
-            } catch {
-                // ignore.
-            }
-        });
-
         return JSON.parse(result.stdout);
     }
 

src/client/pythonEnvironments/common/externalDependencies.ts

@@ -4,14 +4,12 @@
 import * as fsapi from 'fs-extra';
 import * as path from 'path';
 import * as vscode from 'vscode';
-import { ExecutionResult, ShellOptions, SpawnOptions } from '../../common/process/types';
+import { ExecutionResult, IProcessServiceFactory, ShellOptions, SpawnOptions } from '../../common/process/types';
 import { IExperimentService, IDisposable, IConfigurationService } from '../../common/types';
 import { chain, iterable } from '../../common/utils/async';
 import { normalizeFilename } from '../../common/utils/filesystem';
 import { getOSType, OSType } from '../../common/utils/platform';
 import { IServiceContainer } from '../../ioc/types';
-import { plainExec, shellExec } from '../../common/process/rawProcessApis';
-import { BufferDecoder } from '../../common/process/decoder';
 
 let internalServiceContainer: IServiceContainer;
 export function initializeExternalDependencies(serviceContainer: IServiceContainer): void {
@@ -20,39 +18,14 @@ export function initializeExternalDependencies(serviceContainer: IServiceContain
 
 // processes
 
-/**
- * Specialized version of the more generic shellExecute function to use only in
- * cases where we don't need to pass custom environment variables read from env
- * files or execution options.
- *
- * Also ensures to kill the processes created after execution.
- */
 export async function shellExecute(command: string, options: ShellOptions = {}): Promise<ExecutionResult<string>> {
-    const disposables = new Set<IDisposable>();
-    return shellExec(command, options, undefined, disposables).finally(() => {
-        // Ensure the process we started is cleaned up.
-        disposables.forEach((p) => {
-            try {
-                p.dispose();
-            } catch {
-                // ignore.
-            }
-        });
-    });
+    const service = await internalServiceContainer.get<IProcessServiceFactory>(IProcessServiceFactory).create();
+    return service.shellExec(command, options);
 }
 
-/**
- * Specialized version of the more generic exec function to use only in
- * cases where we don't need to pass custom environment variables read from
- * env files.
- */
-export async function exec(
-    file: string,
-    args: string[],
-    options: SpawnOptions = {},
-    disposables?: Set<IDisposable>,
-): Promise<ExecutionResult<string>> {
-    return plainExec(file, args, options, new BufferDecoder(), undefined, disposables);
+export async function exec(file: string, args: string[], options: SpawnOptions = {}): Promise<ExecutionResult<string>> {
+    const service = await internalServiceContainer.get<IProcessServiceFactory>(IProcessServiceFactory).create();
+    return service.exec(file, args, options);
 }
 
 // filesystem

src/test/common/configSettings/configSettings.unit.test.ts

@@ -18,7 +18,6 @@ import {
     IExperiments,
     IFormattingSettings,
     ILintingSettings,
-    ILoggingSettings,
     ISortImportSettings,
     ITerminalSettings,
 } from '../../../client/common/types';
@@ -97,7 +96,6 @@ suite('Python Settings', async () => {
         config.setup((c) => c.get<any[]>('devOptions')).returns(() => sourceSettings.devOptions);
 
         // complex settings
-        config.setup((c) => c.get<ILoggingSettings>('logging')).returns(() => sourceSettings.logging);
         config.setup((c) => c.get<ILintingSettings>('linting')).returns(() => sourceSettings.linting);
         config.setup((c) => c.get<IAnalysisSettings>('analysis')).returns(() => sourceSettings.analysis);
         config.setup((c) => c.get<ISortImportSettings>('sortImports')).returns(() => sourceSettings.sortImports);