Merge #3438 codecatalyst: logging

Author: justinmk3

src/shared/clients/codecatalystClient.ts

@@ -10,6 +10,7 @@ const localize = nls.loadMessageBundle()
 
 import * as AWS from 'aws-sdk'
 import * as logger from '../logger/logger'
+import { PerfLog } from '../logger/logger'
 import { ServiceConfigurationOptions } from 'aws-sdk/lib/service'
 import { CancellationError, Timeout, waitTimeout, waitUntil } from '../utilities/timeoutUtils'
 import { isUserCancelledError } from '../../shared/errors'
@@ -28,8 +29,8 @@ import {
     ListSourceRepositoriesItem,
     ListSourceRepositoriesItems,
 } from 'aws-sdk/clients/codecatalyst'
+import { truncateProps } from '../utilities/textUtilities'
 
-// REMOVE ME SOON: only used for development
 interface CodeCatalystConfig {
     readonly region: string
     readonly endpoint: string
@@ -224,10 +225,12 @@ class CodeCatalystClientInternal {
         const log = this.log
         const bearerToken = (await this.connection.getToken()).accessToken
         req.httpRequest.headers['Authorization'] = `Bearer ${bearerToken}`
+        const perflog = new PerfLog('API request')
 
         return new Promise<T>((resolve, reject) => {
             req.send(function (e, data) {
                 const r = req as any
+                const timecost = perflog.elapsed().toFixed(1)
                 if (e) {
                     if (e.code === 'AccessDeniedException' || e.statusCode === 401) {
                         CodeCatalystClientInternal.identityCache.delete(bearerToken)
@@ -237,19 +240,16 @@ class CodeCatalystClientInternal {
                     const logHeaders = {}
                     // Selected headers which are useful for logging.
                     const logHeaderNames = [
-                        // 'access-control-expose-headers',
-                        // 'cache-control',
-                        // 'strict-transport-security',
-                        'x-amz-apigw-id',
-                        'x-amz-cf-id',
-                        'x-amz-cf-pop',
-                        'x-amzn-remapped-content-length',
-                        'x-amzn-remapped-x-amzn-requestid',
                         'x-amzn-requestid',
-                        'x-amzn-served-from',
                         'x-amzn-trace-id',
+                        'x-amzn-served-from',
                         'x-cache',
-                        'x-request-id', // <- Request id for caws/fusi!
+                        'x-amz-cf-id',
+                        'x-amz-cf-pop',
+                        // 'access-control-expose-headers',
+                        // 'cache-control',
+                        // 'strict-transport-security',
+                        // 'x-amz-apigw-id',
                     ]
                     if (allHeaders && Object.keys(allHeaders).length > 0) {
                         for (const k of logHeaderNames) {
@@ -260,21 +260,24 @@ class CodeCatalystClientInternal {
                     // Stack is noisy and useless in production.
                     const errNoStack = { ...e }
                     delete errNoStack.stack
-                    // Remove confusing "requestId" field (= "x-amzn-requestid" header)
-                    // because for caws/fusi, "x-request-id" is more relevant.
-                    // All of the various request-ids can be found in the logged headers.
-                    delete errNoStack.requestId
+                    delete errNoStack.requestId // redundant (= "x-amzn-requestid" header).
 
                     if (r.operation || r.params) {
                         log.error(
-                            'API request failed: %s\nparams: %O\nerror: %O\nheaders: %O',
+                            'API request failed (time: %dms): %s\nparams: %O\nerror: %O\nheaders: %O',
+                            timecost,
                             r.operation,
-                            r.params,
+                            truncateProps(r.params, 20, ['nextToken']),
                             errNoStack,
                             logHeaders
                         )
                     } else {
-                        log.error('API request failed:%O\nheaders: %O', req, logHeaders)
+                        log.error(
+                            'API request failed (time: %dms):%O\nheaders: %O',
+                            timecost,
+                            truncateProps(req, 20, ['nextToken']),
+                            logHeaders
+                        )
                     }
                     if (silent) {
                         if (defaultVal === undefined) {
@@ -286,7 +289,15 @@ class CodeCatalystClientInternal {
                     }
                     return
                 }
-                log.verbose('API request (%s):\nparams: %O\nresponse: %O', r.operation ?? '?', r.params ?? '?', data)
+                if (log.logLevelEnabled('verbose')) {
+                    log.verbose(
+                        'API request (time: %dms): %s\nparams: %O\nresponse: %O',
+                        timecost,
+                        r.operation ?? '?',
+                        r.params ? truncateProps(r.params, 20, ['nextToken']) : '?',
+                        truncateProps(data as object, 20, ['nextToken'])
+                    )
+                }
                 resolve(data)
             })
         })

src/shared/logger/logger.ts

@@ -4,6 +4,7 @@
  */
 
 import { Uri } from 'vscode'
+import globals from '../extensionGlobals'
 
 const toolkitLoggers: {
     main: Logger | undefined
@@ -144,22 +145,24 @@ export function setLogger(logger: Logger | undefined, type?: 'channel' | 'debugC
 }
 
 export class PerfLog {
-    private log
+    private readonly log
     public readonly start
 
     public constructor(public readonly topic: string) {
         const log = getLogger()
         this.log = log
-        if (log.logLevelEnabled('verbose')) {
-            this.start = Date.now()
-        }
+        this.start = globals.clock.Date.now()
+    }
+
+    public elapsed(): number {
+        return globals.clock.Date.now() - this.start
     }
 
     public done(): void {
-        if (!this.start) {
+        if (!this.log.logLevelEnabled('verbose')) {
             return
         }
-        const elapsed = Date.now() - this.start
+        const elapsed = this.elapsed()
         this.log.verbose('%s took %dms', this.topic, elapsed.toFixed(1))
     }
 }

src/shared/utilities/textUtilities.ts

@@ -10,6 +10,63 @@ import { default as stripAnsi } from 'strip-ansi'
 import { isCloud9 } from '../extensionUtilities'
 import { getLogger } from '../logger'
 
+/**
+ * Truncates string `s` if it exceeds `len` chars.
+ *
+ * @param s String to truncate
+ * @param len Truncate top-level string properties exceeding this length
+ * @param suffix String appended to truncated value (default: "…")
+ */
+export function truncate(s: string, len: number, suffix?: string): string {
+    suffix = suffix ?? '…'
+    if (len <= 0) {
+        throw Error(`invalid len: ${len}`)
+    }
+    if (s === undefined || s.length <= len) {
+        return s
+    }
+    return `${s.substring(0, len)}${suffix}`
+}
+
+/**
+ * Creates a (shallow) clone of `obj` and truncates its top-level string properties.
+ *
+ * @param obj Object to copy and truncate
+ * @param len Truncate top-level string properties exceeding this length
+ * @param propNames Only truncate properties in this list
+ * @param suffix String appended to truncated values (default: "…")
+ */
+export function truncateProps(obj: object, len: number, propNames?: string[], suffix?: string): object {
+    if (len <= 0) {
+        throw Error(`invalid len: ${len}`)
+    }
+    // Shallow-copy to avoid modifying the original object.
+    const r = { ...obj }
+
+    if (propNames) {
+        for (const propName of propNames) {
+            try {
+                const val = (r as any)[propName]
+                if (val !== undefined && typeof val === 'string') {
+                    ;(r as any)[propName] = truncate(val, len, suffix)
+                }
+            } catch {
+                // Do nothing ("best effort").
+            }
+        }
+    } else {
+        for (const propName of Object.getOwnPropertyNames(r)) {
+            try {
+                ;(r as any)[propName] = truncate((r as any)[propName], len, suffix)
+            } catch {
+                // Do nothing ("best effort").
+            }
+        }
+    }
+
+    return r
+}
+
 export function removeAnsi(text: string): string {
     try {
         return stripAnsi(text)

src/test/shared/utilities/textUtilities.test.ts

@@ -4,7 +4,46 @@
  */
 
 import * as assert from 'assert'
-import { getRelativeDate, getStringHash, removeAnsi } from '../../../shared/utilities/textUtilities'
+import { getRelativeDate, getStringHash, removeAnsi, truncateProps } from '../../../shared/utilities/textUtilities'
+
+describe('textUtilities', async function () {
+    it('truncateProps()', async function () {
+        const testObj = {
+            a: 34234234234,
+            b: '123456789',
+            c: new Date(2023, 1, 1),
+            d: '123456789_abcdefg_ABCDEFG',
+            e: {
+                e1: [4, 3, 7],
+                e2: 'loooooooooo \n nnnnnnnnnnn \n gggggggg \n string',
+            },
+            f: () => {
+                throw Error()
+            },
+        }
+        const expected = {
+            ...testObj,
+            e: {
+                e1: [...testObj.e.e1],
+                e2: testObj.e.e2,
+            },
+        }
+
+        assert.deepStrictEqual(truncateProps(testObj, 25), expected)
+        assert.deepStrictEqual(truncateProps(testObj, 3, ['b']), {
+            ...expected,
+            b: '123…',
+        })
+        // Assert that original object didn't change.
+        assert.deepStrictEqual(truncateProps(testObj, 25), expected)
+
+        assert.deepStrictEqual(truncateProps(testObj, 3, ['a', 'b', 'd', 'f']), {
+            ...expected,
+            b: '123…',
+            d: '123…',
+        })
+    })
+})
 
 describe('removeAnsi', async function () {
     it('removes ansi code from text', async function () {