From 8b551882705e500ced51ed1607c65aeb2df398ba Mon Sep 17 00:00:00 2001 From: Paul LeMarquand Date: Wed, 28 Aug 2024 15:18:44 -0400 Subject: [PATCH] Route swift-testing output to /dev/stdout, CONOUT$ Currently we are merging two streams of information to produce swift-testing test output, the JSON event stream written to a named pipe and the stream of data from stdout. This captures both testing events and user outputs produced by things like `print()` statements. However, this approach interleaves the two sources in an arbitrary order. Print statements produced during a test run are typically read after events on the named pipe, which makes it difficult to tell what prints belong to what test. In order to enforce the correct order we can configure swift-testing to write its events to /dev/stdout (or CONOUT$ on Windows). Swift-testing aquires a lock to the `fd` it is writing events and output to, so the order of events and prints is correctly enforced. This also simplifies a lot of the code that worked with the JSON event stream as we can now rely solely on the task's stdout/stderr output without the need for named pipes. When parsing stdout we try and parse a JSON event that matches the swift-testing event schema, and if we fail we print the line directly. If it is parseable, we process it as a swift-testing JSON event and omit it from the test run output. --- .../TestParsers/SwiftTestingOutputParser.ts | 173 +++----- .../TestParsers/TestEventStreamReader.ts | 90 ---- .../TestParsers/XCTestOutputParser.ts | 17 +- src/TestExplorer/TestRunner.ts | 387 ++++++++---------- src/debugger/buildConfig.ts | 1 + src/tasks/SwiftExecution.ts | 7 +- src/tasks/SwiftProcess.ts | 3 +- src/tasks/SwiftPseudoterminal.ts | 8 +- src/tasks/SwiftTaskProvider.ts | 5 + src/utilities/ansi.ts | 57 +++ .../SwiftTestingOutputParser.test.ts | 126 ++++-- .../TestExplorerIntegration.test.ts | 2 +- .../testexplorer/XCTestOutputParser.test.ts | 15 +- 13 files changed, 442 insertions(+), 449 deletions(-) delete mode 100644 src/TestExplorer/TestParsers/TestEventStreamReader.ts create mode 100644 src/utilities/ansi.ts diff --git a/src/TestExplorer/TestParsers/SwiftTestingOutputParser.ts b/src/TestExplorer/TestParsers/SwiftTestingOutputParser.ts index 89e48489d..7e2e63a28 100644 --- a/src/TestExplorer/TestParsers/SwiftTestingOutputParser.ts +++ b/src/TestExplorer/TestParsers/SwiftTestingOutputParser.ts @@ -13,17 +13,11 @@ //===----------------------------------------------------------------------===// import * as vscode from "vscode"; -import * as readline from "readline"; -import { Readable } from "stream"; -import { - INamedPipeReader, - UnixNamedPipeReader, - WindowsNamedPipeReader, -} from "./TestEventStreamReader"; import { ITestRunState } from "./TestRunState"; import { TestClass } from "../TestDiscovery"; -import { regexEscapedString, sourceLocationToVSCodeLocation } from "../../utilities/utilities"; -import { exec } from "child_process"; +import { sourceLocationToVSCodeLocation } from "../../utilities/utilities"; +import { StringColor } from "../../utilities/ansi"; +import { ITestOutputParser } from "./XCTestOutputParser"; // All events produced by a swift-testing run will be one of these three types. // Detailed information about swift-testing's JSON schema is available here: @@ -162,10 +156,12 @@ export interface SourceLocation { column: number; } -export class SwiftTestingOutputParser { +export class SwiftTestingOutputParser implements ITestOutputParser { + public logs: string[] = []; + private completionMap = new Map(); private testCaseMap = new Map>(); - private path?: string; + private preambleComplete = false; constructor( public testRunStarted: () => void, @@ -173,98 +169,66 @@ export class SwiftTestingOutputParser { ) {} /** - * Watches for test events on the named pipe at the supplied path. - * As events are read they are parsed and recorded in the test run state. + * Parse test run output looking for both raw output and JSON events. + * @param output A chunk of stdout emitted during a test run. + * @param runState The test run state to be updated by the output + * @param logger A logging function to capture output not associated with a specific test. */ - public async watch( - path: string, - runState: ITestRunState, - pipeReader?: INamedPipeReader - ): Promise { - this.path = path; - - // Creates a reader based on the platform unless being provided in a test context. - const reader = pipeReader ?? this.createReader(path); - const readlinePipe = new Readable({ - read() {}, - }); - - // Use readline to automatically chunk the data into lines, - // and then take each line and parse it as JSON. - const rl = readline.createInterface({ - input: readlinePipe, - crlfDelay: Infinity, - }); - - rl.on("line", line => this.parse(JSON.parse(line), runState)); - - reader.start(readlinePipe); - } + parseResult(output: string, runState: ITestRunState, logger: (output: string) => void): void { + this.logs.push(output); + + for (const line of output.split("\n")) { + if (line.startsWith("{")) { + try { + // On Windows lines end will end with some ANSI characters, so + // work around that by trying to parse from the start of the line + // to the last '}' character. + const closingBrace = line.lastIndexOf("}"); + if (closingBrace === -1) { + // Break out of the try block and continue + throw new Error("No closing brace found"); + } + + const maybeJSON = line.substring(0, closingBrace + 1); + + const event = JSON.parse(maybeJSON); + if (this.isValidEvent(event)) { + this.parse(event, runState); + this.preambleComplete = true; + continue; + } + } catch { + // Output wasn't valid JSON, continue and treat it like regular output + } + } - /** - * Closes the FIFO pipe after a test run. This must be called at the - * end of a run regardless of the run's success or failure. - */ - public async close() { - if (!this.path) { - return; + // Any line in stdout that fails to match as a swift-testing line is treated + // as a user printed value and recorded to the test run output with no associated test. + const trimmed = line.trim(); + if (this.preambleComplete && trimmed.length > 0) { + logger(`${trimmed}\r\n`); + } } - - await new Promise(resolve => { - exec(`echo '{}' > ${this.path}`, () => { - resolve(); - }); - }); } /** - * Parses stdout of a test run looking for lines that were not captured by - * a JSON event and injecting them in to the test run output. - * @param chunk A chunk of stdout emitted during a test run. + * Type guard for validating that an event is a valid SwiftTestEvent. + * This is not an exaustive validation, but it is sufficient for our purposes. + * + * @param event The event to validate. + * @returns `true` if the event is a valid SwiftTestEvent, `false` otherwise. */ - public parseStdout = (() => { - const values = [ - ...Object.values(TestSymbol) - .filter(symbol => symbol !== TestSymbol.none) - .map(symbol => - regexEscapedString( - // Trim the ANSI reset code from the search since some lines - // are fully colorized from the symbol to the end of line. - SymbolRenderer.eventMessageSymbol(symbol).replace( - SymbolRenderer.resetANSIEscapeCode, - "" - ) - ) - ), - // It is possible there is no symbol for a line produced by swift-testing, - // for instance if the user has a multi line comment before a failing expectation - // only the first line of the printed comment will have a symbol, but to make the - // indentation consistent the subsequent lines will have three spaces. We don't want - // to treat this as output produced by the user during the test run, so omit these. - // This isn't ideal since this will swallow lines the user prints if they start with - // three spaces, but until we have user output as part of the JSON event stream we have - // this workaround. - " ", - ]; - - // Build a regex of all the line beginnings that come out of swift-testing events. - const isSwiftTestingLineBeginning = new RegExp(`^${values.join("|")}`); - - return (chunk: string, runState: ITestRunState) => { - for (const line of chunk.split("\n")) { - // Any line in stdout that fails to match as a swift-testing line is treated - // as a user printed value and recorded to the test run output with no associated test. - if (line.trim().length > 0 && isSwiftTestingLineBeginning.test(line) === false) { - runState.recordOutput(undefined, `${line}\r\n`); - } - } - }; - })(); - - private createReader(path: string): INamedPipeReader { - return process.platform === "win32" - ? new WindowsNamedPipeReader(path) - : new UnixNamedPipeReader(path); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + private isValidEvent(event: any): event is SwiftTestEvent { + return ( + typeof event === "object" && + event !== null && + (event.kind === "test" || + event.kind === "event" || + event.kind === "metadata" || + event.kind === "runStarted" || + event.kind === "runEnded") + ); } private testName(id: string): string { @@ -506,7 +470,7 @@ export class SwiftTestingOutputParser { return; } - this.recordOutput(runState, item.payload.messages, undefined); + // this.recordOutput(runState, item.payload.messages, undefined); } } } @@ -523,14 +487,12 @@ export class MessageRenderer { } private static colorize(symbolType: TestSymbol, message: string): string { - const ansiEscapeCodePrefix = "\u{001B}["; - const resetANSIEscapeCode = `${ansiEscapeCodePrefix}0m`; switch (symbolType) { case TestSymbol.details: case TestSymbol.skip: case TestSymbol.difference: case TestSymbol.passWithKnownIssue: - return `${ansiEscapeCodePrefix}90m${message}${resetANSIEscapeCode}`; + return StringColor.default(message); default: return message; } @@ -548,9 +510,6 @@ export class SymbolRenderer { return this.colorize(symbol, this.symbol(symbol)); } - static ansiEscapeCodePrefix = "\u{001B}["; - static resetANSIEscapeCode = `${SymbolRenderer.ansiEscapeCodePrefix}0m`; - // This is adapted from // https://github.com/apple/swift-testing/blob/786ade71421eb1d8a9c1d99c902cf1c93096e7df/Sources/Testing/Events/Recorder/Event.Symbol.swift#L102 public static symbol(symbol: TestSymbol): string { @@ -604,13 +563,13 @@ export class SymbolRenderer { case TestSymbol.skip: case TestSymbol.difference: case TestSymbol.passWithKnownIssue: - return `${SymbolRenderer.ansiEscapeCodePrefix}90m${symbol}${SymbolRenderer.resetANSIEscapeCode}`; + return StringColor.default(symbol); case TestSymbol.pass: - return `${SymbolRenderer.ansiEscapeCodePrefix}92m${symbol}${SymbolRenderer.resetANSIEscapeCode}`; + return StringColor.green(symbol); case TestSymbol.fail: - return `${SymbolRenderer.ansiEscapeCodePrefix}91m${symbol}${SymbolRenderer.resetANSIEscapeCode}`; + return StringColor.red(symbol); case TestSymbol.warning: - return `${SymbolRenderer.ansiEscapeCodePrefix}93m${symbol}${SymbolRenderer.resetANSIEscapeCode}`; + return StringColor.yellow(symbol); case TestSymbol.none: default: return symbol; diff --git a/src/TestExplorer/TestParsers/TestEventStreamReader.ts b/src/TestExplorer/TestParsers/TestEventStreamReader.ts deleted file mode 100644 index 9278fb4b9..000000000 --- a/src/TestExplorer/TestParsers/TestEventStreamReader.ts +++ /dev/null @@ -1,90 +0,0 @@ -//===----------------------------------------------------------------------===// -// -// This source file is part of the VS Code Swift open source project -// -// Copyright (c) 2024 the VS Code Swift project authors -// Licensed under Apache License v2.0 -// -// See LICENSE.txt for license information -// See CONTRIBUTORS.txt for the list of VS Code Swift project authors -// -// SPDX-License-Identifier: Apache-2.0 -// -//===----------------------------------------------------------------------===// - -import * as fs from "fs"; -import * as net from "net"; -import { Readable } from "stream"; - -export interface INamedPipeReader { - start(readable: Readable): Promise; -} - -/** - * Reads from a named pipe on Windows and forwards data to a `Readable` stream. - * Note that the path must be in the Windows named pipe format of `\\.\pipe\pipename`. - */ -export class WindowsNamedPipeReader implements INamedPipeReader { - constructor(private path: string) {} - - public async start(readable: Readable) { - return new Promise((resolve, reject) => { - try { - const server = net.createServer(function (stream) { - stream.on("data", data => readable.push(data)); - stream.on("error", () => server.close()); - stream.on("end", function () { - readable.push(null); - server.close(); - }); - }); - - server.listen(this.path, () => resolve()); - } catch (error) { - reject(error); - } - }); - } -} - -/** - * Reads from a unix FIFO pipe and forwards data to a `Readable` stream. - * Note that the pipe at the supplied path should be created with `mkfifo` - * before calling `start()`. - */ -export class UnixNamedPipeReader implements INamedPipeReader { - constructor(private path: string) {} - - public async start(readable: Readable) { - return new Promise((resolve, reject) => { - fs.open(this.path, fs.constants.O_RDONLY, (err, fd) => { - if (err) { - return reject(err); - } - try { - // Create our own readable stream that handles backpressure. - // Using a net.Socket to read the pipe has an 8kb internal buffer, - // meaning we couldn't read from writes that were > 8kb. - const pipe = fs.createReadStream("", { fd }); - - pipe.on("data", data => { - if (!readable.push(data)) { - pipe.pause(); - } - }); - - readable.on("drain", () => pipe.resume()); - pipe.on("error", () => pipe.close()); - pipe.on("end", () => { - readable.push(null); - fs.close(fd); - }); - - resolve(); - } catch (error) { - fs.close(fd, () => reject(error)); - } - }); - }); - } -} diff --git a/src/TestExplorer/TestParsers/XCTestOutputParser.ts b/src/TestExplorer/TestParsers/XCTestOutputParser.ts index 0093d684b..fbc38a055 100644 --- a/src/TestExplorer/TestParsers/XCTestOutputParser.ts +++ b/src/TestExplorer/TestParsers/XCTestOutputParser.ts @@ -69,13 +69,16 @@ export const nonDarwinTestRegex = { failedSuite: /^Test Suite '(.*)' failed/, }; -export interface IXCTestOutputParser { - parseResult(output: string, runState: ITestRunState): void; +export interface ITestOutputParser { + logs: string[]; + parseResult(output: string, runState: ITestRunState, logger: (output: string) => void): void; } -export class ParallelXCTestOutputParser implements IXCTestOutputParser { +export class ParallelXCTestOutputParser implements ITestOutputParser { private outputParser: XCTestOutputParser; + public logs: string[] = []; + /** * Create an ParallelXCTestOutputParser. * Optional regex can be supplied for tests. @@ -88,6 +91,8 @@ export class ParallelXCTestOutputParser implements IXCTestOutputParser { } public parseResult(output: string, runState: ITestRunState) { + this.logs = [output]; + // From 5.7 to 5.10 running with the --parallel option dumps the test results out // to the console with no newlines, so it isn't possible to distinguish where errors // begin and end. Consequently we can't record them, and so we manually mark them @@ -133,7 +138,9 @@ class ParallelXCTestRunStateProxy implements ITestRunState { } /* eslint-enable @typescript-eslint/no-unused-vars */ -export class XCTestOutputParser implements IXCTestOutputParser { +export class XCTestOutputParser implements ITestOutputParser { + public logs: string[] = []; + private regex: TestRegex; /** @@ -149,6 +156,8 @@ export class XCTestOutputParser implements IXCTestOutputParser { * @param output Output from `swift test` */ public parseResult(output: string, runState: ITestRunState) { + this.logs.push(output); + const output2 = output.replace(/\r\n/g, "\n"); const lines = output2.split("\n"); if (runState.excess) { diff --git a/src/TestExplorer/TestRunner.ts b/src/TestExplorer/TestRunner.ts index 26ff72fc5..68eb6afbb 100644 --- a/src/TestExplorer/TestRunner.ts +++ b/src/TestExplorer/TestRunner.ts @@ -15,15 +15,14 @@ import * as vscode from "vscode"; import * as path from "path"; import * as stream from "stream"; -import * as os from "os"; import * as asyncfs from "fs/promises"; import { FolderContext } from "../FolderContext"; -import { execFile, getErrorDescription } from "../utilities/utilities"; +import { getErrorDescription } from "../utilities/utilities"; import { createSwiftTask } from "../tasks/SwiftTaskProvider"; import configuration from "../configuration"; import { WorkspaceContext } from "../WorkspaceContext"; import { - IXCTestOutputParser, + ITestOutputParser, ParallelXCTestOutputParser, XCTestOutputParser, } from "./TestParsers/XCTestOutputParser"; @@ -33,7 +32,6 @@ import { TaskOperation } from "../tasks/TaskQueue"; import { TestXUnitParser } from "./TestXUnitParser"; import { ITestRunState, TestIssueDiff } from "./TestParsers/TestRunState"; import { TestRunArguments } from "./TestRunArguments"; -import { TemporaryFolder } from "../utilities/tempFolder"; import { TestClass, runnableTag, upsertTestItem } from "./TestDiscovery"; import { TestCoverage } from "../coverage/LcovResults"; import { BuildConfigurationFactory, TestingConfigurationFactory } from "../debugger/buildConfig"; @@ -60,11 +58,11 @@ export interface TestRunState { export class TestRunProxy { private testRun?: vscode.TestRun; private addedTestItems: { testClass: TestClass; parentIndex: number }[] = []; - private runStarted: boolean = false; private queuedOutput: string[] = []; - private _testItems: vscode.TestItem[]; private iteration: number | undefined; public coverage: TestCoverage; + private _runStarted: boolean = false; + private _testItems: vscode.TestItem[]; public testRunCompleteEmitter = new vscode.EventEmitter(); public onTestRunComplete: vscode.Event; @@ -87,6 +85,10 @@ export class TestRunProxy { return this._testItems; } + public get runStarted(): boolean { + return this._runStarted; + } + constructor( private testRunRequest: vscode.TestRunRequest, private controller: vscode.TestController, @@ -102,7 +104,7 @@ export class TestRunProxy { if (this.runStarted) { return; } - this.runStarted = true; + this._runStarted = true; // When a test run starts we need to do several things: // - Create new TestItems for each paramterized test that was added @@ -147,9 +149,7 @@ export class TestRunProxy { this._testItems = [...this.testItems, ...addedTestItems]; // Forward any output captured before the testRun was created. - for (const outputLine of this.queuedOutput) { - this.testRun.appendOutput(outputLine); - } + this.testRun.appendOutput(this.queuedOutput.join("")); this.queuedOutput = []; for (const test of this.testItems) { @@ -263,8 +263,8 @@ export class TestRunProxy { export class TestRunner { public testRun: TestRunProxy; private testArgs: TestRunArguments; - private xcTestOutputParser: IXCTestOutputParser; - private swiftTestOutputParser: SwiftTestingOutputParser; + private xcTestOutputParser: ITestOutputParser; + private swiftTestOutputParser: ITestOutputParser; /** * Constructor for TestRunner @@ -480,46 +480,33 @@ export class TestRunner { // Run swift-testing first, then XCTest. // swift-testing being parallel by default should help these run faster. if (this.testArgs.hasSwiftTestingTests) { - const fifoPipePath = this.generateFifoPipePath(); - - await TemporaryFolder.withNamedTemporaryFile(fifoPipePath, async () => { - // macOS/Linux require us to create the named pipe before we use it. - // Windows just lets us communicate by specifying a pipe path without any ceremony. - if (process.platform !== "win32") { - await execFile("mkfifo", [fifoPipePath], undefined, this.folderContext); - } - - const testBuildConfig = await TestingConfigurationFactory.swiftTestingConfig( - this.folderContext, - fifoPipePath, - this.testKind, - this.testArgs.swiftTestArgs, - true - ); - - if (testBuildConfig === null) { - return this.testRun.runState; - } + const eventStreamOutputPath = this.swiftTestingEventStreamOutput(); + const testBuildConfig = await TestingConfigurationFactory.swiftTestingConfig( + this.folderContext, + eventStreamOutputPath, + this.testKind, + this.testArgs.swiftTestArgs, + true + ); - const outputStream = this.testOutputWritable(TestLibrary.swiftTesting, runState); - if (token.isCancellationRequested) { - outputStream.end(); - return this.testRun.runState; - } + if (testBuildConfig === null) { + return this.testRun.runState; + } - // Watch the pipe for JSONL output and parse the events into test explorer updates. - // The await simply waits for the watching to be configured. - await this.swiftTestOutputParser.watch(fifoPipePath, runState); + const outputStream = this.testOutputWritable(TestLibrary.swiftTesting, runState); + if (token.isCancellationRequested) { + outputStream.end(); + return this.testRun.runState; + } - await this.launchTests( - runState, - this.testKind === TestKind.parallel ? TestKind.standard : this.testKind, - token, - outputStream, - testBuildConfig, - TestLibrary.swiftTesting - ); - }); + await this.launchTests( + runState, + this.testKind === TestKind.parallel ? TestKind.standard : this.testKind, + token, + outputStream, + testBuildConfig, + TestLibrary.swiftTesting + ); } if (this.testArgs.hasXCTests) { @@ -584,15 +571,18 @@ export class TestRunner { // Test failures result in error code 1 if (error !== 1) { this.testRun.appendOutput(`\r\nError: ${getErrorDescription(error)}`); - } else { - // swift-testing tests don't have their run started until the .swift-testing binary has - // sent all of its `test` events, which enumerate the parameterized test cases. This means that - // build output is witheld until the run starts. If there is a compile error, unless we call - // `testRunStarted()` to flush the buffer of test result output, the build error will be silently - // discarded. If the test run has already started this is a no-op so its safe to call it multiple times. - this.testRun.testRunStarted(); - - this.swiftTestOutputParser.close(); + } else if (!this.testRun.runStarted) { + // If the tests never started we can assume a build error occured. + // Grab the entire output captured during the build and add it to the + // test run's output to make it easy to see any compile erorrs that may have occured. + switch (testLibrary) { + case TestLibrary.swiftTesting: + this.testRun.appendOutput(this.swiftTestOutputParser.logs.join("")); + break; + case TestLibrary.xctest: + this.testRun.appendOutput(this.xcTestOutputParser.logs.join("")); + break; + } } } finally { outputStream.end(); @@ -642,15 +632,9 @@ export class TestRunner { { ...process.env, ...testBuildConfig.env } ); + // Forward the task's output to the output stream that can be parsed for test results. task.execution.onDidWrite(str => { - const replaced = str - .replace("[1/1] Planning build", "") // Work around SPM still emitting progress when doing --no-build. - .replace(/\[1\/1\] Write swift-version-.*/gm, "") - .replace( - /LLVM Profile Error: Failed to write file "default.profraw": Operation not permitted\r\n/gm, - "" - ); // Work around benign LLVM coverage warnings - outputStream.write(replaced); + outputStream.write(str); }); let cancellation: vscode.Disposable; @@ -758,160 +742,140 @@ export class TestRunner { const subscriptions: vscode.Disposable[] = []; const buildConfigs: Array = []; - const fifoPipePath = this.generateFifoPipePath(); - - await TemporaryFolder.withNamedTemporaryFile(fifoPipePath, async () => { - if (this.testArgs.hasSwiftTestingTests) { - // macOS/Linux require us to create the named pipe before we use it. - // Windows just lets us communicate by specifying a pipe path without any ceremony. - if (process.platform !== "win32") { - await execFile("mkfifo", [fifoPipePath], undefined, this.folderContext); - } + const eventStreamOutputPath = this.swiftTestingEventStreamOutput(); - const swiftTestBuildConfig = await TestingConfigurationFactory.swiftTestingConfig( - this.folderContext, - fifoPipePath, - this.testKind, - this.testArgs.swiftTestArgs, - true - ); + if (this.testArgs.hasSwiftTestingTests) { + const swiftTestBuildConfig = await TestingConfigurationFactory.swiftTestingConfig( + this.folderContext, + eventStreamOutputPath, + this.testKind, + this.testArgs.swiftTestArgs, + true + ); - if (swiftTestBuildConfig !== null) { - swiftTestBuildConfig.testType = TestLibrary.swiftTesting; - swiftTestBuildConfig.preLaunchTask = null; + if (swiftTestBuildConfig !== null) { + swiftTestBuildConfig.testType = TestLibrary.swiftTesting; + swiftTestBuildConfig.preLaunchTask = null; + + // If we're testing in both frameworks we're going to start more than one debugging + // session. If both build configurations have the same name LLDB will replace the + // output of the first one in the Debug Console with the output of the second one. + // If they each have a unique name the Debug Console gets a nice dropdown the user + // can switch between to see the output for both sessions. + swiftTestBuildConfig.name = `Swift Testing: ${swiftTestBuildConfig.name}`; + + // output test build configuration + if (configuration.diagnostics) { + const configJSON = JSON.stringify(swiftTestBuildConfig); + this.workspaceContext.outputChannel.logDiagnostic( + `swift-testing Debug Config: ${configJSON}`, + this.folderContext.name + ); + } - // If we're testing in both frameworks we're going to start more than one debugging - // session. If both build configurations have the same name LLDB will replace the - // output of the first one in the Debug Console with the output of the second one. - // If they each have a unique name the Debug Console gets a nice dropdown the user - // can switch between to see the output for both sessions. - swiftTestBuildConfig.name = `Swift Testing: ${swiftTestBuildConfig.name}`; + buildConfigs.push(swiftTestBuildConfig); + } + } - // output test build configuration - if (configuration.diagnostics) { - const configJSON = JSON.stringify(swiftTestBuildConfig); - this.workspaceContext.outputChannel.logDiagnostic( - `swift-testing Debug Config: ${configJSON}`, - this.folderContext.name - ); - } + // create launch config for testing + if (this.testArgs.hasXCTests) { + const xcTestBuildConfig = await TestingConfigurationFactory.xcTestConfig( + this.folderContext, + this.testKind, + this.testArgs.xcTestArgs, + true + ); - buildConfigs.push(swiftTestBuildConfig); + if (xcTestBuildConfig !== null) { + xcTestBuildConfig.testType = TestLibrary.xctest; + xcTestBuildConfig.preLaunchTask = null; + xcTestBuildConfig.name = `XCTest: ${xcTestBuildConfig.name}`; + + // output test build configuration + if (configuration.diagnostics) { + const configJSON = JSON.stringify(xcTestBuildConfig); + this.workspaceContext.outputChannel.logDiagnostic( + `XCTest Debug Config: ${configJSON}`, + this.folderContext.name + ); } + + buildConfigs.push(xcTestBuildConfig); } + } - // create launch config for testing - if (this.testArgs.hasXCTests) { - const xcTestBuildConfig = await TestingConfigurationFactory.xcTestConfig( - this.folderContext, - this.testKind, - this.testArgs.xcTestArgs, - true - ); + const validBuildConfigs = buildConfigs.filter( + config => config !== null + ) as vscode.DebugConfiguration[]; - if (xcTestBuildConfig !== null) { - xcTestBuildConfig.testType = TestLibrary.xctest; - xcTestBuildConfig.preLaunchTask = null; - xcTestBuildConfig.name = `XCTest: ${xcTestBuildConfig.name}`; + const debugRuns = validBuildConfigs.map(config => { + return () => + new Promise((resolve, reject) => { + // add cancelation + const startSession = vscode.debug.onDidStartDebugSession(session => { + if (config.testType === TestLibrary.xctest) { + this.testRun.testRunStarted(); + } - // output test build configuration - if (configuration.diagnostics) { - const configJSON = JSON.stringify(xcTestBuildConfig); this.workspaceContext.outputChannel.logDiagnostic( - `XCTest Debug Config: ${configJSON}`, + "Start Test Debugging", this.folderContext.name ); - } - buildConfigs.push(xcTestBuildConfig); - } - } - - const validBuildConfigs = buildConfigs.filter( - config => config !== null - ) as vscode.DebugConfiguration[]; - - const debugRuns = validBuildConfigs.map(config => { - return () => - new Promise((resolve, reject) => { - // add cancelation - const startSession = vscode.debug.onDidStartDebugSession(session => { - if (config.testType === TestLibrary.xctest) { - this.testRun.testRunStarted(); - } + const outputHandler = this.testOutputHandler(config.testType, runState); + LoggingDebugAdapterTracker.setDebugSessionCallback(session, output => { + outputHandler(output); + }); + const cancellation = token.onCancellationRequested(() => { this.workspaceContext.outputChannel.logDiagnostic( - "Start Test Debugging", + "Test Debugging Cancelled", this.folderContext.name ); - - const outputHandler = this.testOutputHandler(config.testType, runState); - LoggingDebugAdapterTracker.setDebugSessionCallback(session, output => { - outputHandler(output); - }); - - const cancellation = token.onCancellationRequested(() => { - this.workspaceContext.outputChannel.logDiagnostic( - "Test Debugging Cancelled", - this.folderContext.name - ); - vscode.debug.stopDebugging(session); - }); - subscriptions.push(cancellation); + vscode.debug.stopDebugging(session); }); - subscriptions.push(startSession); - - vscode.debug - .startDebugging(this.folderContext.workspaceFolder, config) - .then( - async started => { - if (started) { - if (config.testType === TestLibrary.swiftTesting) { - // Watch the pipe for JSONL output and parse the events into test explorer updates. - // The await simply waits for the watching to be configured. - await this.swiftTestOutputParser.watch( - fifoPipePath, - runState - ); - } - - // show test results pane + subscriptions.push(cancellation); + }); + subscriptions.push(startSession); + + vscode.debug.startDebugging(this.folderContext.workspaceFolder, config).then( + async started => { + if (started) { + // show test results pane + vscode.commands.executeCommand("testing.showMostRecentOutput"); + + const terminateSession = vscode.debug.onDidTerminateDebugSession( + () => { + this.workspaceContext.outputChannel.logDiagnostic( + "Stop Test Debugging", + this.folderContext.name + ); + // dispose terminate debug handler + subscriptions.forEach(sub => sub.dispose()); + vscode.commands.executeCommand( - "testing.showMostRecentOutput" + "workbench.view.extension.test" ); - const terminateSession = - vscode.debug.onDidTerminateDebugSession(() => { - this.workspaceContext.outputChannel.logDiagnostic( - "Stop Test Debugging", - this.folderContext.name - ); - // dispose terminate debug handler - subscriptions.forEach(sub => sub.dispose()); - - vscode.commands.executeCommand( - "workbench.view.extension.test" - ); - - resolve(); - }); - subscriptions.push(terminateSession); - } else { - subscriptions.forEach(sub => sub.dispose()); - reject("Debugger not started"); + resolve(); } - }, - reason => { - subscriptions.forEach(sub => sub.dispose()); - reject(reason); - } - ); - }); - }); - - // Run each debugging session sequentially - await debugRuns.reduce((p, fn) => p.then(() => fn()), Promise.resolve()); + ); + subscriptions.push(terminateSession); + } else { + subscriptions.forEach(sub => sub.dispose()); + reject("Debugger not started"); + } + }, + reason => { + subscriptions.forEach(sub => sub.dispose()); + reject(reason); + } + ); + }); }); + + // Run each debugging session sequentially + await debugRuns.reduce((p, fn) => p.then(() => fn()), Promise.resolve()); } /** Returns a callback that handles a chunk of stdout output from a test run. */ @@ -920,26 +884,19 @@ export class TestRunner { runState: TestRunnerTestRunState // eslint-disable-next-line @typescript-eslint/no-explicit-any ): (chunk: any) => void { - let preambleComplete = false; + let outputParser: ITestOutputParser; switch (testLibrary) { case TestLibrary.swiftTesting: - return chunk => { - // Capture all the output from the build process up until the test run starts. - // From there the SwiftTestingOutputParser reconstructs the test output from the JSON events - // emitted by the swift-testing binary during the run. This allows individual messages to be - // associated with their respective tests while still producing a complete test run log. - if (chunk.indexOf("Test run started.") !== -1) { - preambleComplete = true; - } - if (!preambleComplete) { - this.testRun.appendOutput(chunk.toString().replace(/\n/g, "\r\n")); - } else { - this.swiftTestOutputParser.parseStdout(chunk.toString(), runState); - } - }; + outputParser = this.swiftTestOutputParser; + break; case TestLibrary.xctest: - return chunk => this.xcTestOutputParser.parseResult(chunk.toString(), runState); + outputParser = this.xcTestOutputParser; + break; } + return chunk => + outputParser.parseResult(chunk.toString(), runState, line => + this.testRun.appendOutput(line) + ); } /** Returns a `stream.Writable` that handles a chunk of stdout output from a test run. */ @@ -965,10 +922,8 @@ export class TestRunner { } } - private generateFifoPipePath(): string { - return process.platform === "win32" - ? `\\\\.\\pipe\\vscodemkfifo-${Date.now()}` - : path.join(os.tmpdir(), `vscodemkfifo-${Date.now()}`); + private swiftTestingEventStreamOutput(): string { + return process.platform === "win32" ? "CONOUT$" : "/dev/stdout"; } } diff --git a/src/debugger/buildConfig.ts b/src/debugger/buildConfig.ts index 57783d7e4..e6a2fe6bc 100644 --- a/src/debugger/buildConfig.ts +++ b/src/debugger/buildConfig.ts @@ -446,6 +446,7 @@ export class TestingConfigurationFactory { "0", "--experimental-event-stream-output", this.fifoPipePath, + "--quiet", ]; } diff --git a/src/tasks/SwiftExecution.ts b/src/tasks/SwiftExecution.ts index d7b23e515..e60859022 100644 --- a/src/tasks/SwiftExecution.ts +++ b/src/tasks/SwiftExecution.ts @@ -18,6 +18,7 @@ import { SwiftPseudoterminal } from "./SwiftPseudoterminal"; export interface SwiftExecutionOptions extends vscode.ProcessExecutionOptions { presentation?: vscode.TaskPresentationOptions; + ttyCols?: number; } /** @@ -33,7 +34,11 @@ export class SwiftExecution extends vscode.CustomExecution { swiftProcess: SwiftProcess = new SwiftPtyProcess(command, args, options) ) { super(async () => { - return new SwiftPseudoterminal(swiftProcess, options.presentation || {}); + return new SwiftPseudoterminal( + swiftProcess, + options.presentation || {}, + options.ttyCols + ); }); this.onDidWrite = swiftProcess.onDidWrite; this.onDidClose = swiftProcess.onDidClose; diff --git a/src/tasks/SwiftProcess.ts b/src/tasks/SwiftProcess.ts index d697082c1..fb67d1db3 100644 --- a/src/tasks/SwiftProcess.ts +++ b/src/tasks/SwiftProcess.ts @@ -89,7 +89,7 @@ export class SwiftPtyProcess implements SwiftProcess { constructor( public readonly command: string, public readonly args: string[], - private options: vscode.ProcessExecutionOptions = {} + private options: vscode.ProcessExecutionOptions & { ttyCols?: number } = {} ) {} spawn(): void { @@ -103,6 +103,7 @@ export class SwiftPtyProcess implements SwiftProcess { this.spawnedProcess = spawn(this.command, this.args, { cwd: this.options.cwd, env: { ...process.env, ...this.options.env }, + cols: this.options.ttyCols, useConpty, }); this.spawnEmitter.fire(); diff --git a/src/tasks/SwiftPseudoterminal.ts b/src/tasks/SwiftPseudoterminal.ts index 9fa2c77db..790d4d8b7 100644 --- a/src/tasks/SwiftPseudoterminal.ts +++ b/src/tasks/SwiftPseudoterminal.ts @@ -27,7 +27,8 @@ export class SwiftPseudoterminal implements vscode.Pseudoterminal, vscode.Dispos constructor( private swiftProcess: SwiftProcess, - private options: vscode.TaskPresentationOptions + private options: vscode.TaskPresentationOptions, + private ttyCols?: number ) {} private disposables: vscode.Disposable[] = []; @@ -97,7 +98,10 @@ export class SwiftPseudoterminal implements vscode.Pseudoterminal, vscode.Dispos } setDimensions(dimensions: vscode.TerminalDimensions): void { - this.swiftProcess.setDimensions(dimensions); + this.swiftProcess.setDimensions({ + columns: this.ttyCols ?? dimensions.columns, + rows: dimensions.rows, + }); } onDidWrite: vscode.Event = this.writeEmitter.event; diff --git a/src/tasks/SwiftTaskProvider.ts b/src/tasks/SwiftTaskProvider.ts index 6bca3c816..f5b339a50 100644 --- a/src/tasks/SwiftTaskProvider.ts +++ b/src/tasks/SwiftTaskProvider.ts @@ -327,6 +327,11 @@ export function createSwiftTask( cwd: fullCwd, env: env, presentation, + // Some Windows task configurations will inject newlines at the default, + // column width which breaks some tasks that rely on parsing tty output. + // Work around this by setting the column width of the terminal to + // Int32.MAX_VALUE and let the VS Code terminal renderer wrap the output. + ttyCols: 2147483647, // max Int32 value }) ); // This doesn't include any quotes added by VS Code. diff --git a/src/utilities/ansi.ts b/src/utilities/ansi.ts new file mode 100644 index 000000000..c60c0f8a3 --- /dev/null +++ b/src/utilities/ansi.ts @@ -0,0 +1,57 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the VS Code Swift open source project +// +// Copyright (c) 2024 the VS Code Swift project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of VS Code Swift project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +export const ansiEscapeCodePrefix = "\u{001B}["; +export const resetANSIEscapeCode = `${ansiEscapeCodePrefix}0m`; + +/** + * Utilities for colorizing strings in environments that support rendering ANSI escape codes. + */ +export class StringColor { + static default(str: string) { + return wrapANSI("90m", str); + } + + static red(str: string) { + return wrapANSI("91m", str); + } + + static green(str: string) { + return wrapANSI("92m", str); + } + + static yellow(str: string) { + return wrapANSI("93m", str); + } +} + +/** + * Wrap a string with an ANSI command. + * @param command The code to use. Supply only the command, omitting the leading escape character and `[`. + * @param value The value to wrap + * @returns A wrapped value + */ +export function wrapANSI(command: string, value: string) { + return `${ansiEscapeCodePrefix}${command}${value}${resetANSIEscapeCode}`; +} + +/** + * Returns true if the supplied string contains an escape sequence that clears the line and resets + * the cursor to the beginning of the line. + * @param str A string to check + * @returns If the escape code exists + */ +export function containsErasedLine(str: string) { + return str.indexOf(`${ansiEscapeCodePrefix}2K\r`) !== -1; +} diff --git a/test/suite/testexplorer/SwiftTestingOutputParser.test.ts b/test/suite/testexplorer/SwiftTestingOutputParser.test.ts index 12149bf56..cc07d9e83 100644 --- a/test/suite/testexplorer/SwiftTestingOutputParser.test.ts +++ b/test/suite/testexplorer/SwiftTestingOutputParser.test.ts @@ -27,17 +27,9 @@ import { MessageRenderer, } from "../../../src/TestExplorer/TestParsers/SwiftTestingOutputParser"; import { TestRunState, TestStatus } from "./MockTestRunState"; -import { Readable } from "stream"; -class TestEventStream { - constructor(private items: SwiftTestEvent[]) {} - - async start(readable: Readable) { - this.items.forEach(item => { - readable.push(`${JSON.stringify(item)}\n`); - }); - readable.push(null); - } +function buildEventStream(items: (SwiftTestEvent | string)[]): string { + return items.map(item => (typeof item === "string" ? item : JSON.stringify(item))).join("\n"); } suite("SwiftTestingOutputParser Suite", () => { @@ -50,6 +42,22 @@ suite("SwiftTestingOutputParser Suite", () => { ); }); + async function parseResults( + parser: SwiftTestingOutputParser, + events: string, + testRunState: TestRunState, + expectedLogOutput: string[] = [] + ) { + const logs: string[] = []; + await parser.parseResult(events, testRunState, output => logs.push(output)); + assert.deepStrictEqual( + logs, + expectedLogOutput.map(line => `${line}\r\n`), + "Unexpected test run log output" + ); + return testRunState.tests; + } + type ExtractPayload = T extends { payload: infer E } ? E : never; function testEvent( name: ExtractPayload["kind"], @@ -77,16 +85,16 @@ suite("SwiftTestingOutputParser Suite", () => { test("Passed test", async () => { const testRunState = new TestRunState(["MyTests.MyTests/testPass()"], true); - const events = new TestEventStream([ + const events = buildEventStream([ testEvent("runStarted"), testEvent("testCaseStarted", "MyTests.MyTests/testPass()"), testEvent("testCaseEnded", "MyTests.MyTests/testPass()"), testEvent("runEnded"), ]); - await outputParser.watch("file:///mock/named/pipe", testRunState, events); + const results = await parseResults(outputParser, events, testRunState); - assert.deepEqual(testRunState.tests, [ + assert.deepEqual(results, [ { name: "MyTests.MyTests/testPass()", status: TestStatus.passed, @@ -98,15 +106,15 @@ suite("SwiftTestingOutputParser Suite", () => { test("Skipped test", async () => { const testRunState = new TestRunState(["MyTests.MyTests/testSkip()"], true); - const events = new TestEventStream([ + const events = buildEventStream([ testEvent("runStarted"), testEvent("testSkipped", "MyTests.MyTests/testSkip()"), testEvent("runEnded"), ]); - await outputParser.watch("file:///mock/named/pipe", testRunState, events); + const results = await parseResults(outputParser, events, testRunState); - assert.deepEqual(testRunState.tests, [ + assert.deepEqual(results, [ { name: "MyTests.MyTests/testSkip()", status: TestStatus.skipped, @@ -122,7 +130,7 @@ suite("SwiftTestingOutputParser Suite", () => { line: 1, column: 2, }; - const events = new TestEventStream([ + const events = buildEventStream([ testEvent("runStarted"), testEvent("testCaseStarted", "MyTests.MyTests/testFail()"), testEvent("issueRecorded", "MyTests.MyTests/testFail()", messages, issueLocation), @@ -130,12 +138,12 @@ suite("SwiftTestingOutputParser Suite", () => { testEvent("runEnded"), ]); - await outputParser.watch("file:///mock/named/pipe", testRunState, events); + const results = await parseResults(outputParser, events, testRunState); const renderedMessages = messages.map(message => MessageRenderer.render(message)); const fullFailureMessage = renderedMessages.join("\n"); - assert.deepEqual(testRunState.tests, [ + assert.deepEqual(results, [ { name: "MyTests.MyTests/testFail()", status: TestStatus.failed, @@ -175,7 +183,7 @@ suite("SwiftTestingOutputParser Suite", () => { test("Parameterized test", async () => { const testRunState = new TestRunState(["MyTests.MyTests/testParameterized()"], true); - const events = new TestEventStream([ + const events = buildEventStream([ { kind: "test", payload: { @@ -244,9 +252,9 @@ suite("SwiftTestingOutputParser Suite", () => { }); } ); - await outputParser.watch("file:///mock/named/pipe", testRunState, events); + const results = await parseResults(outputParser, events, testRunState); - assert.deepEqual(testRunState.tests, [ + assert.deepEqual(results, [ { name: "MyTests.MyTests/testParameterized()", status: TestStatus.passed, @@ -268,7 +276,73 @@ suite("SwiftTestingOutputParser Suite", () => { ]); }); - test("Output is captured", async () => { + suite("Output capture", () => { + test("Output is captured", async () => { + const testRunState = new TestRunState(["MyTests.MyTests/testPass()"], true); + const events = buildEventStream([ + "its preamble and should be ignored", + testEvent("runStarted"), + testEvent("testCaseStarted", "MyTests.MyTests/testPass()"), + "the test output", + testEvent("testCaseEnded", "MyTests.MyTests/testPass()"), + testEvent("runEnded"), + "its over", + ]); + + const results = await parseResults(outputParser, events, testRunState, [ + "the test output", + "its over", + ]); + + assert.deepEqual(outputParser.logs, [events]); + assert.deepEqual(results, [ + { + name: "MyTests.MyTests/testPass()", + status: TestStatus.passed, + timing: { timestamp: 0 }, + output: [], + }, + ]); + }); + + test("Output that resembles JSON but isn't is captured", async () => { + const testRunState = new TestRunState([], true); + const events = buildEventStream([ + testEvent("runStarted"), + '{ "kind_of_like_json_with_no_closing_brace": ""', + testEvent("runEnded"), + "its over", + ]); + + const results = await parseResults(outputParser, events, testRunState, [ + '{ "kind_of_like_json_with_no_closing_brace": ""', + "its over", + ]); + + assert.deepEqual(outputParser.logs, [events]); + assert.deepEqual(results, []); + }); + + test("Output that is JSON but isn't a test event", async () => { + const testRunState = new TestRunState([], true); + const events = buildEventStream([ + testEvent("runStarted"), + '{ "valid_json": true }', + testEvent("runEnded"), + "its over", + ]); + + const results = await parseResults(outputParser, events, testRunState, [ + '{ "valid_json": true }', + "its over", + ]); + + assert.deepEqual(outputParser.logs, [events]); + assert.deepEqual(results, []); + }); + }); + + test("Multiple test cases", async () => { const testRunState = new TestRunState( ["MyTests.MyTests/testOutput()", "MyTests.MyTests/testOutput2()"], true @@ -278,7 +352,7 @@ suite("SwiftTestingOutputParser Suite", () => { const makeEvent = (kind: ExtractPayload["kind"], testId?: string) => testEvent(kind, testId, [{ text: kind, symbol }]); - const events = new TestEventStream([ + const events = buildEventStream([ makeEvent("runStarted"), makeEvent("testCaseStarted", "MyTests.MyTests/testOutput()"), makeEvent("testCaseEnded", "MyTests.MyTests/testOutput()"), @@ -287,9 +361,9 @@ suite("SwiftTestingOutputParser Suite", () => { makeEvent("runEnded"), ]); - await outputParser.watch("file:///mock/named/pipe", testRunState, events); + const results = await parseResults(outputParser, events, testRunState); - assert.deepEqual(testRunState.tests, [ + assert.deepEqual(results, [ { name: "MyTests.MyTests/testOutput()", output: [ diff --git a/test/suite/testexplorer/TestExplorerIntegration.test.ts b/test/suite/testexplorer/TestExplorerIntegration.test.ts index 79052e780..cf024bc61 100644 --- a/test/suite/testexplorer/TestExplorerIntegration.test.ts +++ b/test/suite/testexplorer/TestExplorerIntegration.test.ts @@ -389,7 +389,7 @@ suite("Test Explorer Suite", function () { }); assert.strictEqual( - testRun.runState.output.includes("A print statement in a test.\r\r\n"), + testRun.runState.output.includes("A print statement in a test.\r\n"), true ); }); diff --git a/test/suite/testexplorer/XCTestOutputParser.test.ts b/test/suite/testexplorer/XCTestOutputParser.test.ts index 1811989e5..2b676f672 100644 --- a/test/suite/testexplorer/XCTestOutputParser.test.ts +++ b/test/suite/testexplorer/XCTestOutputParser.test.ts @@ -13,6 +13,7 @@ //===----------------------------------------------------------------------===// import * as assert from "assert"; +import { beforeEach } from "mocha"; import { darwinTestRegex, nonDarwinTestRegex, @@ -29,7 +30,10 @@ suite("XCTestOutputParser Suite", () => { .map(line => `${line}\r\n`); suite("Darwin", () => { - const outputParser = new XCTestOutputParser(darwinTestRegex); + let outputParser: XCTestOutputParser; + beforeEach(() => { + outputParser = new XCTestOutputParser(darwinTestRegex); + }); test("Passed Test", () => { const testRunState = new TestRunState(["MyTests.MyTests/testPass"], true); @@ -48,6 +52,15 @@ Test Case '-[MyTests.MyTests testPass]' passed (0.001 seconds). ]); }); + test("Captures logs", () => { + const testRunState = new TestRunState(["MyTests.MyTests/testPass"], true); + const input = `Test Case '-[MyTests.MyTests testPass]' started. +Test Case '-[MyTests.MyTests testPass]' passed (0.001 seconds).`; + outputParser.parseResult(input, testRunState); + + assert.deepEqual(outputParser.logs, [input]); + }); + test("Multiple Passed Tests", () => { const testRunState = new TestRunState( ["MyTests.MyTests/testPass", "MyTests.MyTests/testPass2"],