feat(sam): improve rendering of SAM output #4285

Problem:
`vscode.LogOutputChannel` is now available via `createOutputChannel(...,
{ log: true })`, for improved highlighting and presentation of log-like
output in VSCode, but AWS Toolkit still uses the old
`vscode.OutputChannel` interface.

Solution:
- Use `vscode.LogOutputChannel` methods when possible.
- samCliLocalInvoke.ts: log `onStderr` to "info" log-level instead of "error".

Author: justinmk3

.changes/next-release/Feature-a4a67f74-2ea2-4e18-9864-c8904e0128e6.json

@@ -0,0 +1,4 @@
+{
+	"type": "Feature",
+	"description": "SAM lambda debugging: SAM output and other logs are now presented with VSCode's log highlighting"
+}

src/codewhisperer/models/constants.ts

@@ -266,7 +266,7 @@ export const connectionExpired = `Connection expired. To continue using Amazon Q
 export const DoNotShowAgain = `Don\'t Show Again`
 
 export const codeScanLogsOutputChannelId =
-    'workbench.action.output.show.extension-output-amazonwebservices.aws-toolkit-vscode-#2-CodeWhisperer Security Scan Logs'
+    'workbench.action.output.show.extension-output-amazonwebservices.aws-toolkit-vscode-#1-CodeWhisperer Security Scan Logs'
 
 export const stopScanMessage =
     'Stop security scan? This scan will be counted as one complete scan towards your monthly security scan limits.'

src/extensionWeb.ts

@@ -27,7 +27,7 @@ export async function activate(context: vscode.ExtensionContext) {
         setupGlobalStubs()
 
         // Setup the logger
-        const toolkitOutputChannel = vscode.window.createOutputChannel('AWS Toolkit')
+        const toolkitOutputChannel = vscode.window.createOutputChannel('AWS Toolkit', { log: true })
         await activateLogger(context, toolkitOutputChannel)
 
         await initializeComputeRegion()

src/shared/logger/activation.ts

@@ -27,7 +27,7 @@ const defaultLogLevel: LogLevel = 'info'
  */
 export async function activate(
     extensionContext: vscode.ExtensionContext,
-    outputChannel: vscode.OutputChannel
+    outputChannel: vscode.LogOutputChannel
 ): Promise<void> {
     const chan = logOutputChannel
     const settings = Settings.instance.getSection('aws')

src/shared/logger/outputChannel.ts

@@ -5,7 +5,7 @@
 
 import * as vscode from 'vscode'
 
-export const logOutputChannel: vscode.OutputChannel = vscode.window.createOutputChannel('AWS Toolkit Logs')
+export const logOutputChannel = vscode.window.createOutputChannel('AWS Toolkit Logs', { log: true })
 
 /**
  * Shows the log output channel.

src/shared/logger/outputChannelTransport.ts

@@ -7,6 +7,7 @@ import * as vscode from 'vscode'
 import Transport from 'winston-transport'
 import globals from '../extensionGlobals'
 import { removeAnsi } from '../utilities/textUtilities'
+import { LogLevel } from './logger'
 
 export const MESSAGE = Symbol.for('message') // eslint-disable-line @typescript-eslint/naming-convention
 
@@ -19,6 +20,8 @@ interface LogEntry {
 
 export class OutputChannelTransport extends Transport {
     private readonly outputChannel: Pick<vscode.OutputChannel, 'append' | 'appendLine'>
+    // True if `outputChannel` is a `vscode.LogOutputChannel`.
+    private readonly isLogChan: boolean
     private readonly stripAnsi: boolean
 
     public constructor(
@@ -32,16 +35,46 @@ export class OutputChannelTransport extends Transport {
 
         this.outputChannel = options.outputChannel
         this.stripAnsi = options.stripAnsi ?? false
+
+        const c = this.outputChannel
+        this.isLogChan = !!((c as any).info && (c as any).debug && (c as any).warn && (c as any).error)
+        // Else: we got `vscode.debug.activeDebugConsole` which does not yet implement `vscode.LogOutputChannel`.
     }
 
     public override log(info: LogEntry, next: () => void): void {
         globals.clock.setImmediate(() => {
-            const msg = this.stripAnsi ? removeAnsi(info[MESSAGE]) : info[MESSAGE]
+            if (this.isLogChan) {
+                const c = this.outputChannel as vscode.LogOutputChannel
+                // Example input:
+                //      message: 'Preparing to debug locally: Lambda "index.handler"'
+                //      raw: true
+                //      Symbol(level): 'info'
+                //      Symbol(message): '2024-01-16 08:54:30 [INFO]: Preparing to debug locally: Lambda "index.handler"'
+                //      Symbol(splat): (1) [{…}]
+                //      timestamp: '2024-01-16 08:54:30'
+                // We want the "raw" message without the frontmatter, because
+                // `vscode.LogOutputChannel` presents its own timestamp + loglevel.
+                const raw = this.stripAnsi ? removeAnsi(info.message) : info.message
+                // Avoid extra line breaks.
+                const msg = raw.trim()
 
-            if (info.raw) {
-                this.outputChannel.append(msg)
+                const loglevel = info.level as LogLevel
+                if (loglevel === 'error') {
+                    c.error(msg)
+                } else if (loglevel === 'warn') {
+                    c.warn(msg)
+                } else if (loglevel === 'debug' || loglevel === 'verbose') {
+                    c.debug(msg)
+                } else {
+                    c.info(msg)
+                }
             } else {
-                this.outputChannel.appendLine(msg)
+                const msg = this.stripAnsi ? removeAnsi(info[MESSAGE]) : info[MESSAGE]
+                if (info.raw) {
+                    this.outputChannel.append(msg)
+                } else {
+                    this.outputChannel.appendLine(msg)
+                }
             }
 
             this.emit('logged', info)

src/shared/sam/cli/samCliLocalInvoke.ts

@@ -80,7 +80,7 @@ export class DefaultSamLocalInvokeCommand implements SamLocalInvokeCommand {
                         this.logger.verbose('SAM: pid %d: stdout: %s', childProcess.pid(), removeAnsi(text))
                     },
                     onStderr: (text: string): void => {
-                        getLogger('debugConsole').error(text, { raw: true })
+                        getLogger('debugConsole').info(text, { raw: true })
                         // If we have a timeout (as we do on debug) refresh the timeout as we receive text
                         params.timeout?.refresh()
                         this.logger.verbose('SAM: pid %d: stderr: %s', childProcess.pid(), removeAnsi(text))

src/test/testUtil.ts

@@ -341,9 +341,11 @@ export async function closeAllEditors(): Promise<void> {
     // Note: `workbench.action.closeAllEditors` is unreliable.
     const closeAllCmd = 'openEditors.closeAll'
 
-    // Output channels are named with prefix "extension-output". https://github.com/microsoft/vscode/issues/148993#issuecomment-1167654358
+    // Ignore these "editors" not closed by "openEditors.closeAll":
+    //  - `vscode.OutputChannel` name prefixed with "extension-output". https://github.com/microsoft/vscode/issues/148993#issuecomment-1167654358
+    //  - `vscode.LogOutputChannel` name (created with `vscode.window.createOutputChannel(…,{log:true})`
     // Maybe we can close these with a command?
-    const ignorePatterns = [/extension-output/, /tasks/]
+    const ignorePatterns = [/extension-output/, /tasks/, /amazonwebservices\.aws-toolkit-vscode\./]
     const editors: vscode.TextEditor[] = []
 
     const noVisibleEditor: boolean | undefined = await waitUntil(