Improvements to logging (#8098)

.eslintrc.js

@@ -491,7 +491,6 @@ module.exports = {
         'src/client/common/platform/serviceRegistry.ts',
         'src/client/common/platform/errors.ts',
         'src/client/common/platform/fs-temp.ts',
-        'src/client/common/platform/fs-paths.ts',
         'src/client/common/platform/constants.ts',
         'src/client/common/platform/fileSystem.ts',
         'src/client/common/platform/registry.ts',
@@ -708,8 +707,6 @@ module.exports = {
         'src/client/logging/levels.ts',
         'src/client/logging/transports.ts',
         'src/client/logging/util.ts',
-        'src/client/logging/formatters.ts',
-        'src/client/logging/trace.ts',
         'src/client/ioc/serviceManager.ts',
         'src/client/ioc/container.ts',
         'src/client/ioc/types.ts',

src/client/api/pythonApi.ts

@@ -19,6 +19,7 @@ import { trackPackageInstalledIntoInterpreter } from '../common/installer/produc
 import { ProductNames } from '../common/installer/productNames';
 import { InterpreterUri } from '../common/installer/types';
 import { traceInfo, traceInfoIfCI } from '../common/logger';
+import { getDisplayPath } from '../common/platform/fs-paths';
 import {
     GLOBAL_MEMENTO,
     IDisposableRegistry,
@@ -379,7 +380,11 @@ export class InterpreterService implements IInterpreterService {
                 if (isCI) {
                     promise
                         .then((item) =>
-                            traceInfo(`Active Interpreter in Python API for ${resource?.toString()} is ${item?.path}`)
+                            traceInfo(
+                                `Active Interpreter in Python API for ${resource?.toString()} is ${getDisplayPath(
+                                    item?.path
+                                )}`
+                            )
                         )
                         .catch(noop);
                 }

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

@@ -2,6 +2,7 @@
 // Licensed under the MIT License.
 
 import * as nodepath from 'path';
+import { Uri } from 'vscode';
 import { getOSType, OSType } from '../utils/platform';
 import { IExecutables, IFileSystemPaths, IFileSystemPathUtils } from './types';
 // eslint-disable-next-line @typescript-eslint/no-var-requires, @typescript-eslint/no-require-imports
@@ -142,3 +143,24 @@ export class FileSystemPathUtils implements IFileSystemPathUtils {
         }
     }
 }
+
+const homePath = untildify('~');
+export function getDisplayPath(filename?: string | Uri) {
+    let file = '';
+    if (typeof filename === 'string') {
+        file = filename;
+    } else if (!filename) {
+        file = '';
+    } else if (filename.scheme === 'file') {
+        file = filename.fsPath;
+    } else {
+        file = filename.toString();
+    }
+    if (!file) {
+        return '';
+    } else if (file.startsWith(homePath)) {
+        return `~${nodepath.sep}${nodepath.relative(homePath, file)}`;
+    } else {
+        return file;
+    }
+}

src/client/common/process/baseDaemon.ts

@@ -10,7 +10,7 @@ import * as util from 'util';
 import { MessageConnection, NotificationType, RequestType, RequestType0 } from 'vscode-jsonrpc';
 import { IPlatformService } from '../../common/platform/types';
 import { BaseError } from '../errors/types';
-import { traceError, traceInfo, traceVerbose, traceWarning } from '../logger';
+import { traceError, traceVerbose, traceWarning } from '../logger';
 import { IDisposable } from '../types';
 import { createDeferred, Deferred } from '../utils/async';
 import { noop } from '../utils/misc';
@@ -364,14 +364,15 @@ export abstract class BasePythonDaemon {
             pid?: string;
         }>('log');
         this.connection.onNotification(logNotification, (output) => {
+            // Logging from python code will be displayed only if we have verbose logging turned on.
             const pid = output.pid ? ` (pid: ${output.pid})` : '';
             const msg = `Python Daemon${pid}: ${output.msg}`;
             if (output.level === 'DEBUG' || output.level === 'NOTSET') {
                 traceVerbose(msg);
             } else if (output.level === 'INFO') {
-                traceInfo(msg);
+                traceVerbose(msg);
             } else if (output.level === 'WARN' || output.level === 'WARNING') {
-                traceWarning(msg);
+                traceVerbose(msg);
             } else {
                 traceError(msg);
             }

src/client/datascience/ipywidgets/notebookIPyWidgetCoordinator.ts

@@ -14,6 +14,7 @@ import { IVSCodeNotebook } from '../../common/application/types';
 import { Cancellation } from '../../common/cancellation';
 import { disposeAllDisposables } from '../../common/helpers';
 import { traceInfo, traceInfoIfCI, traceVerbose } from '../../common/logger';
+import { getDisplayPath } from '../../common/platform/fs-paths';
 import { IAsyncDisposableRegistry, IDisposable, IDisposableRegistry } from '../../common/types';
 import { createDeferred } from '../../common/utils/async';
 import { noop } from '../../common/utils/misc';
@@ -116,7 +117,7 @@ export class NotebookIPyWidgetCoordinator {
             return;
         }
         // Dispost previous message coordinators.
-        traceInfo(`Setting setActiveController for ${notebook.uri}`);
+        traceInfo(`Setting setActiveController for ${getDisplayPath(notebook.uri)}`);
         const previousCoordinators = this.messageCoordinators.get(notebook);
         if (previousCoordinators) {
             this.messageCoordinators.delete(notebook);
@@ -149,15 +150,19 @@ export class NotebookIPyWidgetCoordinator {
         const controller = this.selectedNotebookController.get(notebook);
         if (!controller) {
             traceVerbose(
-                `No controller, hence notebook communications cannot be initialized for editor ${editor.document.uri.toString()}`
+                `No controller, hence notebook communications cannot be initialized for editor ${getDisplayPath(
+                    editor.document.uri
+                )}`
             );
             return;
         }
         if (this.notebookCommunications.has(editor)) {
-            traceVerbose(`notebook communications already initialized for editor ${editor.document.uri.toString()}`);
+            traceVerbose(
+                `notebook communications already initialized for editor ${getDisplayPath(editor.document.uri)}`
+            );
             return;
         }
-        traceVerbose(`Intiailize notebook communications for editor ${editor.document.uri.toString()}`);
+        traceVerbose(`Intiailize notebook communications for editor ${getDisplayPath(editor.document.uri)}`);
         const comms = new NotebookCommunication(editor, controller);
         this.addNotebookDiposables(notebook, [comms]);
         this.notebookCommunications.set(editor, comms);
@@ -171,7 +176,7 @@ export class NotebookIPyWidgetCoordinator {
     ): Promise<void> {
         // Create a handler for this notebook if we don't already have one. Since there's one of the notebookMessageCoordinator's for the
         // entire VS code session, we have a map of notebook document to message coordinator
-        traceVerbose(`Resolving notebook UI Comms (resolve) for ${document.uri.toString()}`);
+        traceVerbose(`Resolving notebook UI Comms (resolve) for ${getDisplayPath(document.uri)}`);
         let promise = this.messageCoordinators.get(document);
         if (promise === undefined) {
             promise = CommonMessageCoordinator.create(document, this.serviceContainer);
@@ -212,12 +217,12 @@ export class NotebookIPyWidgetCoordinator {
         const attachedEditors = this.attachedEditors.get(document) || new Set<NotebookEditor>();
         this.attachedEditors.set(document, attachedEditors);
         if (attachedEditors.has(webview.editor) || this.previouslyInitialized.has(webview.editor)) {
-            traceVerbose(`Coordinator already attached for ${document.uri.toString()}`);
+            traceVerbose(`Coordinator already attached for ${getDisplayPath(document.uri)}`);
             promise.resolve();
         } else {
             attachedEditors.add(webview.editor);
             const disposables: IDisposable[] = [];
-            traceVerbose(`Attach Coordinator for ${document.uri.toString()}`);
+            traceVerbose(`Attach Coordinator for ${getDisplayPath(document.uri)}`);
             // Attach message requests to this webview (should dupe to all of them)
             c.postMessage(
                 (e) => {

src/client/datascience/jupyter/kernels/helpers.ts

@@ -43,6 +43,7 @@ import { SysInfoReason } from '../../interactive-common/interactiveWindowTypes';
 import { isDefaultPythonKernelSpecName } from '../../kernel-launcher/localPythonAndRelatedNonPythonKernelSpecFinder';
 import { executeSilently } from './kernel';
 import { IWorkspaceService } from '../../../common/application/types';
+import { getDisplayPath } from '../../../common/platform/fs-paths';
 
 // Helper functions for dealing with kernels and kernelspecs
 
@@ -405,7 +406,7 @@ export function findPreferredKernel(
     remoteKernelPreferredProvider: PreferredRemoteKernelIdProvider | undefined
 ): KernelConnectionMetadata | undefined {
     traceInfo(
-        `Find preferred kernel for ${resource?.toString()} with metadata ${JSON.stringify(
+        `Find preferred kernel for ${getDisplayPath(resource)} with metadata ${JSON.stringify(
             notebookMetadata || {}
         )} & preferred interpreter ${JSON.stringify(preferredInterpreter || {})}`
     );
@@ -820,7 +821,9 @@ export async function sendTelemetryForPythonKernelExecutable(
                     trackKernelResourceInformation(resource, { interpreterMatchesKernel: match });
                     if (!match) {
                         traceError(
-                            `Interpreter started by kernel does not match expectation, expected ${kernelConnection.interpreter?.path}, got ${sysExecutable}`
+                            `Interpreter started by kernel does not match expectation, expected ${getDisplayPath(
+                                kernelConnection.interpreter?.path
+                            )}, got ${getDisplayPath(sysExecutable)}`
                         );
                     }
                 }

src/client/datascience/jupyter/kernels/jupyterKernelService.ts

@@ -10,6 +10,7 @@ import { CancellationToken, CancellationTokenSource } from 'vscode';
 import { Cancellation, wrapCancellationTokens } from '../../../common/cancellation';
 import '../../../common/extensions';
 import { traceDecorators, traceInfo, traceInfoIfCI } from '../../../common/logger';
+import { getDisplayPath } from '../../../common/platform/fs-paths';
 import { IFileSystem } from '../../../common/platform/types';
 
 import { ReadWrite, Resource } from '../../../common/types';
@@ -93,7 +94,9 @@ export class JupyterKernelService {
         // Update the kernel environment to use the interpreter's latest
         if (kernel.kind !== 'connectToLiveKernel' && kernel.kernelSpec && kernel.interpreter && specFile) {
             traceInfoIfCI(
-                `updateKernelEnvironment ${kernel.interpreter.displayName}, ${kernel.interpreter.path} for ${kernel.id}`
+                `updateKernelEnvironment ${kernel.interpreter.displayName}, ${getDisplayPath(
+                    kernel.interpreter.path
+                )} for ${kernel.id}`
             );
             await this.updateKernelEnvironment(kernel.interpreter, kernel.kernelSpec, specFile, token);
         }
@@ -222,7 +225,9 @@ export class JupyterKernelService {
                     // If conda is the first word, its possible its a conda activation command.
                     traceInfo(`Spec argv[0], not updated as it is using conda.`);
                 } else {
-                    traceInfo(`Spec argv[0] updated from '${specModel.argv[0]}' to '${interpreter.path}'`);
+                    traceInfo(
+                        `Spec argv[0] updated from '${specModel.argv[0]}' to '${getDisplayPath(interpreter.path)}'`
+                    );
                     specModel.argv[0] = interpreter.path;
                 }
 

src/client/datascience/jupyter/kernels/kernel.ts

@@ -61,6 +61,7 @@ import { IPythonExecutionFactory } from '../../../common/process/types';
 import { INotebookControllerManager } from '../../notebook/types';
 import { getResourceType } from '../../common';
 import { Deferred } from '../../../common/utils/async';
+import { getDisplayPath } from '../../../common/platform/fs-paths';
 
 export class Kernel implements IKernel {
     get connection(): INotebookProviderConnection | undefined {
@@ -228,7 +229,7 @@ export class Kernel implements IKernel {
         traceInfo(`Restart requested ${this.notebookDocument.uri}`);
         this.startCancellation.cancel();
         await this.kernelExecution.restart(this._notebookPromise);
-        traceInfoIfCI(`Restarted ${this.notebookDocument.uri}`);
+        traceInfoIfCI(`Restarted ${getDisplayPath(this.notebookDocument.uri)}`);
 
         // Interactive window needs a restart sys info
         await this.initializeAfterStart(SysInfoReason.Restart, this.notebookDocument);

src/client/datascience/jupyter/kernels/kernelDependencyService.ts

@@ -10,6 +10,7 @@ import { createPromiseFromCancellation, wrapCancellationTokens } from '../../../
 import { isModulePresentInEnvironment } from '../../../common/installer/productInstaller';
 import { ProductNames } from '../../../common/installer/productNames';
 import { traceDecorators, traceInfo } from '../../../common/logger';
+import { getDisplayPath } from '../../../common/platform/fs-paths';
 import {
     GLOBAL_MEMENTO,
     IInstaller,
@@ -58,7 +59,7 @@ export class KernelDependencyService implements IKernelDependencyService {
         token?: CancellationToken,
         disableUI?: boolean
     ): Promise<void> {
-        traceInfo(`installMissingDependencies ${interpreter.path}`);
+        traceInfo(`installMissingDependencies ${getDisplayPath(interpreter.path)}`);
         if (await this.areDependenciesInstalled(interpreter, token)) {
             return;
         }
@@ -104,7 +105,7 @@ export class KernelDependencyService implements IKernelDependencyService {
         }
         throw new IpyKernelNotInstalledError(
             DataScience.ipykernelNotInstalled().format(
-                `${interpreter.displayName || interpreter.path}:${interpreter.path}`
+                `${interpreter.displayName || getDisplayPath(interpreter.path)}:${getDisplayPath(interpreter.path)}`
             ),
             response
         );

src/client/datascience/jupyter/kernels/kernelProvider.ts

@@ -8,6 +8,7 @@ import { Event, EventEmitter, NotebookDocument } from 'vscode';
 import { ServerStatus } from '../../../../datascience-ui/interactive-common/mainState';
 import { IApplicationShell, IVSCodeNotebook, IWorkspaceService } from '../../../common/application/types';
 import { traceInfo, traceWarning } from '../../../common/logger';
+import { getDisplayPath } from '../../../common/platform/fs-paths';
 import { IFileSystem } from '../../../common/platform/types';
 import { IPythonExecutionFactory } from '../../../common/process/types';
 import {
@@ -141,8 +142,10 @@ export class KernelProvider implements IKernelProvider {
                 if (this.kernelsByNotebook.get(notebook)?.kernel === kernel) {
                     this.kernelsByNotebook.delete(notebook);
                     traceInfo(
-                        `Kernel got disposed, hence there is no longer a kernel associated with ${notebook.uri.toString()}`,
-                        kernel.notebookDocument.uri.toString()
+                        `Kernel got disposed, hence there is no longer a kernel associated with ${getDisplayPath(
+                            notebook.uri
+                        )}`,
+                        getDisplayPath(kernel.notebookDocument.uri)
                     );
                 }
                 this.pendingDisposables.delete(kernel);

src/client/datascience/kernel-launcher/kernelDaemon.ts

@@ -6,7 +6,7 @@
 import { ChildProcess } from 'child_process';
 import { Subject } from 'rxjs/Subject';
 import { MessageConnection, NotificationType, RequestType, RequestType0 } from 'vscode-jsonrpc';
-import { traceInfo, traceWarning } from '../../common/logger';
+import { traceInfo } from '../../common/logger';
 import { IPlatformService } from '../../common/platform/types';
 import { BasePythonDaemon, ExecResponse } from '../../common/process/baseDaemon';
 import { IPythonExecutionService, ObservableExecutionResult, Output, SpawnOptions } from '../../common/process/types';
@@ -89,7 +89,7 @@ export class PythonKernelDaemon extends BasePythonDaemon implements IPythonKerne
             // This is why when we run `execModule` in the Kernel daemon, it finishes (comes back) quickly.
             // However in reality it is running in the background.
             // See `m_exec_module_observable` in `kernel_launcher_daemon.py`.
-            traceInfo(`Starting kernel from scratch with options ${JSON.stringify(options)}`);
+            traceInfo('Starting kernel from scratch');
             await this.execModule(moduleName, args, options);
         }
 
@@ -125,18 +125,7 @@ export class PythonKernelDaemon extends BasePythonDaemon implements IPythonKerne
         // This is because the kernel is a long running process and that will be the only code in the daemon
         // spitting stuff into stdout/stderr.
         this.outputObservable.subscribe(
-            (out) => {
-                if (out.source === 'stderr') {
-                    // Don't call this.subject.error, as that can only be called once (hence can only be handled once).
-                    // Instead log this error & pass this only when the kernel dies.
-                    stdErr += out.out;
-                    // If we have requested for kernel to be killed, don't raise kernel died error.
-                    if (!this.killed) {
-                        traceWarning(`Kernel ${this.proc.pid} as possibly died, StdErr from Kernel Process ${out.out}`);
-                    }
-                }
-                this.subject.next(out);
-            },
+            (out) => this.subject.next(out),
             this.subject.error.bind(this.subject),
             this.subject.complete.bind(this.subject)
         );

src/client/datascience/kernel-launcher/kernelDaemonPool.ts

@@ -6,6 +6,7 @@
 import { inject, injectable } from 'inversify';
 import { IWorkspaceService } from '../../common/application/types';
 import { traceError, traceInfo } from '../../common/logger';
+import { getDisplayPath } from '../../common/platform/fs-paths';
 import { IFileSystem } from '../../common/platform/types';
 
 import { IPythonExecutionFactory, IPythonExecutionService } from '../../common/process/types';
@@ -155,7 +156,9 @@ export class KernelDaemonPool implements IDisposable {
             .then((d) => {
                 // Prewarm if we support prewarming
                 if ('preWarm' in d) {
-                    d.preWarm().catch(traceError.bind(`Failed to prewarm kernel daemon ${interpreter.path}`));
+                    d.preWarm().catch(
+                        traceError.bind(`Failed to prewarm kernel daemon ${getDisplayPath(interpreter.path)}`)
+                    );
                 }
             })
             .catch((e) => {

src/client/datascience/kernel-launcher/kernelLauncherDaemon.ts

@@ -7,6 +7,7 @@ import { ChildProcess } from 'child_process';
 import * as fs from 'fs-extra';
 import { inject, injectable } from 'inversify';
 import { traceInfo } from '../../common/logger';
+import { getDisplayPath } from '../../common/platform/fs-paths';
 import { IPythonExecutionFactory, ObservableExecutionResult } from '../../common/process/types';
 import { IDisposable, Resource } from '../../common/types';
 import { noop } from '../../common/utils/misc';
@@ -59,7 +60,7 @@ export class PythonKernelLauncherDaemon implements IDisposable {
                 bypassCondaExecution: true
             });
 
-            traceInfo(`Launching kernel daemon for ${kernelSpec.display_name} # ${interpreter?.path}`);
+            traceInfo(`Launching kernel daemon for ${kernelSpec.display_name} # ${getDisplayPath(interpreter?.path)}`);
             const [executionService, wdExists, env] = await Promise.all([
                 executionServicePromise,
                 fs.pathExists(workingDirectory),
@@ -76,7 +77,7 @@ export class PythonKernelLauncherDaemon implements IDisposable {
         }
 
         const executionServicePromise = this.daemonPool.get(resource, kernelSpec, interpreter);
-        traceInfo(`Launching kernel daemon for ${kernelSpec.display_name} # ${interpreter?.path}`);
+        traceInfo(`Launching kernel daemon for ${kernelSpec.display_name} # ${getDisplayPath(interpreter?.path)}`);
         const [executionService, wdExists, env] = await Promise.all([
             executionServicePromise,
             fs.pathExists(workingDirectory),