feat(logs): "Watch Logs" command #4176

Problem:
- Not easy to observe telemetry as it happens.
- Telemetry logs could be much more readable with some formatting.

Solution:
- Use new vscode API [LogOutputChannel](https://github.com/microsoft/vscode/blob/aa835c938d2518832a934a7e3124fa761c6f50a0/src/vscode-dts/vscode.d.ts#L10766)
- Add "AWS (Developer): Watch Logs" command which shows logs the vscode
  Debug Console (which allows filtering, unlike the Output panel).
  microsoft/vscode#52134
- Cleanup the metrics `Metadata` field before logging it.
- Format with "%O" instead of JSON stringify.

Before:

    telemetry: emitted metric "aws_expandExplorerNode" -> {"Metadata":[{"Key":"serviceType","Value":"ecs"},{"Key":"awsAccount","Value":"541201481031"},{"Key":"awsRegion","Value":"us-west-2"}],"MetricName":"aws_expandExplorerNode","Value":1,"Unit":"None","Passive":false,"EpochTimestamp":1697147194606}

After:

    2023-10-19 14:22:25 [DEBUG]: telemetry: aws_expandExplorerNode {
      Metadata: {
        serviceType: 'logs',
        awsAccount: '541201481031',
        awsRegion: 'us-west-2'
      },
      Value: 1,
      Unit: 'None',
      Passive: false
    }

Author: justinmk3

CONTRIBUTING.md

@@ -286,28 +286,36 @@ generating SDKs, etc.
 
 ### Toolkit developer settings (`aws.dev.*`)
 
-The [DevSettngs](https://github.com/aws/aws-toolkit-vscode/blob/479b9d45b5f5ad30fc10567e649b59801053aeba/src/shared/settings.ts#L553) class defines various developer-only settings that change the behavior of the
+The [DevSettings](https://github.com/aws/aws-toolkit-vscode/blob/479b9d45b5f5ad30fc10567e649b59801053aeba/src/shared/settings.ts#L553) class defines various developer-only settings that change the behavior of the
 Toolkit for testing and development purposes. To use a setting just add it to
 your `settings.json`. At runtime, if the Toolkit reads any of these settings,
 the "AWS" statusbar item will [change its color](https://github.com/aws/aws-toolkit-vscode/blob/479b9d45b5f5ad30fc10567e649b59801053aeba/src/credentials/awsCredentialsStatusBarItem.ts#L45).
 
-The setting `aws.dev.forceDevMode` will take precedence over all dev settings and enable dev mode on `"aws.dev.forceDevMode": true` or disable on `"aws.dev.forceDevMode": false`.
+The `aws.dev.forceDevMode` setting enables or disables Toolkit "dev mode". Without this setting, the presence of any other `aws.dev.*` setting defined in `DevSettings` implicitly enables "dev mode".
 
 ### Logging
 
-The `aws.dev.logfile` setting allows you to set the path of the logfile. This makes it easy to
-follow and filter the logfile using shell tools like `tail` and `grep`. For example in
-settings.json,
-
+-   Use the `aws.dev.logfile` setting to set the logfile path to a fixed location, so you can easily
+    follow and filter the logfile using shell tools like `tail` and `grep`. For example in
+    settings.json,
+    ```
     "aws.dev.logfile": "~/awstoolkit.log",
-
-then following the log with:
-
+    ```
+    then you can tail the logfile in your terminal:
+    ```
     tail -F ~/awstoolkit.log
+    ```
+-   Use the `AWS (Developer): Watch Logs` command to watch and filter Toolkit logs (including
+    telemetry) in VSCode.
+    -   Only available if you enabled "dev mode" (`aws.dev.forceDevMode` setting, see above).
+    -   Sets `aws.logLevel` to "debug".
+    -   Enter text in the Debug Console filter box to show only log messages with that text. <br/>
+        <img src="./docs/images/debug-console-filter.png" alt="VSCode Debug Console" width="320"/>
 
 ### Telemetry
 
-See [docs/telemetry.md](./docs/telemetry.md) for notes on emitting telemetry in this project.
+-   See [docs/telemetry.md](./docs/telemetry.md) for guidelines on developing telemetry in this project.
+-   To watch Toolkit telemetry events, use the `AWS (Developer): Watch Logs` command (see [Logging](#logging) above) and enter "telemetry" in the Debug Console filter box.
 
 ### Service Endpoints
 

docs/images/debug-console-filter.png

@@ -3751,6 +3751,11 @@
                 "category": "AWS (Developer)",
                 "enablement": "aws.isDevMode"
             },
+            {
+                "command": "aws.dev.viewLogs",
+                "title": "Watch Logs",
+                "category": "AWS (Developer)"
+            },
             {
                 "command": "aws.openInApplicationComposerDialog",
                 "title": "%AWS.command.applicationComposer.openDialog%",

package.json

@@ -20,6 +20,7 @@ import { entries } from '../shared/utilities/tsUtils'
 import { isReleaseVersion } from '../shared/vscode/env'
 import { isAnySsoConnection } from '../auth/connection'
 import { Auth } from '../auth/auth'
+import { getLogger } from '../shared/logger'
 
 interface MenuOption {
     readonly label: string
@@ -55,9 +56,9 @@ const menuOptions: Record<string, MenuOption> = {
         executor: deleteDevEnvCommand,
     },
     editStorage: {
-        label: 'Show or Edit Global Storage',
+        label: 'Show or Edit globalState',
         description: 'VS Code',
-        detail: 'Shows all globalState values, or edit a specific globalState/secret key as a JSON document',
+        detail: 'Shows all globalState values, or edit a globalState/secret item',
         executor: openStorageFromInput,
     },
     showEnvVars: {
@@ -124,8 +125,23 @@ export async function activate(ctx: vscode.ExtensionContext): Promise<void> {
 
     ctx.subscriptions.push(
         devSettings.onDidChangeActiveSettings(updateMode),
+        vscode.workspace.registerTextDocumentContentProvider('aws-dev2', new DevDocumentProvider(ctx)),
+        // "AWS (Developer): Open Developer Menu"
         vscode.commands.registerCommand('aws.dev.openMenu', () => openMenu(ctx, menuOptions)),
-        vscode.workspace.registerTextDocumentContentProvider('aws-dev2', new DevDocumentProvider(ctx))
+        // "AWS (Developer): Watch Logs"
+        Commands.register('aws.dev.viewLogs', async () => {
+            // HACK: Use startDebugging() so we can use the DEBUG CONSOLE (which supports
+            // user-defined filtering, unlike the OUTPUT panel).
+            await vscode.debug.startDebugging(undefined, {
+                name: 'aws-dev-log',
+                request: 'launch',
+                type: 'node', // Nonsense, to force the debugger to start.
+            })
+            getLogger().enableDebugConsole()
+            if (!getLogger().logLevelEnabled('debug')) {
+                getLogger().setLogLevel('debug')
+            }
+        })
     )
 
     await updateMode()

src/dev/activation.ts

@@ -92,7 +92,8 @@ export async function activate(context: vscode.ExtensionContext) {
     initializeManifestPaths(context)
 
     const toolkitOutputChannel = vscode.window.createOutputChannel(
-        localize('AWS.channel.aws.toolkit', '{0} Toolkit', getIdeProperties().company)
+        localize('AWS.channel.aws.toolkit', '{0} Toolkit', getIdeProperties().company),
+        { log: true }
     )
     await activateLogger(context, toolkitOutputChannel)
     const remoteInvokeOutputChannel = vscode.window.createOutputChannel(

src/extension.ts

@@ -50,7 +50,7 @@ export async function activate(
     setLogger(mainLogger)
     getLogger().info(`log level: ${getLogLevel()}`)
 
-    // channel logger
+    // Logs to "AWS Toolkit" output channel.
     setLogger(
         makeLogger(
             {
@@ -62,11 +62,11 @@ export async function activate(
         'channel'
     )
 
-    // debug channel logger
+    // Logs to vscode Debug Console.
     setLogger(
         makeLogger(
             {
-                staticLogLevel: 'verbose', // verbose will log anything
+                staticLogLevel: 'debug',
                 outputChannels: [outputChannel, chan],
                 useDebugConsole: true,
             },

src/shared/logger/activation.ts

@@ -27,6 +27,8 @@ export interface Logger {
     /** Returns true if the given log level is being logged.  */
     logLevelEnabled(logLevel: LogLevel): boolean
     getLogById(logID: number, file: Uri): string | undefined
+    /** HACK: Enables logging to vscode Debug Console. */
+    enableDebugConsole(): void
 }
 
 /**
@@ -97,6 +99,7 @@ export class NullLogger implements Logger {
     public getLogById(logID: number, file: Uri): string | undefined {
         return undefined
     }
+    public enableDebugConsole(): void {}
 }
 
 /**
@@ -131,6 +134,7 @@ export class ConsoleLogger implements Logger {
     public getLogById(logID: number, file: Uri): string | undefined {
         return undefined
     }
+    public enableDebugConsole(): void {}
 }
 
 export function getNullLogger(type?: 'channel' | 'debugConsole' | 'main'): Logger {

src/shared/logger/logger.ts

@@ -43,6 +43,10 @@ export class WinstonToolkitLogger implements Logger, vscode.Disposable {
         })
     }
 
+    public enableDebugConsole(): void {
+        this.logToDebugConsole()
+    }
+
     public setLogLevel(logLevel: LogLevel) {
         if (this.logger.level === logLevel) {
             return

src/shared/logger/winstonToolkitLogger.ts

@@ -4,6 +4,7 @@
  */
 
 import { getLogger } from '../logger'
+import { DevSettings } from '../settings'
 import { isReleaseVersion } from '../vscode/env'
 import { MetricDatum, MetadataEntry } from './clienttelemetry'
 
@@ -28,7 +29,14 @@ function isValidEntry(datum: MetadataEntry): datum is Required<MetadataEntry> {
 }
 
 /**
- * Telemetry currently sends metadata as an array of key/value pairs, but this is unintuitive for JS
+ * Takes a Telemetry metadata key-value pairs array:
+ * ```
+ *      [ {Key:'a',Value:…}, {Key:'b',Value:…}, … ]
+ * ```
+ * and produces an object:
+ * ```
+ *      {a:…, b:…}
+ * ```
  */
 export const mapMetadata = (excludeKeys: string[]) => (metadata: Required<MetricDatum>['Metadata']) => {
     const result: Metadata = {}
@@ -38,13 +46,29 @@ export const mapMetadata = (excludeKeys: string[]) => (metadata: Required<Metric
         .reduce((a, b) => ((a[b.Key] = b.Value), a), result)
 }
 
+/** Transforms a metric for human readability in logs, etc. */
+function scrubMetric(metric: MetricDatum): any {
+    const metaMap = mapMetadata(['MetricName'])(metric.Metadata ?? [])
+    metaMap.awsAccount = metaMap.awsAccount && metaMap.awsAccount.length > 10 ? '[omitted]' : metaMap.awsAccount
+    const metricCopy = { ...metric, Metadata: metaMap } as any
+    delete metricCopy.MetricName // Redundant.
+    delete metricCopy.EpochTimestamp // Not interesting.
+    return metricCopy
+}
+
 /**
  * Simple class to log queryable metrics.
  *
  * Does not track any other telemetry APIs such as feedback.
  */
 export class TelemetryLogger {
     private readonly _metrics: MetricDatum[] = []
+    private readonly isDevMode: boolean
+
+    public constructor() {
+        const devSettings = DevSettings.instance
+        this.isDevMode = devSettings.isDevMode()
+    }
 
     public get metricCount(): number {
         return this._metrics.length
@@ -55,13 +79,13 @@ export class TelemetryLogger {
     }
 
     public log(metric: MetricDatum): void {
-        const msg = `telemetry: emitted metric "${metric.MetricName}"`
+        const msg = `telemetry: ${metric.MetricName}`
 
-        if (!isReleaseVersion()) {
+        if (this.isDevMode || !isReleaseVersion()) {
             this._metrics.push(metric)
             if (getLogger().logLevelEnabled('debug')) {
-                const stringified = JSON.stringify(metric)
-                getLogger().debug(`${msg} -> ${stringified}`)
+                const metricCopy = scrubMetric(metric)
+                getLogger().debug(`${msg} %O`, metricCopy)
             } else {
                 getLogger().verbose(msg)
             }

src/shared/telemetry/telemetryLogger.ts

@@ -15,7 +15,7 @@ import { getLogger } from '../logger'
  * If `n` is negative, truncates at start instead of end.
  *
  * @param s String to truncate
- * @param n Truncate top-level string properties exceeding this length
+ * @param n Truncate after this length
  * @param suffix String appended to truncated value (default: "…")
  */
 export function truncate(s: string, n: number, suffix?: string): string {