From 69b7a4a26f3873dfc1d762bfdf76cec12837fcd3 Mon Sep 17 00:00:00 2001 From: Paul LeMarquand Date: Fri, 7 Feb 2025 11:20:05 -0500 Subject: [PATCH] More debugging --- .../TestParsers/XCTestOutputParser.ts | 274 +++++++++++------- src/TestExplorer/TestRunner.ts | 5 +- .../TestExplorerIntegration.test.ts | 16 +- 3 files changed, 178 insertions(+), 117 deletions(-) diff --git a/src/TestExplorer/TestParsers/XCTestOutputParser.ts b/src/TestExplorer/TestParsers/XCTestOutputParser.ts index 52c96f561..739deead4 100644 --- a/src/TestExplorer/TestParsers/XCTestOutputParser.ts +++ b/src/TestExplorer/TestParsers/XCTestOutputParser.ts @@ -18,6 +18,8 @@ import { MarkdownString, Location } from "vscode"; // eslint-disable-next-line @typescript-eslint/no-require-imports import stripAnsi = require("strip-ansi"); +/* eslint-disable no-console */ + /** Regex for parsing XCTest output */ interface TestRegex { started: RegExp; @@ -151,117 +153,157 @@ export class XCTestOutputParser implements IXCTestOutputParser { * @param output Output from `swift test` */ public parseResult(rawOutput: string, runState: ITestRunState) { - console.log("RAW XCTEST OUTPUT:", rawOutput.split("\n").join("\n>>>> ")); - - // Windows is inserting ANSI codes into the output to do things like clear the cursor, - // which we don't care about. - const output = process.platform === "win32" ? stripAnsi(rawOutput) : rawOutput; - const output2 = output.replace(/\r\n/g, "\n"); - const lines = output2.split("\n"); - if (runState.excess) { - lines[0] = runState.excess + lines[0]; - } - // pop empty string off the end of the lines array - if (lines.length > 0 && lines[lines.length - 1] === "") { - lines.pop(); - } - // if submitted text does not end with a newline then pop that off and store in excess - // for next call of parseResult - if (output2[output2.length - 1] !== "\n") { - runState.excess = lines.pop(); - } else { - runState.excess = undefined; - } - - // Non-Darwin test output does not include the test target name. The only way to find out - // the target for a test is when it fails and returns a file name. If we find failed tests - // first and then remove them from the list we cannot set them to passed by mistake. - // We extract the file name from the error and use that to check whether the file belongs - // to the target associated with the TestItem. This does not work 100% as the error could - // occur in another target, so we revert to just searching for class and function name if - // the above method is unsuccessful. - for (const line of lines) { - // Regex "Test Case '-[ ]' started" - const startedMatch = this.regex.started.exec(line); - if (startedMatch) { - const testName = `${startedMatch[1]}/${startedMatch[2]}`; - - // Save the active TestTarget.SuiteClass. - // Note that TestTarget is only present on Darwin. - runState.activeSuite = startedMatch[1]; - this.processPendingSuiteOutput(runState, startedMatch[1]); - - const startedTestIndex = runState.getTestItemIndex(testName, undefined); - this.startTest(startedTestIndex, runState); - this.appendTestOutput(startedTestIndex, line, runState); - continue; - } - // Regex "Test Case '-[ ]' ( seconds)" - const finishedMatch = this.regex.finished.exec(line); - if (finishedMatch) { - const testName = `${finishedMatch[1]}/${finishedMatch[2]}`; - const testIndex = runState.getTestItemIndex(testName, undefined); - const state = finishedMatch[3] as TestCompletionState; - const duration = +finishedMatch[4]; - switch (state) { - case TestCompletionState.failed: - this.failTest(testIndex, { duration }, runState); - break; - case TestCompletionState.passed: - this.passTest(testIndex, { duration }, runState); - break; - case TestCompletionState.skipped: - this.skipTest(testIndex, runState); - break; - } - - this.appendTestOutput(testIndex, line, runState); - continue; - } - // Regex ":: error: . : " - const errorMatch = this.regex.error.exec(line); - if (errorMatch) { - const testName = `${errorMatch[3]}/${errorMatch[4]}`; - const failedTestIndex = runState.getTestItemIndex(testName, errorMatch[1]); - this.startErrorMessage( - failedTestIndex, - errorMatch[5], - errorMatch[1], - errorMatch[2], - runState - ); - this.appendTestOutput(failedTestIndex, line, runState); - continue; - } - // Regex ":: . : Test skipped" - const skippedMatch = this.regex.skipped.exec(line); - if (skippedMatch) { - const testName = `${skippedMatch[3]}/${skippedMatch[4]}`; - const skippedTestIndex = runState.getTestItemIndex(testName, skippedMatch[1]); - this.skipTest(skippedTestIndex, runState); - this.appendTestOutput(skippedTestIndex, line, runState); - continue; + try { + console.log( + ">>>>>>>>>>>>>>>> RAW XCTEST OUTPUT >>>>>>>>>>>>>>>>>>> :\n" + + rawOutput.split("\n").join("\n") + ); + console.log(">>>>>>>>>>>>>>>> RAW XCTEST OUTPUT COMPLETE >>>>>>>>>>>>>>>>>>>"); + const annotated = rawOutput + .replaceAll("\r\n", "🐀❌\r\n") + .replaceAll("\n\r", "❌🐀\n\r") + .replaceAll("\n", "❌\n") + .replaceAll("\r", "🐀\r"); + console.log( + ">>>>>>>>>>>>>>>> ANNOTATED XCTEST OUTPUT >>>>>>>>>>>>>>>>>>> :\n" + annotated + ); + console.log(">>>>>>>>>>>>>>>> ANNOTATED XCTEST OUTPUT COMPLETE >>>>>>>>>>>>>>>>>>>"); + + // Windows is inserting ANSI codes into the output to do things like clear the cursor, + // which we don't care about. + const output = process.platform === "win32" ? stripAnsi(rawOutput) : rawOutput; + const lines = output.replace(/\r\n/g, "\n").split("\n"); + console.log(">>> Lines to Process:", lines); + console.log(">>> Run State Excess |" + runState.excess + "|"); + if (runState.excess) { + console.log(">>> !Had Excess from previous output |" + runState.excess + "|"); + lines[0] = runState.excess + lines[0]; + console.log(">>> !New line[0] is now |" + lines[0] + "|"); } - // Regex "Test Suite '-[ ]' started" - const startedSuiteMatch = this.regex.startedSuite.exec(line); - if (startedSuiteMatch) { - this.startTestSuite(startedSuiteMatch[1], line, runState); - continue; + // pop empty string off the end of the lines array + if (lines.length > 0 && lines[lines.length - 1] === "") { + console.log(">>> Trimming last line"); + lines.pop(); } - // Regex "Test Suite '-[ ]' passed" - const passedSuiteMatch = this.regex.passedSuite.exec(line); - if (passedSuiteMatch) { - this.completeSuite(runState, line, this.passTestSuite); - continue; + // if submitted text does not end with a newline then pop that off and store in excess + // for next call of parseResult + if (lines.length > 0 && !lines[lines.length - 1].endsWith("\n")) { + runState.excess = lines.pop(); + console.log(">>> Saving Excess |" + runState.excess + "|"); + } else { + console.log(">>> Unsetting Excess"); + runState.excess = undefined; } - // Regex "Test Suite '-[ ]' failed" - const failedSuiteMatch = this.regex.failedSuite.exec(line); - if (failedSuiteMatch) { - this.completeSuite(runState, line, this.failTestSuite); - continue; + + // Non-Darwin test output does not include the test target name. The only way to find out + // the target for a test is when it fails and returns a file name. If we find failed tests + // first and then remove them from the list we cannot set them to passed by mistake. + // We extract the file name from the error and use that to check whether the file belongs + // to the target associated with the TestItem. This does not work 100% as the error could + // occur in another target, so we revert to just searching for class and function name if + // the above method is unsuccessful. + for (const line of lines) { + console.log(">>> Process Line: |" + line + "|"); + // Regex "Test Case '-[ ]' started" + const startedMatch = this.regex.started.exec(line); + if (startedMatch) { + const testName = `${startedMatch[1]}/${startedMatch[2]}`; + + // Save the active TestTarget.SuiteClass. + // Note that TestTarget is only present on Darwin. + runState.activeSuite = startedMatch[1]; + this.processPendingSuiteOutput(runState, startedMatch[1]); + + const startedTestIndex = runState.getTestItemIndex(testName, undefined); + this.startTest(startedTestIndex, runState); + this.appendTestOutput(startedTestIndex, line, runState); + continue; + } + // Regex "Test Case '-[ ]' ( seconds)" + const finishedMatch = this.regex.finished.exec(line); + if (finishedMatch) { + const testName = `${finishedMatch[1]}/${finishedMatch[2]}`; + const testIndex = runState.getTestItemIndex(testName, undefined); + const state = finishedMatch[3] as TestCompletionState; + const duration = +finishedMatch[4]; + console.log( + "!!! >>>>> !!!! FINISHED MATCH ON LINE:", + line, + "...STATE IS", + state, + "... TEST INDEX IS", + testIndex, + "... FAILED TEST IS", + runState.failedTest + ); + switch (state) { + case TestCompletionState.failed: + this.failTest(testIndex, { duration }, runState); + break; + case TestCompletionState.passed: + this.passTest(testIndex, { duration }, runState); + break; + case TestCompletionState.skipped: + this.skipTest(testIndex, runState); + break; + } + + this.appendTestOutput(testIndex, line, runState); + continue; + } + // Regex ":: error: . : " + const errorMatch = this.regex.error.exec(line); + if (errorMatch) { + const testName = `${errorMatch[3]}/${errorMatch[4]}`; + const failedTestIndex = runState.getTestItemIndex(testName, errorMatch[1]); + console.log( + ">>> ERROR MATCH ON LINE:", + line, + "...FAILED TEST INDEX IS", + failedTestIndex + ); + this.startErrorMessage( + failedTestIndex, + errorMatch[5], + errorMatch[1], + errorMatch[2], + runState + ); + this.appendTestOutput(failedTestIndex, line, runState); + continue; + } + // Regex ":: . : Test skipped" + const skippedMatch = this.regex.skipped.exec(line); + if (skippedMatch) { + const testName = `${skippedMatch[3]}/${skippedMatch[4]}`; + const skippedTestIndex = runState.getTestItemIndex(testName, skippedMatch[1]); + this.skipTest(skippedTestIndex, runState); + this.appendTestOutput(skippedTestIndex, line, runState); + continue; + } + // Regex "Test Suite '-[ ]' started" + const startedSuiteMatch = this.regex.startedSuite.exec(line); + if (startedSuiteMatch) { + this.startTestSuite(startedSuiteMatch[1], line, runState); + continue; + } + // Regex "Test Suite '-[ ]' passed" + const passedSuiteMatch = this.regex.passedSuite.exec(line); + if (passedSuiteMatch) { + this.completeSuite(runState, line, this.passTestSuite); + continue; + } + // Regex "Test Suite '-[ ]' failed" + const failedSuiteMatch = this.regex.failedSuite.exec(line); + if (failedSuiteMatch) { + this.completeSuite(runState, line, this.failTestSuite); + continue; + } + // unrecognised output could be the continuation of a previous error message + this.continueErrorMessage(line, runState); } - // unrecognised output could be the continuation of a previous error message - this.continueErrorMessage(line, runState); + } catch (e) { + console.error("!!! >>>>> !!! ERROR PARSING OUTPUT", e); } } @@ -342,6 +384,7 @@ export class XCTestOutputParser implements IXCTestOutputParser { private startTest(testIndex: number, runState: ITestRunState) { runState.started(testIndex); // clear error state + console.log(">>>>> startTest resetting failed test", testIndex); runState.failedTest = undefined; } @@ -352,6 +395,7 @@ export class XCTestOutputParser implements IXCTestOutputParser { runState: ITestRunState ) { runState.completed(testIndex, timing); + console.log(">>>>> passTest resetting failed test", testIndex); runState.failedTest = undefined; } @@ -363,6 +407,14 @@ export class XCTestOutputParser implements IXCTestOutputParser { lineNumber: string, runState: ITestRunState ) { + console.log( + "!!! >>>>> !! START ERROR MESSAGE", + testIndex, + message, + file, + lineNumber, + !!runState.failedTest + ); // If we were already capturing an error record it and start a new one if (runState.failedTest) { const location = sourceLocationToVSCodeLocation( @@ -379,6 +431,7 @@ export class XCTestOutputParser implements IXCTestOutputParser { lineNumber: parseInt(lineNumber), complete: false, }; + console.log(">>>>>>> SET FAILED TEST TO", runState.failedTest); } /** continue capturing error message */ @@ -407,16 +460,21 @@ export class XCTestOutputParser implements IXCTestOutputParser { const diff = this.extractDiff(message); runState.recordIssue(testIndex, message, false, location, diff); } else { - console.log(">>>>>>>>>> MARKED FAILED TEST WITH NO ATTACHED FAILED TEST >>>>>>>>>>>>>"); + console.log( + `>>>>>>>>>> MARKED FAILED TEST WITH NO ATTACHED FAILED TEST ${testIndex} >>>>>>>>>>>>>` + ); runState.recordIssue(testIndex, "Failed", false); } runState.completed(testIndex, timing); + + console.log(">>>>> failTest resetting failed test", testIndex); runState.failedTest = undefined; } /** Flag we have skipped a test */ private skipTest(testIndex: number, runState: ITestRunState) { runState.skipped(testIndex); + console.log(">>>>> skipTest resetting failed test", testIndex); runState.failedTest = undefined; } diff --git a/src/TestExplorer/TestRunner.ts b/src/TestExplorer/TestRunner.ts index 45df6717a..813701f4c 100644 --- a/src/TestExplorer/TestRunner.ts +++ b/src/TestExplorer/TestRunner.ts @@ -1168,7 +1168,10 @@ class NonDarwinTestItemFinder implements TestItemFinder { * Store state of current test run output parse */ export class TestRunnerTestRunState implements ITestRunState { - constructor(private testRun: TestRunProxy) {} + constructor(private testRun: TestRunProxy) { + // eslint-disable-next-line no-console + console.log(">>>>>> CREATED TestRunnerTestRunState"); + } public currentTestItem?: vscode.TestItem; public lastTestItem?: vscode.TestItem; diff --git a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts index 374044db0..f2c3ab724 100644 --- a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts +++ b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts @@ -560,7 +560,7 @@ suite("Test Explorer Suite", function () { }); }); - test(`Runs failing test (${runProfile})`, async function () { + test(`swift-testing Runs failing test (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -582,7 +582,7 @@ suite("Test Explorer Suite", function () { }); }); - test(`Runs Suite (${runProfile})`, async function () { + test(`swift-testing Runs Suite (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -607,7 +607,7 @@ suite("Test Explorer Suite", function () { }); }); - test(`Runs parameterized test (${runProfile})`, async function () { + test(`swift-testing Runs parameterized test (${runProfile})`, async function () { const testId = "PackageTests.parameterizedTest(_:)"; const testRun = await runTest(testExplorer, runProfile, testId); @@ -657,7 +657,7 @@ suite("Test Explorer Suite", function () { assert.deepEqual(unrunnableChildren, [true, true, true]); }); - test(`Runs Suite (${runProfile})`, async function () { + test(`swift-testing Runs Suite (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -682,7 +682,7 @@ suite("Test Explorer Suite", function () { }); }); - test(`Runs All (${runProfile})`, async function () { + test(`swift-testing Runs All (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -721,7 +721,7 @@ suite("Test Explorer Suite", function () { }); suite(`XCTests (${runProfile})`, () => { - test("Runs passing test", async function () { + test(`XCTest Runs passing test (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -736,7 +736,7 @@ suite("Test Explorer Suite", function () { }); }); - test("Runs failing test", async function () { + test(`XCTest Runs failing test (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile, @@ -757,7 +757,7 @@ suite("Test Explorer Suite", function () { }); }); - test("Runs Suite", async function () { + test(`XCTest Runs Suite (${runProfile})`, async function () { const testRun = await runTest( testExplorer, runProfile,