From e8a8f0f09cd449d03410fbb0384226ded3f3e78a Mon Sep 17 00:00:00 2001 From: Jonathan McPherson Date: Wed, 11 Dec 2024 10:16:56 -0800 Subject: [PATCH 1/4] capture and log supervisor output in case there's an error --- extensions/positron-supervisor/positron.json | 8 +++ .../resources/supervisor-wrapper.bat | 44 +++++++++++++ .../resources/supervisor-wrapper.sh | 34 ++++++++++ .../src/KallichoreAdapterApi.ts | 62 ++++++++++++++++++- 4 files changed, 147 insertions(+), 1 deletion(-) create mode 100644 extensions/positron-supervisor/positron.json create mode 100644 extensions/positron-supervisor/resources/supervisor-wrapper.bat create mode 100755 extensions/positron-supervisor/resources/supervisor-wrapper.sh diff --git a/extensions/positron-supervisor/positron.json b/extensions/positron-supervisor/positron.json new file mode 100644 index 00000000000..8c1f7c37f95 --- /dev/null +++ b/extensions/positron-supervisor/positron.json @@ -0,0 +1,8 @@ +{ + "binaries": [ + { + "from": "resources/supervisor-wrapper.*", + "to": "resources" + } + ] +} diff --git a/extensions/positron-supervisor/resources/supervisor-wrapper.bat b/extensions/positron-supervisor/resources/supervisor-wrapper.bat new file mode 100644 index 00000000000..3bd76c99180 --- /dev/null +++ b/extensions/positron-supervisor/resources/supervisor-wrapper.bat @@ -0,0 +1,44 @@ +REM --------------------------------------------------------------------------------------------- +REM Copyright (C) 2024 Posit Software, PBC. All rights reserved. +REM --------------------------------------------------------------------------------------------- + +REM This script is used to run a program and capture its output to a file. It is +REM used to capture the output of the supervisor process so that it can be displayed +REM in the UI in the case of a startup failure. + +@echo off + +REM Check that the user provided at least two arguments; the first is the output +REM file and the second is the program to run and any arguments. If not, print a +REM usage message and exit with an error code. + +if "%~2"=="" ( + echo Usage: %0 ^ ^ [program-args...] >&2 + exit /b 1 +) + +REM The first argument is the output file; consume it. +set output_file=%1 +shift + +REM `shift` doesn't affect `%*`, so we have to manually remove the first argument +set "args=" +:parse +if "%~1" neq "" ( + set args=%args% %1 + shift + goto :parse +) +if defined args set args=%args:~1% + +REM Print the command line to the log file +echo %args% >> "%output_file%" + +REM Run the program with its arguments and capture the output +%args% >> "%output_file%" + +REM Save the exit code of the program +set exit_code=%ERRORLEVEL% + +REM Exit with the same code as the program so that the caller can correctly report errors +exit /b exit_code diff --git a/extensions/positron-supervisor/resources/supervisor-wrapper.sh b/extensions/positron-supervisor/resources/supervisor-wrapper.sh new file mode 100755 index 00000000000..4ac4cce2620 --- /dev/null +++ b/extensions/positron-supervisor/resources/supervisor-wrapper.sh @@ -0,0 +1,34 @@ +#!/usr/bin/env bash + +# --------------------------------------------------------------------------------------------- +# Copyright (C) 2024 Posit Software, PBC. All rights reserved. +# Licensed under the Elastic License 2.0. See LICENSE.txt for license information. +# --------------------------------------------------------------------------------------------- + +# This script is used to run a program and capture its output to a file. It is +# used to capture the output of the supervisor process so that it can be displayed +# in the UI in the case of a startup failure + +# Check that the user provided at least two arguments; the first is the output +# file and the second is the program to run and any arguments. If not, print a +# usage message and exit with an error code. +if [ $# -lt 2 ]; then + echo "Usage: $0 [program-args...]" >&2 + exit 1 +fi + +# The first argument is the output file; consume it. +output_file="$1" +shift + +# Print the command line to the log file +echo "$@" >> "$output_file" + +# Run the program with its arguments, redirecting stdout and stderr to the output file +"$@" >> "$output_file" 2>&1 + +# Save the exit code of the program +exit_code=$? + +# Exit with the same code as the program so that the caller can correctly report errors +exit $exit_code diff --git a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts index 0c2a1257dcb..577e6cd8e60 100644 --- a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts +++ b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts @@ -69,6 +69,11 @@ export class KCApi implements KallichoreAdapterApi { */ private _logStreamer: LogStreamer | undefined; + /** + * An array of disposables that need to be cleaned up when the API is disposed. + */ + private _disposables: vscode.Disposable[] = []; + /** * Create a new Kallichore API object. * @@ -202,12 +207,21 @@ export class KCApi implements KallichoreAdapterApi { // Create a temporary file with a random name to use for logs const logFile = path.join(os.tmpdir(), `kallichore-${sessionId}.log`); + // Create a second file to capture the server's stdout and stderr + const outFile = path.join(os.tmpdir(), `kallichore-${sessionId}.out.log`); + + // Determine the path to the wrapper script. + const wrapperName = os.platform() === 'win32' ? 'supervisor-wrapper.bat' : 'supervisor-wrapper.sh'; + const wrapperPath = path.join(this._context.extensionPath, 'resources', wrapperName); + // Start the server in a new terminal this._log.appendLine(`Starting Kallichore server ${shellPath} on port ${port}`); const terminal = vscode.window.createTerminal({ name: 'Kallichore', - shellPath: shellPath, + shellPath: wrapperPath, shellArgs: [ + outFile, + shellPath, '--port', port.toString(), '--token', tokenPath, '--log-level', logLevel, @@ -219,6 +233,46 @@ export class KCApi implements KallichoreAdapterApi { isTransient: false }); + // Listen for the terminal to close. If it closes unexpectedly before + // the start barrier opens, provide some feedback. + const closeListener = vscode.window.onDidCloseTerminal((closedTerminal) => { + // Ignore closed terminals that aren't the one we started + if (closedTerminal === terminal) { + return; + } + + // Ignore if the start barrier is already open (that means the + // server started successfully) + if (this._started.isOpen()) { + return; + } + + // Ignore if it's been more than 5 minutes since the start time + if (Date.now() - startTime > 300000) { + return; + } + + // Read the contents of the output file and log it + const contents = fs.readFileSync(outFile, 'utf8'); + if (terminal.exitStatus && terminal.exitStatus.code) { + this._log.appendLine(`Supervisor terminal closed with exit code ${terminal.exitStatus.code}; output:\n${contents}`); + } else { + this._log.appendLine(`Supervisor terminal closed unexpectedly; output:\n${contents}`); + } + + // Display a notification that directs users to open the log to get more information + vscode.window.showInformationMessage( + vscode.l10n.t('There was an error starting the kernel supervisor. Check the log for more information.'), { + title: vscode.l10n.t('Open Log'), + run: () => { + this._log.show(); + } + }); + }); + + // Ensure this listener is disposed when the API is disposed + this._disposables.push(closeListener); + // Wait for the terminal to start and get the PID await terminal.processId; @@ -285,6 +339,9 @@ export class KCApi implements KallichoreAdapterApi { this._log.appendLine(`Streaming Kallichore server logs from ${logFile} (log level: ${logLevel})`); }); + // Now that we're online, we can dispose of the close listener + closeListener.dispose(); + // Open the started barrier and save the server state since we're online this._started.open(); const state: KallichoreServerState = { @@ -579,6 +636,9 @@ export class KCApi implements KallichoreAdapterApi { this._logStreamer.dispose(); this._logStreamer = undefined; } + + // Dispose of any other disposables + this._disposables.forEach(disposable => disposable.dispose()); } findAvailablePort(excluding: Array, maxTries: number): Promise { From 2f25291a523a52d8df9456727307d2e085dc3d13 Mon Sep 17 00:00:00 2001 From: Jonathan McPherson Date: Wed, 11 Dec 2024 10:21:16 -0800 Subject: [PATCH 2/4] ensure output file is cleaned up --- extensions/positron-supervisor/src/KallichoreAdapterApi.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts index 577e6cd8e60..17305132923 100644 --- a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts +++ b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts @@ -242,7 +242,7 @@ export class KCApi implements KallichoreAdapterApi { } // Ignore if the start barrier is already open (that means the - // server started successfully) + // server started successfully), or if more than 5 minutes have elapsed if (this._started.isOpen()) { return; } @@ -273,6 +273,11 @@ export class KCApi implements KallichoreAdapterApi { // Ensure this listener is disposed when the API is disposed this._disposables.push(closeListener); + // Ensure the output file is cleaned up when the API is disposed + this._disposables.push(new vscode.Disposable(() => { + fs.unlinkSync(outFile); + })); + // Wait for the terminal to start and get the PID await terminal.processId; From 3f2d2692d79064617f6ef79b994dab37b83880c9 Mon Sep 17 00:00:00 2001 From: Jonathan McPherson Date: Wed, 11 Dec 2024 10:39:48 -0800 Subject: [PATCH 3/4] don't bother retrying if terminal has exited --- .../src/KallichoreAdapterApi.ts | 24 +++++++++++++++---- 1 file changed, 19 insertions(+), 5 deletions(-) diff --git a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts index 17305132923..7efbe2602dd 100644 --- a/extensions/positron-supervisor/src/KallichoreAdapterApi.ts +++ b/extensions/positron-supervisor/src/KallichoreAdapterApi.ts @@ -233,11 +233,14 @@ export class KCApi implements KallichoreAdapterApi { isTransient: false }); + // Flag to track if the terminal exited before the start barrier opened + let exited = false; + // Listen for the terminal to close. If it closes unexpectedly before // the start barrier opens, provide some feedback. - const closeListener = vscode.window.onDidCloseTerminal((closedTerminal) => { + const closeListener = vscode.window.onDidCloseTerminal(async (closedTerminal) => { // Ignore closed terminals that aren't the one we started - if (closedTerminal === terminal) { + if (closedTerminal !== terminal) { return; } @@ -252,6 +255,9 @@ export class KCApi implements KallichoreAdapterApi { return; } + // Mark the terminal as exited + exited = true; + // Read the contents of the output file and log it const contents = fs.readFileSync(outFile, 'utf8'); if (terminal.exitStatus && terminal.exitStatus.code) { @@ -261,13 +267,16 @@ export class KCApi implements KallichoreAdapterApi { } // Display a notification that directs users to open the log to get more information - vscode.window.showInformationMessage( + const selection = await vscode.window.showInformationMessage( vscode.l10n.t('There was an error starting the kernel supervisor. Check the log for more information.'), { title: vscode.l10n.t('Open Log'), - run: () => { - this._log.show(); + execute: () => { + this._log.show(false); } }); + if (selection) { + selection.execute(); + } }); // Ensure this listener is disposed when the API is disposed @@ -296,6 +305,11 @@ export class KCApi implements KallichoreAdapterApi { } catch (err) { const elapsed = Date.now() - startTime; + // Has the terminal exited? if it has, there's no point in continuing to retry. + if (exited) { + throw new Error(`The supervisor process exited before the server was ready.`); + } + // ECONNREFUSED is a normal condition during startup; the server // isn't ready yet. Keep trying until we hit the retry limit, // about 2 seconds from the time we got a process ID From 0cbcd64bebdc5daed62259c23112b213571bcc04 Mon Sep 17 00:00:00 2001 From: Jonathan McPherson Date: Wed, 11 Dec 2024 15:24:23 -0800 Subject: [PATCH 4/4] turn off echo right away in supervisor wrapper on windows --- .../positron-supervisor/resources/supervisor-wrapper.bat | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/extensions/positron-supervisor/resources/supervisor-wrapper.bat b/extensions/positron-supervisor/resources/supervisor-wrapper.bat index 3bd76c99180..37629a075e4 100644 --- a/extensions/positron-supervisor/resources/supervisor-wrapper.bat +++ b/extensions/positron-supervisor/resources/supervisor-wrapper.bat @@ -1,3 +1,5 @@ +@echo off + REM --------------------------------------------------------------------------------------------- REM Copyright (C) 2024 Posit Software, PBC. All rights reserved. REM --------------------------------------------------------------------------------------------- @@ -6,8 +8,6 @@ REM This script is used to run a program and capture its output to a file. It is REM used to capture the output of the supervisor process so that it can be displayed REM in the UI in the case of a startup failure. -@echo off - REM Check that the user provided at least two arguments; the first is the output REM file and the second is the program to run and any arguments. If not, print a REM usage message and exit with an error code.