Updates to logged messages (#14708)

* Updates to logged messages

* Update messages

src/kernels/api/kernel.ts

@@ -14,7 +14,7 @@ import { Telemetry, sendTelemetryEvent } from '../../telemetry';
 import { StopWatch } from '../../platform/common/utils/stopWatch';
 import { Deferred, createDeferred, sleep } from '../../platform/common/utils/async';
 import { once } from '../../platform/common/utils/events';
-import { traceError, traceInfo, traceVerbose } from '../../platform/logging';
+import { traceError, traceVerbose } from '../../platform/logging';
 
 function getExtensionDisplayName(extensionId: string) {
     const extensionDisplayName = extensions.getExtension(extensionId)?.packageJSON.displayName;
@@ -169,7 +169,6 @@ class WrappedKernelPerExtension implements Kernel {
                 completed = true;
                 done.resolve();
                 sendApiExecTelemetry(this.kernel, measures, properties).catch(noop);
-                traceVerbose(`Kernel execution completed in ${measures.duration}ms, ${this.extensionDisplayName}.`);
             }
         });
         const kernelExecution = ServiceContainer.instance
@@ -225,7 +224,7 @@ class WrappedKernelPerExtension implements Kernel {
                 measures.cancelledAfter = stopwatch.elapsedTime;
                 properties.cancelledBeforeRequestSent = !properties.requestSent;
                 properties.cancelledBeforeRequestAcknowledged = !properties.requestAcknowledged;
-                traceInfo(`Code execution cancelled by extension ${this.extensionDisplayName}`);
+                traceVerbose(`Code execution cancelled by extension ${this.extensionDisplayName}`);
             },
             this,
             disposables

src/kernels/execution/cellExecution.ts

@@ -427,7 +427,7 @@ export class CellExecution implements ICellExecution, IDisposable {
         try {
             // At this point we're about to ACTUALLY execute some code. Fire an event to indicate that
             this._preExecuteEmitter.fire(this.cell);
-            traceVerbose(`Execution Request Sent to Kernel for cell ${this.cell.index}`);
+            traceVerbose(`Cell Index:${this.cell.index} sent to kernel`);
             // For Jupyter requests, silent === don't output, while store_history === don't update execution count
             // https://jupyter-client.readthedocs.io/en/stable/api/client.html#jupyter_client.KernelClient.execute
             this.request = kernelConnection.requestExecute(

src/kernels/execution/cellExecutionCreator.ts

@@ -70,9 +70,9 @@ export class NotebookCellExecutionWrapper implements NotebookCellExecution {
             try {
                 this._impl.end(success, endTime);
                 traceInfo(
-                    `End cell ${this.cell.index} execution @ ${endTime}, started @ ${this._startTime}, elapsed time = ${
+                    `End cell ${this.cell.index} execution after ${
                         ((endTime || 0) - (this._startTime || 0)) / 1000
-                    }s`
+                    }s, completed @ ${endTime}, started @ ${this._startTime}`
                 );
             } finally {
                 this._endCallback();

src/kernels/execution/cellExecutionQueue.ts

@@ -109,7 +109,6 @@ export class CellExecutionQueue implements Disposable {
             this.disposables.push(codeExecution);
             this.queueOfItemsToExecute.push(codeExecution);
             this.disposables.push(once(token.onCancellationRequested)(() => codeExecution.cancel()));
-            traceVerbose(`Extension ${extensionId} queued code for execution`);
         }
         // Start executing the cells.
         this.startExecutingCells();
@@ -198,10 +197,8 @@ export class CellExecutionQueue implements Disposable {
     private async executeQueuedCells() {
         let notebookClosed: boolean | undefined;
         const kernelConnection = await this.session;
-        this.queueOfItemsToExecute.forEach((exec) =>
-            exec.type === 'cell'
-                ? traceCellMessage(exec.cell, 'Ready to execute')
-                : traceVerbose(`Ready to execute code ${exec.code.substring(0, 50)}...`)
+        this.queueOfItemsToExecute.forEach(
+            (exec) => exec.type === 'cell' && traceCellMessage(exec.cell, 'Ready to execute')
         );
         while (this.queueOfItemsToExecute.length) {
             // Dispose the previous cell execution.

src/kernels/execution/codeExecution.ts

@@ -5,7 +5,7 @@ import type * as KernelMessage from '@jupyterlab/services/lib/kernel/messages';
 
 import type { Kernel } from '@jupyterlab/services';
 import { dispose } from '../../platform/common/utils/lifecycle';
-import { traceError, traceInfoIfCI } from '../../platform/logging';
+import { traceError, traceInfoIfCI, traceVerbose } from '../../platform/logging';
 import { IDisposable } from '../../platform/common/types';
 import { createDeferred } from '../../platform/common/utils/async';
 import { noop } from '../../platform/common/utils/misc';
@@ -16,7 +16,7 @@ import { executeSilentlyAndEmitOutput } from '../helpers';
 import { EventEmitter, NotebookCellOutputItem } from 'vscode';
 
 function traceExecMessage(executionId: string, message: string) {
-    traceInfoIfCI(`Execution Id:${executionId}. ${message}.`);
+    traceVerbose(`Execution Id:${executionId}. ${message}.`);
 }
 
 const extensionIdsPerExtension = new Map<string, number>();
@@ -53,15 +53,15 @@ export class CodeExecution implements ICodeExecution, IDisposable {
     private readonly disposables: IDisposable[] = [];
     private session?: IKernelSession;
     private cancelRequested?: boolean;
-    private readonly executionId: string;
+    public readonly executionId: string;
     private constructor(
         public readonly code: string,
         public readonly extensionId: string
     ) {
         let executionId = extensionIdsPerExtension.get(extensionId) || 0;
         executionId += 1;
         extensionIdsPerExtension.set(extensionId, executionId);
-        this.executionId = `${extensionId}-${extensionId}`;
+        this.executionId = `${extensionId}-${executionId}`;
         this.disposables.push(this._onDidEmitOutput);
     }
 
@@ -135,7 +135,9 @@ export class CodeExecution implements ICodeExecution, IDisposable {
             return;
         }
         this.disposed = true;
-        traceExecMessage(this.executionId, 'Execution disposed');
+        if (!this._completed) {
+            traceExecMessage(this.executionId, 'Execution disposed');
+        }
         dispose(this.disposables);
     }
 
@@ -181,7 +183,6 @@ export class CodeExecution implements ICodeExecution, IDisposable {
             // When the request finishes we are done
             // request.done resolves even before all iopub messages have been sent through.
             // Solution is to wait for all messages to get processed.
-            traceExecMessage(this.executionId, 'Wait for jupyter execution');
             await this.request!.done.catch(noop);
             this._completed = true;
             this._done.resolve();

src/kernels/execution/types.ts

@@ -17,6 +17,7 @@ export interface ICellExecution {
 
 export interface ICodeExecution {
     type: 'code';
+    executionId: string;
     code: string;
     result: Promise<NotebookCellRunState>;
     onRequestSent: Event<void>;

src/kernels/helpers.ts

@@ -706,15 +706,13 @@ export function executeSilentlyAndEmitOutput(
     onStarted: () => void,
     onOutput: (outputs: NotebookCellOutputItem[]) => void
 ) {
-    traceVerbose(
-        `Executing silently Code (${kernelConnection.status}) = ${splitLines(code.substring(0, 100)).join('\\n')}`
-    );
+    code = code.replace(/\r\n/g, '\n');
     // eslint-disable-next-line @typescript-eslint/no-require-imports
     const jupyterLab = require('@jupyterlab/services') as typeof import('@jupyterlab/services');
 
     const request = kernelConnection.requestExecute(
         {
-            code: code.replace(/\r\n/g, '\n'),
+            code,
             silent: false,
             stop_on_error: false,
             allow_stdin: false,

src/kernels/kernelExecution.ts

@@ -35,6 +35,8 @@ import {
 } from './types';
 import { SessionDisposedError } from '../platform/errors/sessionDisposedError';
 import { ICodeExecution } from './execution/types';
+import { StopWatch } from '../platform/common/utils/stopWatch';
+import { noop } from '../platform/common/utils/misc';
 
 /**
  * Everything in this classes gets disposed via the `onWillCancel` hook.
@@ -151,9 +153,7 @@ export class NotebookKernelExecution implements INotebookKernelExecution {
         return result[0];
     }
     public async executeCode(code: string, extensionId: string, token: CancellationToken): Promise<ICodeExecution> {
-        traceVerbose(`NotebookKernelExecution.executeCode (1), ${code.substring(0, 50)}... from ${extensionId}`);
-
-        traceVerbose(`NotebookKernelExecution.executeCode, ${code.substring(0, 50)}... from ${extensionId}`);
+        const stopWatch = new StopWatch();
         await initializeInteractiveOrNotebookTelemetryBasedOnUserAction(
             this.kernel.resourceUri,
             this.kernel.kernelConnectionMetadata
@@ -164,9 +164,17 @@ export class NotebookKernelExecution implements INotebookKernelExecution {
         // If we're restarting, wait for it to finish
         await this.kernel.restarting;
 
-        traceVerbose(`NotebookKernelExecution.executeCode (2), ${code.substring(0, 50)}... from ${extensionId}`);
         const executionQueue = this.getOrCreateCellExecutionQueue(this.notebook, sessionPromise);
-        return executionQueue.queueCode(code, extensionId, token);
+        const result = executionQueue.queueCode(code, extensionId, token);
+        traceVerbose(`Queue code ${result.executionId} from ${extensionId} after ${stopWatch.elapsedTime}ms:\n${code}`);
+        result.result
+            .finally(
+                () =>
+                    !token.isCancellationRequested &&
+                    traceInfo(`Execution of code ${result.executionId} completed in ${stopWatch.elapsedTime}ms`)
+            )
+            .catch(noop);
+        return result;
     }
     executeHidden(code: string): Promise<IOutput[]> {
         const sessionPromise = this.kernel.start();

src/notebooks/controllers/kernelConnector.ts

@@ -250,12 +250,6 @@ export class KernelConnector {
         disposables: IDisposable[],
         onAction: (action: KernelAction, kernel: IBaseKernel | IKernel) => void = () => noop()
     ): Promise<IBaseKernel | IKernel> {
-        traceVerbose(
-            `${initialContext} the kernel, options.disableUI=${options.disableUI} for ${getDisplayPath(
-                'notebook' in notebookResource ? notebookResource.notebook.uri : notebookResource.resource
-            )}`
-        );
-
         let currentPromise = this.getKernelInfo(notebookResource);
         if (!options.disableUI && currentPromise?.options.disableUI) {
             currentPromise.options.disableUI = false;
@@ -284,6 +278,12 @@ export class KernelConnector {
             );
         }
 
+        traceVerbose(
+            `${initialContext} the kernel, options.disableUI=${options.disableUI} for ${getDisplayPath(
+                'notebook' in notebookResource ? notebookResource.notebook.uri : notebookResource.resource
+            )}`
+        );
+
         const promise = KernelConnector.wrapKernelMethodImpl(
             metadata,
             initialContext,