From 66ada03534396d472c143609b1a6d9f8340951ed Mon Sep 17 00:00:00 2001 From: Julia Silge Date: Mon, 30 Sep 2024 17:13:11 -0600 Subject: [PATCH] Update logs in the `jupyter-adapter` extension (#4845) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 2 +- .../jupyter-adapter/src/JupyterKernel.ts | 88 ++++++++++++------- .../jupyter-adapter/src/JupyterSocket.ts | 17 ++-- .../src/LanguageRuntimeAdapter.ts | 7 +- extensions/jupyter-adapter/src/extension.ts | 2 +- .../jupyter-adapter/src/jupyter-adapter.d.ts | 3 +- .../src/client/jupyter-adapter.d.ts | 3 +- .../src/client/positron/session.ts | 6 +- .../positron-r/src/jupyter-adapter.d.ts | 3 +- extensions/positron-r/src/session.ts | 7 +- .../src/jupyter-adapter.d.ts | 3 +- 11 files changed, 88 insertions(+), 53 deletions(-) diff --git a/extensions/jupyter-adapter/src/Api.ts b/extensions/jupyter-adapter/src/Api.ts index e158b42fa00..5afd2961913 100644 --- a/extensions/jupyter-adapter/src/Api.ts +++ b/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) { } /** diff --git a/extensions/jupyter-adapter/src/JupyterKernel.ts b/extensions/jupyter-adapter/src/JupyterKernel.ts index 22c523c4fbf..8195e691de0 100644 --- a/extensions/jupyter-adapter/src/JupyterKernel.ts +++ b/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,7 +1515,8 @@ 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 { @@ -1514,7 +1524,8 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable { `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,24 +1557,35 @@ 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); } } @@ -1571,7 +1593,7 @@ export class JupyterKernel extends EventEmitter implements vscode.Disposable { * Show kernel log in output panel. */ public showOutput() { - this._logChannel?.show(); + this._kernelChannel?.show(); } public async showProfile() { diff --git a/extensions/jupyter-adapter/src/JupyterSocket.ts b/extensions/jupyter-adapter/src/JupyterSocket.ts index 5ac9e91141f..11439ec1c67 100644 --- a/extensions/jupyter-adapter/src/JupyterSocket.ts +++ b/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(); } diff --git a/extensions/jupyter-adapter/src/LanguageRuntimeAdapter.ts b/extensions/jupyter-adapter/src/LanguageRuntimeAdapter.ts index 8d362e3e1d6..8639b17eead 100644 --- a/extensions/jupyter-adapter/src/LanguageRuntimeAdapter.ts +++ b/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); } /** diff --git a/extensions/jupyter-adapter/src/extension.ts b/extensions/jupyter-adapter/src/extension.ts index 5bc7812c6fd..494ddeb20e1 100644 --- a/extensions/jupyter-adapter/src/extension.ts +++ b/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); } diff --git a/extensions/jupyter-adapter/src/jupyter-adapter.d.ts b/extensions/jupyter-adapter/src/jupyter-adapter.d.ts index 78b5a03fa26..4ee76b2c9d2 100644 --- a/extensions/jupyter-adapter/src/jupyter-adapter.d.ts +++ b/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()` diff --git a/extensions/positron-python/src/client/jupyter-adapter.d.ts b/extensions/positron-python/src/client/jupyter-adapter.d.ts index 26054e26230..c60889e8bd5 100644 --- a/extensions/positron-python/src/client/jupyter-adapter.d.ts +++ b/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()` diff --git a/extensions/positron-python/src/client/positron/session.ts b/extensions/positron-python/src/client/positron/session.ts index b287d3cd24b..5f649ada3b0 100644 --- a/extensions/positron-python/src/client/positron/session.ts +++ b/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, ); } } diff --git a/extensions/positron-r/src/jupyter-adapter.d.ts b/extensions/positron-r/src/jupyter-adapter.d.ts index 9a29e4409eb..2403c01dfc2 100644 --- a/extensions/positron-r/src/jupyter-adapter.d.ts +++ b/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()` diff --git a/extensions/positron-r/src/session.ts b/extensions/positron-r/src/session.ts index 0f7216a866a..b61267a5ce7 100644 --- a/extensions/positron-r/src/session.ts +++ b/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); } } }); diff --git a/extensions/positron-reticulate/src/jupyter-adapter.d.ts b/extensions/positron-reticulate/src/jupyter-adapter.d.ts index 5a0c9cbd3be..58a1fd01442 100644 --- a/extensions/positron-reticulate/src/jupyter-adapter.d.ts +++ b/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()`