Update logs in the jupyter-adapter extension (#4845)

Addresses #4275 

This PR makes changes to all the output channels generated by the
`jupyter-adapter` extension.

The "main" Jupyter Adapter output channel is now a real log, with
timestamps and log level annotations:

![Screenshot 2024-09-28 at 4 51
07 PM](https://github.com/user-attachments/assets/28c48414-f7ee-4da5-9ebb-eeaa96d892ac)

The existing "Console: X.Y.Z" channel now only has messages generated
from Positron, not the kernel itself. This is now also a real log and is
the part that directly addresses #4275:

![Screenshot 2024-09-28 at 4 51
26 PM](https://github.com/user-attachments/assets/9e1b1345-4001-44d6-b43a-d2b9e092027c)

Notice the new "error" log level here; you can now set the log level in
these first two output channels and it will update moving forward.

These first two output channels are generated in the same way most of
the time (we write to the "Console" channel if that kernel is up but to
the "Jupyter Adapter" channel if not) so we have to make changes to them
together; this seems good rather than bad to me and overall both are now
improved.

There is a new "Kernel: X.Y.Z" channel which still uses the raw output
channel that we created back in #1589. It is not a real log and does not
have timestamps, unless the kernel log generated those. You cannot
change the log level via the normal method for this one:

![Screenshot 2024-09-28 at 4 51
38 PM](https://github.com/user-attachments/assets/2df12fb3-7cc5-4aab-b49b-933fc3ecdc7a)

It is kind of a bummer to now have _three_ output channels generated
from this one extension but IMO the tradeoffs are worth it.


### QA Notes

You'll now see timestamps and log level annotations in the "Jupyter
Adapter" and "Console: X.Y.Z" output channels, and there is a new
"Kernel: X.Y.Z" channel.

extensions/jupyter-adapter/src/Api.ts

@@ -13,7 +13,7 @@ import { JupyterSerializedSession, workspaceStateKey } from './JupyterSessionSer
 
 export class JupyterAdapterApiImpl implements JupyterAdapterApi {
 	constructor(private readonly _context: vscode.ExtensionContext,
-		private readonly _channel: vscode.OutputChannel) {
+		private readonly _channel: vscode.LogOutputChannel) {
 	}
 
 	/**

extensions/jupyter-adapter/src/JupyterKernel.ts

@@ -95,12 +95,15 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 	 */
 	private _terminal?: vscode.Terminal;
 
-	/** The channel to which output for this specific terminal is logged, if any */
-	private _logChannel?: vscode.OutputChannel;
+	/** The channel to which output for this specific kernel is logged, if any */
+	private _kernelChannel?: vscode.OutputChannel;
 
 	/** An optional profiler channel */
 	private _profileChannel?: vscode.OutputChannel;
 
+	/** The channel to which output for this specific console is logged */
+	private _consoleChannel?: vscode.LogOutputChannel;
+
 	/** The exit code, if any */
 	private _exitCode: number;
 
@@ -136,7 +139,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 		private readonly _context: vscode.ExtensionContext,
 		spec: JupyterKernelSpec,
 		private readonly _runtimeId: string,
-		private readonly _channel: vscode.OutputChannel,
+		private readonly _channel: vscode.LogOutputChannel,
 		private readonly _notebookUri?: vscode.Uri,
 		readonly extra?: JupyterKernelExtra,
 	) {
@@ -256,7 +259,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 		this.disposeAllSockets();
 
 		// Create ZeroMQ sockets
-		const logger = (message: string) => this.log(message);
+		const logger = (message: string, logLevel?: vscode.LogLevel) => this.log(message, logLevel);
 		this._control = new JupyterSocket('Control', 'dealer', logger);
 		this._allSockets.push(this._control);
 		this._shell = new JupyterSocket('Shell', 'dealer', logger);
@@ -312,14 +315,20 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 	 */
 	public async connectToSession(session: JupyterSession) {
 
-		// Establish a log channel for the kernel we're connecting to, if we
+		// Establish log channels for the console and kernel we're connecting to, if we
 		// don't already have one (we will if we're restarting)
 		// We use `.path` here because we discovered sometimes `fspath` does not exist on a `Uri`.
-		if (!this._logChannel) {
-			this._logChannel = positron.window.createRawLogOutputChannel(
+		if (!this._consoleChannel) {
+			this._consoleChannel = vscode.window.createOutputChannel(
 				this._notebookUri ?
-					`Notebook: ${path.basename(this._notebookUri.path)} (${this._spec.display_name})` :
-					`Console: ${this._spec.display_name}`);
+					`${this._spec.display_name}: Notebook: (${path.basename(this._notebookUri.path)})` :
+					`${this._spec.display_name}: Console`,
+				{ log: true });
+		}
+
+		if (!this._kernelChannel) {
+			this._kernelChannel = positron.window.createRawLogOutputChannel(
+				`${this._spec.display_name}: Kernel`);
 		}
 
 		// Bind to the Jupyter session
@@ -344,7 +353,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 		if (fs.existsSync(logFilePath)) {
 			this.log('Streaming log file: ' + logFilePath);
 
-			this._logStreamer = new LogStreamer(this._logChannel, logFilePath, this._spec.language);
+			this._logStreamer = new LogStreamer(this._kernelChannel, logFilePath, this._spec.language);
 			this._disposables.push(this._logStreamer);
 
 			this._logStreamer.watch();
@@ -520,7 +529,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 						case 'rpc_request': {
 							// Concurrent requests are not currently allowed
 							if (this._activeBackendRequestHeader !== undefined) {
-								this.log('ERROR: Overlapping request on StdIn');
+								this.log('Overlapping request on StdIn', vscode.LogLevel.Error);
 							}
 							this._activeBackendRequestHeader = msg.header;
 							break;
@@ -660,7 +669,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 				return this.reconnect(this._session.state);
 			} catch (err) {
 				// If we failed to reconnect, then we need to remove the stale session state
-				this.log(`Failed to reconnect to kernel: ${err}`);
+				this.log(`Failed to reconnect to kernel: ${err}`, vscode.LogLevel.Error);
 
 				// After a beat, consider this state to be 'exited' so that we
 				// can start a new session; the most common cause of a failure
@@ -796,7 +805,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 				try {
 					await this._extra!.attachOnStartup!.attach();
 				} catch (err) {
-					this.log(`Can't execute attach action: ${err}`);
+					this.log(`Can't execute attach action: ${err}`, vscode.LogLevel.Error);
 				}
 			}
 
@@ -1096,7 +1105,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 		this.send(id, 'execute_request', this._shell!, msg)
 			.catch((err) => {
 				// Fail if we couldn't connect to the socket
-				this.log(`Failed to send execute_request for ${code} (id ${id}): ${err}`);
+				this.log(`Failed to send execute_request for ${code} (id ${id}): ${err}`, vscode.LogLevel.Error);
 			});
 	}
 
@@ -1125,7 +1134,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 			// Couldn't find the request? Send the response anyway; most likely
 			// the kernel doesn't care (it is probably waiting for this specific
 			// response)
-			this.log(`WARN: Failed to find parent for input request ${id}; sending anyway: ${value}`);
+			this.log(`Failed to find parent for input request ${id}; sending anyway: ${value}`, vscode.LogLevel.Warning);
 			this.send(uuidv4(), 'input_reply', this._stdin!, msg);
 		}
 	}
@@ -1140,7 +1149,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 		const parent = this._activeBackendRequestHeader;
 
 		if (!parent) {
-			this.log(`ERROR: Failed to find parent for comm request ${response.id}`);
+			this.log(`Failed to find parent for comm request ${response.id}`, vscode.LogLevel.Error);
 			return;
 		}
 
@@ -1317,7 +1326,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 			await dest.send(serializeJupyterMessage(msg, this._session!.key));
 			this.log(`SEND ${msg.header.msg_type}: OK`);
 		} catch (err) {
-			this.log(`SEND ${msg.header.msg_type}: ERR: ${err}`);
+			this.log(`SEND ${msg.header.msg_type}: ERR: ${err}`, vscode.LogLevel.Error);
 		}
 	}
 
@@ -1506,15 +1515,17 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 						}
 					} catch (e) {
 						this.log(`Could not find exit code in last line of log file ` +
-							`${state.logFile}: ${lastLine} (${e}))`);
+							`${state.logFile}: ${lastLine} (${e}))`,
+							vscode.LogLevel.Error);
 					}
 				}
 			} else {
 				this.log(`Not reading exit code from process ${state.processId}; ` +
 					`log file ${state.logFile} does not exist`);
 			}
 		} catch (e) {
-			this.log(`Error reading exit code from log file ${state.logFile}: ${e}`);
+			this.log(`Error reading exit code from log file ${state.logFile}: ${e}`,
+				vscode.LogLevel.Error);
 		}
 
 		// Fire the actual exit event
@@ -1546,32 +1557,43 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable {
 	 *
 	 * @param msg The message to log
 	 */
-	public log(msg: string) {
+	public log(msg: string, logLevel?: vscode.LogLevel) {
 		// Ensure message isn't over the maximum length
 		if (msg.length > 2048) {
 			msg = msg.substring(0, 2048) + '... (truncated)';
 		}
 
-		if (this._logChannel) {
-			// If we have a kernel-specific log channel, log to that. The kernel
-			// log channel primarily streams the kernel's log, so prefix our
-			// output with "Positron" to distinguish it from the output from the
-			// language runtime.
-			this._logChannel.appendLine(`[Positron] ${msg}`);
-		} else {
-			// Otherwise, log to the main Jupyter Adapter channel. This is
-			// useful to send logs before the kernel is fully initialized; we
-			// don't create a log channel for the kernel unless it actually
-			// starts up.
-			this._channel.appendLine(msg);
+		// By default, log to the main Jupyter Adapter channel. This is
+		// useful to send logs before the kernel is fully initialized; we
+		// don't create a log channel for the kernel unless it actually
+		// starts up.
+		let channel = this._channel;
+
+		// If we have a console-specific log channel, log to that instead.
+		if (this._consoleChannel) {
+			channel = this._consoleChannel;
+		}
+
+		switch (logLevel) {
+			case vscode.LogLevel.Error:
+				channel.error(msg);
+				break;
+			case vscode.LogLevel.Warning:
+				channel.warn(msg);
+				break;
+			case vscode.LogLevel.Info:
+				channel.info(msg);
+				break;
+			default:
+				channel.appendLine(msg);
 		}
 	}
 
 	/**
 	 * Show kernel log in output panel.
 	 */
 	public showOutput() {
-		this._logChannel?.show();
+		this._kernelChannel?.show();
 	}
 
 	public async showProfile() {

extensions/jupyter-adapter/src/JupyterSocket.ts

@@ -51,7 +51,7 @@ export class JupyterSocket implements vscode.Disposable {
 	 * @param _logger A function that logs a message
 	 */
 	constructor(title: string, socketType: 'sub' | 'dealer' | 'req',
-		private readonly _logger: (msg: string) => void) {
+		private readonly _logger: (msg: string, logLevel?: vscode.LogLevel) => void) {
 		this._socket = zmq.createSocket(socketType);
 		this._title = title;
 		this.onDisconnected = this._disconnectEmitter.event;
@@ -65,8 +65,8 @@ export class JupyterSocket implements vscode.Disposable {
 		// Warn if we are nearing ZeroMQ's maximum number of sockets. This is 1024 in
 		// typical installations, but can be changed by setting ZMQ_MAX_SOCKETS.
 		if (JupyterSocket._jupyterSocketCount >= (zmq.Context.getMaxSockets() - 1)) {
-			this._logger(`*** WARNING *** Nearing maximum number of ZeroMQ sockets ` +
-				`(${zmq.Context.getMaxSockets()})`);
+			this._logger(`Nearing maximum number of ZeroMQ sockets ${zmq.Context.getMaxSockets()}`,
+				vscode.LogLevel.Warning);
 		}
 
 		// Monitor the socket for events; this is necessary to get events like
@@ -146,7 +146,8 @@ export class JupyterSocket implements vscode.Disposable {
 		try {
 			this._socket.disconnect(this._addr);
 		} catch (err) {
-			this._logger(`Error disconnecting ${this._title} socket from ${this._addr}: ${err}`);
+			this._logger(`Error disconnecting ${this._title} socket from ${this._addr}: ${err}`,
+				vscode.LogLevel.Error);
 		}
 
 
@@ -256,7 +257,8 @@ export class JupyterSocket implements vscode.Disposable {
 			const waitTime = Date.now() - startTime;
 			if (waitTime >= 20000) {
 				// If we've been waiting for more than 20 seconds, reject the promise
-				this._logger(`${this._title} socket connect timed out after 20 seconds`);
+				this._logger(`${this._title} socket connect timed out after 20 seconds`,
+					vscode.LogLevel.Error);
 				this._connectPromise.reject(new Error('Socket connect timed out after 20 seconds'));
 				this._connectPromise = undefined;
 
@@ -335,8 +337,9 @@ export class JupyterSocket implements vscode.Disposable {
 		// Disconnect the socket if it's connected
 		if (this._state === JupyterSocketState.Connected) {
 			// This generally should not happen, so log a warning
-			this._logger(`WARN: ${this._title} socket disposed while connected; ` +
-				` disconnecting from ${this._addr}...`);
+			this._logger(`${this._title} socket disposed while connected; ` +
+				` disconnecting from ${this._addr}...`,
+				vscode.LogLevel.Warning);
 			this.disconnect();
 		}
 

extensions/jupyter-adapter/src/LanguageRuntimeAdapter.ts

@@ -81,7 +81,7 @@ export class LanguageRuntimeSessionAdapter
 		readonly runtimeMetadata: positron.LanguageRuntimeMetadata,
 		public readonly metadata: positron.RuntimeSessionMetadata,
 		private readonly _context: vscode.ExtensionContext,
-		private readonly _channel: vscode.OutputChannel,
+		private readonly _channel: vscode.LogOutputChannel,
 		private readonly _spec: JupyterKernelSpec,
 		public dynState: positron.LanguageRuntimeDynState,
 		extra?: JupyterKernelExtra,
@@ -219,9 +219,10 @@ export class LanguageRuntimeSessionAdapter
 	 * Emits a message into the Jupyter kernel's log channel.
 	 *
 	 * @param message The message to emit to the log
+	 * @param logLevel Optionally, the log level of the message.
 	 */
-	public emitJupyterLog(message: string): void {
-		this._kernel.log(message);
+	public emitJupyterLog(message: string, logLevel?: vscode.LogLevel): void {
+		this._kernel.log(message, logLevel);
 	}
 
 	/**

extensions/jupyter-adapter/src/extension.ts

@@ -13,7 +13,7 @@ import { JupyterAdapterApi } from './jupyter-adapter';
 export const JUPYTER_WORKSPACE_STATE_KEY = 'jupyter-adapter.v1';
 
 export function activate(_context: vscode.ExtensionContext): JupyterAdapterApi {
-	const channel = vscode.window.createOutputChannel('Jupyter Adapter');
+	const channel = vscode.window.createOutputChannel('Jupyter Adapter', { log: true });
 	channel.appendLine('Jupyter Adapter extension activated');
 	return new JupyterAdapterApiImpl(_context, channel);
 }

extensions/jupyter-adapter/src/jupyter-adapter.d.ts

@@ -100,8 +100,9 @@ export interface JupyterLanguageRuntimeSession extends positron.LanguageRuntimeS
 	 * channel.
 	 *
 	 * @param message A message to emit to the Jupyter log.
+	 * @param logLevel Optionally, the log level of the message.
 	 */
-	emitJupyterLog(message: string): void;
+	emitJupyterLog(message: string, logLevel?: vscode.LogLevel): void;
 
 	/**
 	 * A Jupyter kernel is guaranteed to have a `showOutput()`

extensions/positron-python/src/client/jupyter-adapter.d.ts

@@ -64,8 +64,9 @@ export interface JupyterLanguageRuntimeSession extends positron.LanguageRuntimeS
      * channel.
      *
      * @param message A message to emit to the Jupyter log.
+     * @param logLevel Optionally, the log level of the message.
      */
-    emitJupyterLog(message: string): void;
+    emitJupyterLog(message: string, logLevel?: vscode.LogLevel): void;
 
     /**
      * A Jupyter kernel is guaranteed to have a `showOutput()`

extensions/positron-python/src/client/positron/session.ts

@@ -312,7 +312,10 @@ export class PythonRuntimeSession implements positron.LanguageRuntimeSession, vs
             // Log the error if we can't set the console width; this is not
             // fatal, so we don't rethrow the error
             const runtimeError = err as positron.RuntimeMethodError;
-            this._kernel.emitJupyterLog(`Error setting console width: ${runtimeError.message} (${runtimeError.code})`);
+            this._kernel.emitJupyterLog(
+                `Error setting console width: ${runtimeError.message} (${runtimeError.code})`,
+                vscode.LogLevel.Error,
+            );
         }
     }
 
@@ -534,6 +537,7 @@ export class PythonRuntimeSession implements positron.LanguageRuntimeSession, vs
                         const runtimeError = err as positron.RuntimeMethodError;
                         this._kernel.emitJupyterLog(
                             `Error setting initial console width: ${runtimeError.message} (${runtimeError.code})`,
+                            vscode.LogLevel.Error,
                         );
                     }
                 }

extensions/positron-r/src/jupyter-adapter.d.ts

@@ -68,8 +68,9 @@ export interface JupyterLanguageRuntimeSession extends positron.LanguageRuntimeS
 	 * channel.
 	 *
 	 * @param message A message to emit to the Jupyter log.
+	 * @param logLevel Optionally, the log level of the message.
 	 */
-	emitJupyterLog(message: string): void;
+	emitJupyterLog(message: string, logLevel?: vscode.LogLevel): void;
 
 	/**
 	 * A Jupyter kernel is guaranteed to have a `showOutput()`

extensions/positron-r/src/session.ts

@@ -263,8 +263,8 @@ export class RSession implements positron.LanguageRuntimeSession, vscode.Disposa
 			// fatal, so we don't rethrow the error
 			const runtimeError = err as positron.RuntimeMethodError;
 			this._kernel!.emitJupyterLog(
-				`Error setting console width: ${runtimeError.message} ` +
-				`(${runtimeError.code})`);
+				`Error setting console width: ${runtimeError.message} ${runtimeError.code})`,
+				vscode.LogLevel.Error);
 		}
 	}
 
@@ -601,7 +601,8 @@ export class RSession implements positron.LanguageRuntimeSession, vscode.Disposa
 						const runtimeError = err as positron.RuntimeMethodError;
 						this._kernel.emitJupyterLog(
 							`Error setting initial console width: ${runtimeError.message} ` +
-							`(${runtimeError.code})`);
+							`(${runtimeError.code})`,
+							vscode.LogLevel.Error);
 					}
 				}
 			});

extensions/positron-reticulate/src/jupyter-adapter.d.ts

@@ -100,8 +100,9 @@ export interface JupyterLanguageRuntimeSession extends positron.LanguageRuntimeS
 	 * channel.
 	 *
 	 * @param message A message to emit to the Jupyter log.
+	 * @param logLevel Optionally, the log level of the message.
 	 */
-	emitJupyterLog(message: string): void;
+	emitJupyterLog(message: string, logLevel?: vscode.LogLevel): void;
 
 	/**
 	 * A Jupyter kernel is guaranteed to have a `showOutput()`