feat(audoedit): improve output channel logs

sourcegraph · Jan 8, 2025 · 66bc0e1 · 66bc0e1
1 parent ba5d332
commit 66bc0e1
Show file tree

Hide file tree

Showing 2 changed files with 70 additions and 48 deletions.
diff --git a/vscode/src/autoedits/analytics-logger/analytics-logger.ts b/vscode/src/autoedits/analytics-logger/analytics-logger.ts
@@ -463,7 +463,7 @@ export class AutoeditAnalyticsLogger {
                     source,
                     isFuzzyMatch,
                     responseHeaders,
-                    latency: loadedAt - request.startedAt,
+                    latency: Math.floor(loadedAt - request.startedAt),
                 },
             }
         })
@@ -618,9 +618,10 @@ export class AutoeditAnalyticsLogger {
             !request ||
             !(validRequestTransitions[request.phase] as readonly Phase[]).includes(nextPhase)
         ) {
-            this.writeDebugBookkeepingEvent(
-                `invalidTransitionTo${capitalize(nextPhase) as Capitalize<Phase>}`
-            )
+            this.writeAutoeditEvent({
+                action: `invalidTransitionTo${capitalize(nextPhase) as Capitalize<Phase>}`,
+                logDebugArgs: [request ? `from: "${request.phase}"` : 'missing request'],
+            })
 
             return null
         }
@@ -642,40 +643,44 @@ export class AutoeditAnalyticsLogger {
         state.suggestionLoggedAt = getTimeNowInMillis()
 
         const { metadata, privateMetadata } = splitSafeMetadata(payload)
-        this.writeAutoeditEvent(action, {
-            version: 0,
-            // Extract `id` from payload into the first-class `interactionId` field.
-            interactionID: 'id' in payload ? payload.id : undefined,
-            metadata: {
-                ...metadata,
-                recordsPrivateMetadataTranscript: 'prediction' in privateMetadata ? 1 : 0,
-            },
-            privateMetadata,
-            billingMetadata: {
-                product: 'cody',
-                // TODO: double check with the analytics team
-                // whether we should be categorizing the different completion event types.
-                category: action === 'suggested' ? 'billable' : 'core',
+
+        this.writeAutoeditEvent({
+            action,
+            logDebugArgs: terminalStateToLogDebugArgs(action, state),
+            telemetryParams: {
+                version: 0,
+                // Extract `id` from payload into the first-class `interactionId` field.
+                interactionID: 'id' in payload ? payload.id : undefined,
+                metadata: {
+                    ...metadata,
+                    recordsPrivateMetadataTranscript: 'prediction' in privateMetadata ? 1 : 0,
+                },
+                privateMetadata,
+                billingMetadata: {
+                    product: 'cody',
+                    // TODO: double check with the analytics team
+                    // whether we should be categorizing the different completion event types.
+                    category: action === 'suggested' ? 'billable' : 'core',
+                },
             },
         })
     }
 
-    private writeAutoeditEvent(
-        action: AutoeditEventAction,
-        params?: TelemetryEventParameters<{ [key: string]: number }, BillingProduct, BillingCategory>
-    ): void {
-        autoeditsOutputChannelLogger.logDebug(
-            'writeAutoeditEvent',
-            `${action} id: "${params?.interactionID ?? 'n/a'}"`,
-            {
-                verbose: {
-                    latency: params?.metadata?.latency,
-                    prediction: params?.privateMetadata?.prediction,
-                    codeToRewrite: params?.privateMetadata?.codeToRewrite,
-                },
-            }
-        )
-        telemetryRecorder.recordEvent('cody.autoedit', action, params)
+    private writeAutoeditEvent({
+        action,
+        logDebugArgs,
+        telemetryParams,
+    }: {
+        action: AutoeditEventAction
+        logDebugArgs: readonly [string, ...unknown[]]
+        telemetryParams?: TelemetryEventParameters<
+            { [key: string]: number },
+            BillingProduct,
+            BillingCategory
+        >
+    }): void {
+        autoeditsOutputChannelLogger.logDebug('writeAutoeditEvent', action, ...logDebugArgs)
+        telemetryRecorder.recordEvent('cody.autoedit', action, telemetryParams)
     }
 
     /**
@@ -691,36 +696,52 @@ export class AutoeditAnalyticsLogger {
         const traceId = isNetworkError(error) ? error.traceId : undefined
 
         const currentCount = this.errorCounts.get(messageKey) ?? 0
+        const logDebugArgs = [error.name, { verbose: { message: error.message } }] as const
         if (currentCount === 0) {
-            this.writeAutoeditEvent('error', {
-                version: 0,
-                metadata: { count: 1 },
-                privateMetadata: { message: error.message, traceId },
+            this.writeAutoeditEvent({
+                action: 'error',
+                logDebugArgs,
+                telemetryParams: {
+                    version: 0,
+                    metadata: { count: 1 },
+                    privateMetadata: { message: error.message, traceId },
+                },
             })
 
             // After the interval, flush repeated errors
             setTimeout(() => {
                 const finalCount = this.errorCounts.get(messageKey) ?? 0
                 if (finalCount > 0) {
-                    this.writeAutoeditEvent('error', {
-                        version: 0,
-                        metadata: { count: finalCount },
-                        privateMetadata: { message: error.message, traceId },
+                    this.writeAutoeditEvent({
+                        action: 'error',
+                        logDebugArgs,
+                        telemetryParams: {
+                            version: 0,
+                            metadata: { count: finalCount },
+                            privateMetadata: { message: error.message, traceId },
+                        },
                     })
                 }
                 this.errorCounts.set(messageKey, 0)
             }, this.ERROR_THROTTLE_INTERVAL_MS)
         }
         this.errorCounts.set(messageKey, currentCount + 1)
     }
-
-    private writeDebugBookkeepingEvent(action: `invalidTransitionTo${Capitalize<Phase>}`): void {
-        this.writeAutoeditEvent(action)
-    }
 }
 
 export const autoeditAnalyticsLogger = new AutoeditAnalyticsLogger()
 
 export function getTimeNowInMillis(): number {
     return Math.floor(performance.now())
 }
+
+function terminalStateToLogDebugArgs(
+    action: AutoeditEventAction,
+    { requestId, phase, payload }: AcceptedState | RejectedState | DiscardedState
+): readonly [string, ...unknown[]] {
+    if (action === 'suggested' && (phase === 'rejected' || phase === 'accepted')) {
+        return [`"${requestId}" latency:"${payload.latency}ms" isRead:"${payload.isRead}"`]
+    }
+
+    return [`"${requestId}"`]
+}
diff --git a/vscode/src/autoedits/autoedits-provider.ts b/vscode/src/autoedits/autoedits-provider.ts
@@ -269,8 +269,8 @@ export class AutoeditsProvider implements vscode.InlineCompletionItemProvider, v
         })
         autoeditsOutputChannelLogger.logDebug(
             'provideInlineCompletionItems',
-            `========================== Response:\n${initialPrediction}\n` +
-                `========================== Time Taken: ${getTimeNowInMillis() - start}ms`
+            `"${requestId}" ============= Response:\n${initialPrediction}\n` +
+                `============= Time Taken: ${getTimeNowInMillis() - start}ms`
         )
 
         const prediction = shrinkPredictionUntilSuffix({
@@ -383,6 +383,7 @@ export class AutoeditsProvider implements vscode.InlineCompletionItemProvider, v
      * same name, it's prefixed with `unstable_` to avoid a clash when the new API goes GA.
      */
     public async unstable_handleDidShowCompletionItem(requestId: AutoeditRequestID): Promise<void> {
+        autoeditsOutputChannelLogger.logDebug('handleDidShowSuggestion', `"${requestId}"`)
         return this.rendererManager.handleDidShowSuggestion(requestId)
     }