feat: route real test program output to Test Results (#1887)

* feat: route real test program output to Test Results

The debuggee's stdout/stderr are delivered by java-debug as standard DAP
`output` events, which by default only surface in the Debug Console. This
splits program output (Debug Console) from test results (Test Results view)
across two separate surfaces, and the runner previously echoed the raw
JUnit/TestNG control protocol frames to Test Results as noise.

- Attach a DebugAdapterTracker to the test's own debug session and forward
  its DAP `output` events into the Test Results view (BaseRunner).
- Stop echoing the socket control protocol to Test Results: JUnit no longer
  appends every raw line, and TestNG no longer echoes its JSON frames.
- Attribute forwarded output to the running test when exactly one test is
  executing; fall back to run-level output when idle or when several tests
  run in parallel (attribution would only be a guess).

* fix: route debug output at test run level

Correlate debug sessions with a unique launch marker, mirror non-telemetry DAP output at run level, and preserve structured TestNG runner errors while suppressing control protocol noise.

Author: wenytang-ms

src/runners/baseRunner/BaseRunner.ts

@@ -2,16 +2,19 @@
 // Licensed under the MIT license.
 
 import * as iconv from 'iconv-lite';
+import { randomUUID } from 'crypto';
 import { AddressInfo, createServer, Server, Socket } from 'net';
 import * as os from 'os';
-import { CancellationToken, debug, DebugConfiguration, DebugSession, Disposable } from 'vscode';
+import { CancellationToken, debug, DebugAdapterTracker, DebugConfiguration, DebugSession, Disposable, ProviderResult } from 'vscode';
 import { sendError } from 'vscode-extension-telemetry-wrapper';
 import { Configurations } from '../../constants';
 import { IProgressReporter } from '../../debugger.api';
 import { ITestRunnerInternal } from '../ITestRunner';
 import { RunnerResultAnalyzer } from './RunnerResultAnalyzer';
 import { IExecutionConfig, IRunTestContext } from '../../java-test-runner.api';
 
+const JAVA_TEST_RUN_ID: string = '__javaTestRunId';
+
 export abstract class BaseRunner implements ITestRunnerInternal {
     protected server: Server;
     protected socket: Socket;
@@ -56,9 +59,26 @@ export abstract class BaseRunner implements ITestRunnerInternal {
         // So we force to use internal console here to make sure the session is still under debugger's control.
         launchConfiguration.console = 'internalConsole';
 
+        const testRunId: string = randomUUID();
+        launchConfiguration[JAVA_TEST_RUN_ID] = testRunId;
+        const isTestSession: (session: DebugSession) => boolean = (session: DebugSession): boolean =>
+            session.configuration[JAVA_TEST_RUN_ID] === testRunId;
+
+        // Mirror the test session's user-visible Debug Console output in Test Results.
+        this.disposables.push(debug.registerDebugAdapterTrackerFactory('java', {
+            createDebugAdapterTracker: (session: DebugSession): ProviderResult<DebugAdapterTracker> => {
+                if (!isTestSession(session)) {
+                    return undefined;
+                }
+                return {
+                    onDidSendMessage: (message: any): void => this.handleDebugAdapterMessage(message),
+                };
+            },
+        }));
+
         let debugSession: DebugSession | undefined;
         this.disposables.push(debug.onDidStartDebugSession((session: DebugSession) => {
-            if (session.name === launchConfiguration.name) {
+            if (!debugSession && isTestSession(session)) {
                 debugSession = session;
             }
         }));
@@ -80,7 +100,7 @@ export abstract class BaseRunner implements ITestRunnerInternal {
             return await new Promise<void>((resolve: () => void): void => {
                 this.disposables.push(
                     debug.onDidTerminateDebugSession((session: DebugSession): void => {
-                        if (launchConfiguration.name === session.name) {
+                        if (session.id === debugSession?.id) {
                             debugSession = undefined;
                             this.tearDown();
                             if (data.length > 0) {
@@ -97,6 +117,19 @@ export abstract class BaseRunner implements ITestRunnerInternal {
         }));
     }
 
+    protected handleDebugAdapterMessage(message: any): void {
+        if (message?.type !== 'event' || message.event !== 'output' || message.body?.category === 'telemetry') {
+            return;
+        }
+
+        const output: unknown = message.body?.output;
+        if (typeof output !== 'string' || output.length === 0) {
+            return;
+        }
+
+        this.testContext.testRun.appendOutput(output.replace(/\r?\n/g, '\r\n'));
+    }
+
     public async tearDown(): Promise<void> {
         try {
             if (this.socket) {

src/runners/junitRunner/JUnitRunnerResultAnalyzer.ts

@@ -52,8 +52,14 @@ export class JUnitRunnerResultAnalyzer extends RunnerResultAnalyzer {
     public analyzeData(data: string): void {
         const lines: string[] = data.split(/\r?\n/);
         for (const line of lines) {
+            // The socket stream carries only the JUnit runner's control protocol
+            // (`%`-prefixed frames plus stack-trace / expected-actual payloads).
+            // The control frames are noise, and the failure payloads are already
+            // surfaced structurally as TestMessages on the failed items, so nothing
+            // here is echoed to the Test Results output. The user-facing program
+            // output is instead forwarded from the debug session's DAP `output`
+            // events (see BaseRunner).
             this.processData(line);
-            this.testContext.testRun.appendOutput(line + '\r\n');
         }
     }
 

src/runners/testngRunner/TestNGRunnerResultAnalyzer.ts

@@ -10,6 +10,7 @@ import { IRunTestContext, TestLevel, TestResultState } from '../../java-test-run
 const TEST_START: string = 'testStarted';
 const TEST_FAIL: string = 'testFailed';
 const TEST_FINISH: string = 'testFinished';
+const TEST_ERROR: string = 'error';
 
 export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
 
@@ -47,17 +48,25 @@ export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
             try {
                 this.processData(match[1]);
             } catch (error) {
-                this.testContext.testRun.appendOutput(`[ERROR] Failed to parse output data: ${match[1]}\n`);
+                this.testContext.testRun.appendOutput(`[ERROR] Failed to parse output data: ${match[1]}\r\n`);
             }
         }
     }
 
     public processData(data: string): void {
         const outputData: ITestNGOutputData = JSON.parse(data) as ITestNGOutputData;
 
-        this.testContext.testRun.appendOutput(this.unescape(data).replace(/\r?\n/g, '\r\n'));
+        if (outputData.name === TEST_ERROR) {
+            this.processRunnerError(outputData.attributes);
+            return;
+        }
+
+        const attributes: ITestNGAttributes | undefined = outputData.attributes;
+        if (!attributes?.name) {
+            return;
+        }
 
-        const id: string = `${this.projectName}@${outputData.attributes.name}`;
+        const id: string = `${this.projectName}@${attributes.name}`;
         if (outputData.name === TEST_START) {
             this.initializeCache();
             const item: TestItem | undefined = this.getTestItem(id);
@@ -76,11 +85,11 @@ export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
             this.currentTestState = TestResultState.Failed;
             const testMessages: TestMessage[] = [];
 
-            if (outputData.attributes.trace) {
+            if (attributes.trace) {
                 const markdownTrace: MarkdownString = new MarkdownString();
                 markdownTrace.isTrusted = true;
                 markdownTrace.supportHtml = true;
-                for (const line of outputData.attributes.trace.split(/\r?\n/)) {
+                for (const line of attributes.trace.split(/\r?\n/)) {
                     this.processStackTrace(line, markdownTrace, this.currentItem, this.projectName);
                 }
 
@@ -93,17 +102,17 @@ export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
                 }
                 testMessages.push(testMessage);
             }
-            const duration: number = Number.parseInt(outputData.attributes.duration, 10);
+            const duration: number | undefined = this.parseDuration(attributes.duration);
             setTestState(this.testContext.testRun, item, this.currentTestState, testMessages, duration);
         } else if (outputData.name === TEST_FINISH) {
-            const item: TestItem | undefined = this.getTestItem(data);
+            const item: TestItem | undefined = this.getTestItem(id);
             if (!item) {
                 return;
             }
             if (this.currentTestState === TestResultState.Running) {
                 this.currentTestState = TestResultState.Passed;
             }
-            const duration: number = Number.parseInt(outputData.attributes.duration, 10);
+            const duration: number | undefined = this.parseDuration(attributes.duration);
             setTestState(this.testContext.testRun, item, this.currentTestState, undefined, duration);
             const itemData: ITestItemData | undefined = dataCache.get(item);
             if (itemData?.testLevel === TestLevel.Method) {
@@ -121,20 +130,31 @@ export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
         return this.currentItem;
     }
 
-    protected unescape(content: string): string {
-        return content.replace(/\\r/gm, '\r')
-            .replace(/\\f/gm, '\f')
-            .replace(/\\n/gm, '\n')
-            .replace(/\\t/gm, '\t')
-            .replace(/\\b/gm, '\b')
-            .replace(/\\"/gm, '"');
-    }
-
     protected initializeCache(): void {
         this.currentTestState = TestResultState.Queued;
         this.currentItem = undefined;
     }
 
+    private processRunnerError(attributes: ITestNGAttributes | undefined): void {
+        let message: string = attributes?.message || 'Failed to run TestNG tests.';
+        if (attributes?.trace) {
+            message += `\n${attributes.trace}`;
+        }
+        const testMessage: TestMessage = new TestMessage(message);
+        for (const item of this.testContext.testItems) {
+            this.testContext.testRun.errored(item, testMessage);
+        }
+    }
+
+    private parseDuration(duration: string | undefined): number | undefined {
+        if (!duration) {
+            return undefined;
+        }
+
+        const parsed: number = Number.parseInt(duration, 10);
+        return Number.isNaN(parsed) ? undefined : parsed;
+    }
+
     protected getStacktraceFilter(): string[] {
         return [
             'com.microsoft.java.test.runner.',
@@ -151,20 +171,14 @@ export class TestNGRunnerResultAnalyzer extends RunnerResultAnalyzer {
 }
 
 interface ITestNGOutputData {
-    attributes: ITestNGAttributes;
-    type: TestOutputType;
+    attributes?: ITestNGAttributes;
     name: string;
 }
 
-enum TestOutputType {
-    Info,
-    Error,
-}
-
 interface ITestNGAttributes {
-    name: string;
-    duration: string;
-    location: string;
-    message: string;
-    trace: string;
+    name?: string;
+    duration?: string;
+    location?: string;
+    message?: string;
+    trace?: string;
 }

test/suite/TestNGAnalyzer.test.ts

@@ -0,0 +1,73 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT license.
+
+'use strict';
+
+import * as assert from 'assert';
+import * as sinon from 'sinon';
+import { TestController, TestMessage, TestRunRequest, tests, workspace } from 'vscode';
+import { TestNGRunnerResultAnalyzer } from '../../src/runners/testngRunner/TestNGRunnerResultAnalyzer';
+import { IRunTestContext, TestKind } from '../../src/java-test-runner.api';
+import { generateTestItem } from './utils';
+
+// tslint:disable: only-arrow-functions
+suite('TestNG Runner Analyzer Tests', () => {
+
+    let testController: TestController;
+
+    setup(() => {
+        testController = tests.createTestController('testngTestController', 'Mock TestNG');
+    });
+
+    teardown(() => {
+        testController.dispose();
+    });
+
+    test('surfaces runner errors as structured test errors', () => {
+        const testItem = generateTestItem(testController, 'testng@example.SampleTest#test', TestKind.TestNG);
+        const testRun = testController.createTestRun(new TestRunRequest([testItem], []));
+        const erroredSpy = sinon.spy(testRun, 'errored');
+        const runnerContext: IRunTestContext = {
+            isDebug: false,
+            kind: TestKind.TestNG,
+            projectName: 'testng',
+            testItems: [testItem],
+            testRun,
+            workspaceFolder: workspace.workspaceFolders?.[0]!,
+        };
+        const analyzer = new TestNGRunnerResultAnalyzer(runnerContext);
+        const trace = 'java.lang.ClassNotFoundException: example.SampleTest';
+
+        analyzer.processData(JSON.stringify({
+            name: 'error',
+            attributes: {
+                message: 'Failed to run TestNG tests',
+                trace,
+            },
+        }));
+
+        sinon.assert.calledOnce(erroredSpy);
+        sinon.assert.calledWith(erroredSpy, testItem, sinon.match.instanceOf(TestMessage));
+        const testMessage = erroredSpy.firstCall.args[1] as TestMessage;
+        assert.strictEqual(testMessage.message, `Failed to run TestNG tests\n${trace}`);
+    });
+
+    test('ignores control messages without test attributes', () => {
+        const testItem = generateTestItem(testController, 'testng@example.SampleTest#test', TestKind.TestNG);
+        const testRun = testController.createTestRun(new TestRunRequest([testItem], []));
+        const appendOutputSpy = sinon.spy(testRun, 'appendOutput');
+        const runnerContext: IRunTestContext = {
+            isDebug: false,
+            kind: TestKind.TestNG,
+            projectName: 'testng',
+            testItems: [testItem],
+            testRun,
+            workspaceFolder: workspace.workspaceFolders?.[0]!,
+        };
+        const analyzer = new TestNGRunnerResultAnalyzer(runnerContext);
+
+        analyzer.analyzeData('@@<TestRunner-{"name":"reporterAttached"}-TestRunner>');
+
+        sinon.assert.notCalled(appendOutputSpy);
+    });
+});

test/suite/baseRunner.test.ts

@@ -4,12 +4,17 @@
 'use strict';
 
 import * as assert from 'assert';
+import * as sinon from 'sinon';
 import { AddressInfo } from 'net';
 import { BaseRunner } from '../../src/runners/baseRunner/BaseRunner';
 import { RunnerResultAnalyzer } from '../../src/runners/baseRunner/RunnerResultAnalyzer';
 import { IRunTestContext, TestKind } from '../../src/java-test-runner.api';
 
 class TestableBaseRunner extends BaseRunner {
+    public handleMessage(message: any): void {
+        this.handleDebugAdapterMessage(message);
+    }
+
     protected getAnalyzer(): RunnerResultAnalyzer {
         return {} as RunnerResultAnalyzer;
     }
@@ -63,4 +68,52 @@ suite('BaseRunner Tests', () => {
             }
         });
     });
+
+    suite('handleDebugAdapterMessage', () => {
+        test('forwards non-telemetry output at run level with CRLF newlines', () => {
+            const appendOutput = sinon.spy();
+            const runner = new TestableBaseRunner({
+                kind: TestKind.JUnit,
+                isDebug: false,
+                projectName: 'test-project',
+                testItems: [],
+                testRun: { appendOutput } as any,
+                workspaceFolder: {} as any,
+            } as IRunTestContext);
+
+            runner.handleMessage({
+                type: 'event',
+                event: 'output',
+                body: {
+                    category: 'console',
+                    output: 'first\nsecond\r\n',
+                },
+            });
+
+            sinon.assert.calledOnceWithExactly(appendOutput, 'first\r\nsecond\r\n');
+        });
+
+        test('ignores telemetry output', () => {
+            const appendOutput = sinon.spy();
+            const runner = new TestableBaseRunner({
+                kind: TestKind.JUnit,
+                isDebug: false,
+                projectName: 'test-project',
+                testItems: [],
+                testRun: { appendOutput } as any,
+                workspaceFolder: {} as any,
+            } as IRunTestContext);
+
+            runner.handleMessage({
+                type: 'event',
+                event: 'output',
+                body: {
+                    category: 'telemetry',
+                    output: 'internal event',
+                },
+            });
+
+            sinon.assert.notCalled(appendOutput);
+        });
+    });
 });