Reduce logging verbosity during CMake configure and build failures; update logging levels for output and error messages in CMakeOutputConsumer.

Author: Hannia Valera

CHANGELOG.md

@@ -17,6 +17,7 @@ Improvements:
 - Allow preset modification commands to target CMakeUserPresets.json. The target file is determined by the focused editor, or by prompting the user when both files exist. [#4564](https://github.com/microsoft/vscode-cmake-tools/issues/4564)
 
 Bug Fixes:
+- Reduce overly verbose logging when CMake configure or build fails. The Output panel no longer floods with duplicated output, and the channel is only revealed on error rather than unconditionally. [#4749](https://github.com/microsoft/vscode-cmake-tools/issues/4749)
 - Fix wrong path created for artifact when parsing code model using CMake File API. [#3015](https://github.com/microsoft/vscode-cmake-tools/issues/3015)
 - Fix garbled characters (Mojibake) in the Output panel when MSVC outputs UTF-8 (e.g., with `/utf-8`) on non-UTF-8 Windows systems. When `cmake.outputLogEncoding` is `auto`, the build output is now validated as UTF-8 before falling back to the system code page. [#4520](https://github.com/microsoft/vscode-cmake-tools/issues/4520)
 - Fix CMakePresets.json discovery failing in multi-folder workspaces when the presets file is in a subdirectory specified by `cmake.sourceDirectory`. [#4727](https://github.com/microsoft/vscode-cmake-tools/issues/4727)

src/cmakeProject.ts

@@ -1905,7 +1905,6 @@ export class CMakeProject {
             log.debug(localize('no.preset.abort', 'No preset selected. Abort configure'));
             return { exitCode: -1, resultType: ConfigureResultType.Other };
         }
-        log.showChannel();
         const consumer = new CMakeOutputConsumer(this.sourceDir, cmakeLogger);
         const result = await cb(consumer);
         result.stdout = consumer.stdout;
@@ -2135,7 +2134,6 @@ export class CMakeProject {
                         });
                         const combinedToken = util.createCombinedCancellationToken(cancel, cancellationToken);
                         combinedToken.onCancellationRequested(() => rollbar.invokeAsync(localize('stop.on.cancellation', 'Stop on cancellation'), () => this.stop()));
-                        log.showChannel();
                         buildLogger.info(localize('starting.build', 'Starting build'));
                         await setContextAndStore(isBuildingKey, true);
                         const rc = await drv!.build(newTargets, consumer, isBuildCommand);

src/diagnostics/cmake.ts

@@ -51,7 +51,7 @@ export class CMakeOutputConsumer extends CommandConsumer {
      */
     output(line: string) {
         if (this.logger) {
-            this.logger.info(line);
+            this.logger.trace(line);
         }
         super.output(line);
         this._parseDiags(line);
@@ -88,7 +88,7 @@ export class CMakeOutputConsumer extends CommandConsumer {
     error(line: string) {
         // First, just log the line
         if (this.logger) {
-            this.logger.error(line);
+            this.logger.warning(line);
         }
         super.error(line);
         this._parseDiags(line);

src/drivers/cmakeFileApiDriver.ts

@@ -306,8 +306,6 @@ export class CMakeFileApiDriver extends CMakeDriver {
 
             const result = await child.result;
             this.configureProcess = null;
-            log.trace(result.stderr);
-            log.trace(result.stdout);
             if (result.retc === 0) {
                 if (!configurePreset || (configurePreset && defaultConfigurePresetName && configurePreset.name === defaultConfigurePresetName)) {
                     this._needsReconfigure = false;

src/drivers/cmakeLegacyDriver.ts

@@ -126,8 +126,6 @@ export class CMakeLegacyDriver extends CMakeDriver {
             this.configureProcess = child;
             const result = await child.result;
             this.configureProcess = null;
-            log.trace(result.stderr);
-            log.trace(result.stdout);
             if (result.retc === 0 && (!configurePreset || (configurePreset && defaultConfigurePresetName && configurePreset.name === defaultConfigurePresetName))) {
                 this._needsReconfigure = false;
             }

test/unit-tests/diagnostics.test.ts

@@ -16,6 +16,30 @@ import { CMakeOutputConsumer } from '@cmt/diagnostics/cmake';
 import { populateCollection } from '@cmt/diagnostics/util';
 import collections from '@cmt/diagnostics/collections';
 import { getTestResourceFilePath } from '@test/util';
+import { Logger } from '@cmt/logging';
+
+/** A spy logger that records which log methods were called and at what level. */
+class SpyLogger extends Logger {
+    readonly calls: { level: string; args: string[] }[] = [];
+    constructor() {
+        super('spy');
+    }
+    override trace(...args: any[]) {
+        this.calls.push({ level: 'trace', args: args.map(String) });
+    }
+    override debug(...args: any[]) {
+        this.calls.push({ level: 'debug', args: args.map(String) });
+    }
+    override info(...args: any[]) {
+        this.calls.push({ level: 'info', args: args.map(String) });
+    }
+    override warning(...args: any[]) {
+        this.calls.push({ level: 'warning', args: args.map(String) });
+    }
+    override error(...args: any[]) {
+        this.calls.push({ level: 'error', args: args.map(String) });
+    }
+}
 
 function feedLines(consumer: OutputConsumer, output: string[], error: string[]) {
     for (const line of output) {
@@ -1252,4 +1276,48 @@ suite('Diagnostics', () => {
         expect(collections.build.has(testUri)).to.be.false;
         expect(collections.presets.has(testUri)).to.be.false;
     });
+
+    test('CMakeOutputConsumer logs stdout lines at trace level, not info', () => {
+        const spy = new SpyLogger();
+        const consumerWithLogger = new CMakeOutputConsumer('dummyPath', spy);
+        consumerWithLogger.output('-- Configuring done');
+        consumerWithLogger.output('-- Generating done');
+
+        const traceCalls = spy.calls.filter(c => c.level === 'trace');
+        const infoCalls = spy.calls.filter(c => c.level === 'info');
+        expect(traceCalls.length).to.eq(2);
+        expect(infoCalls.length).to.eq(0);
+    });
+
+    test('CMakeOutputConsumer logs stderr lines at warning level, not error', () => {
+        const spy = new SpyLogger();
+        const consumerWithLogger = new CMakeOutputConsumer('dummyPath', spy);
+        consumerWithLogger.error('CMake Error at CMakeLists.txt:1 (message):');
+        consumerWithLogger.error('  Something went wrong');
+
+        const warningCalls = spy.calls.filter(c => c.level === 'warning');
+        const errorCalls = spy.calls.filter(c => c.level === 'error');
+        expect(warningCalls.length).to.eq(2);
+        expect(errorCalls.length).to.eq(0);
+    });
+
+    test('CMakeOutputConsumer still parses diagnostics after log level change', () => {
+        const spy = new SpyLogger();
+        const consumerWithLogger = new CMakeOutputConsumer('dummyPath', spy);
+        const error_output = [
+            'CMake Warning at CMakeLists.txt:14 (message):',
+            '  I am a warning!',
+            '',
+            ''
+        ];
+        for (const line of error_output) {
+            consumerWithLogger.error(line);
+        }
+        // Diagnostics should still be parsed correctly regardless of log level
+        expect(consumerWithLogger.diagnostics.length).to.eq(1);
+        const diag = consumerWithLogger.diagnostics[0];
+        expect(diag.filepath).to.eq('dummyPath/CMakeLists.txt');
+        expect(diag.diag.severity).to.eq(vscode.DiagnosticSeverity.Warning);
+        expect(diag.diag.message).to.match(/I am a warning!$/);
+    });
 });