telemetry(webview): Emit toolkit_X module telemetry on auth webview

Problem:

With our telemetry, we do not know when the frontend webview UI has actually loaded

Solution:

Emit certain metrics during the webview loading process to get a better idea of if the
webview UI successfully completed its initial load.

- toolkit_willOpenModule, indicates intent to render a webview
- toolkit_didLoadModule, indicates the final result of loading the webview
  - On Success it it just a success result. We know a success when the frontend send a successful
    message to the backend. It knows this by ensuring there were no errors and that a certain HTML element
    can be found, then once the page finishes its initial load it will send a success message to the backend.
  - On Failure, what happens is a timer times out after 10 seconds.

Signed-off-by: nkomonen-amazon <[email protected]>

Author: nkomonen-amazon

packages/core/src/amazonq/webview/messages/messageDispatcher.ts

@@ -16,6 +16,8 @@ import globals from '../../../shared/extensionGlobals'
 import { openUrl } from '../../../shared/utilities/vsCodeUtils'
 import { DefaultAmazonQAppInitContext } from '../../apps/initContext'
 
+const qChatModuleName = 'amazonqChat'
+
 export function dispatchWebViewMessagesToApps(
     webview: Webview,
     webViewToAppsMessagePublishers: Map<TabType, MessagePublisher<any>>
@@ -29,8 +31,8 @@ export function dispatchWebViewMessagesToApps(
                  * This would be equivalent of the duration between "user clicked open q" and "ui has become available"
                  * NOTE: Amazon Q UI is only loaded ONCE. The state is saved between each hide/show of the webview.
                  */
-                telemetry.webview_load.emit({
-                    webviewName: 'amazonq',
+                telemetry.toolkit_didLoadModule.emit({
+                    module: qChatModuleName,
                     duration: performance.measure(amazonqMark.uiReady, amazonqMark.open).duration,
                     result: 'Succeeded',
                 })
@@ -86,12 +88,19 @@ export function dispatchWebViewMessagesToApps(
         }
 
         if (msg.type === 'error') {
-            const event = msg.event === 'webview_load' ? telemetry.webview_load : telemetry.webview_error
-            event.emit({
-                webviewName: 'amazonqChat',
-                result: 'Failed',
-                reasonDesc: msg.errorMessage,
-            })
+            if (msg.event === 'toolkit_didLoadModule') {
+                telemetry.toolkit_didLoadModule.emit({
+                    module: qChatModuleName,
+                    result: 'Failed',
+                    reasonDesc: msg.errorMessage,
+                })
+            } else {
+                telemetry.webview_error.emit({
+                    webviewName: qChatModuleName,
+                    result: 'Failed',
+                    reasonDesc: msg.errorMessage,
+                })
+            }
             return
         }
 

packages/core/src/amazonq/webview/ui/main.ts

@@ -63,7 +63,7 @@ export const createMynahUI = (
         const { error, message } = e
         ideApi.postMessage({
             type: 'error',
-            event: connector.isUIReady ? 'webview_error' : 'webview_load',
+            event: connector.isUIReady ? 'webview_error' : 'toolkit_didLoadModule',
             errorMessage: error ? error.toString() : message,
         })
     })

packages/core/src/login/webview/commonAuthViewProvider.ts

@@ -137,6 +137,11 @@ export class CommonAuthViewProvider implements WebviewViewProvider {
         }
         webviewView.webview.html = this._getHtmlForWebview(this.extensionContext.extensionUri, webviewView.webview)
         // register the webview server
+        //
+        // TODO: Fix potential race condition, since setup() sets up the message handlers, but it is possible that
+        // when setting the .html above it will execute the HTML (and send messages) before the handlers are configured.
+        // To repro, add a sleep right after setting .html and watch how nothing loads. I'm assuming all the messages are
+        // dropped.
         await this.webView?.setup(webviewView.webview)
     }
 

packages/core/src/login/webview/vue/backend.ts

@@ -63,17 +63,19 @@ export abstract class CommonAuthWebview extends VueWebview {
 
     private didCall: { login: boolean; reauth: boolean } = { login: false, reauth: false }
     public setUiReady(state: 'login' | 'reauth') {
-        // Prevent telemetry spam, since showing/hiding chat triggers this each time.
-        // So only emit once.
+        this.loadTimeout?.dispose()
+
+        // Only emit once to prevent telemetry spam, since showing/hiding chat triggers this each time.
         if (this.didCall[state]) {
             return
         }
-
-        telemetry.webview_load.emit({
+        telemetry.toolkit_didLoadModule.emit({
             passive: true,
-            webviewName: state,
+            module: state,
             result: 'Succeeded',
+            traceId: this.traceId,
         })
+        this.traceId = undefined
         this.didCall[state] = true
     }
 

packages/core/src/login/webview/vue/login.vue

@@ -145,6 +145,7 @@
                 ></SelectableItem>
                 <button
                     class="continue-button"
+                    id="connection-selection-continue-button"
                     :disabled="selectedLoginOption === 0"
                     v-on:click="handleContinueClick()"
                 >
@@ -368,8 +369,6 @@ export default defineComponent({
         // Pre-select the first available login option
         await this.preselectLoginOption()
         await this.handleUrlInput() // validate the default startUrl
-
-        await client.setUiReady('login')
     },
     methods: {
         toggleItemSelection(itemId: number) {
@@ -590,6 +589,18 @@ export default defineComponent({
         },
     },
 })
+
+/**
+ * The ID of the element we will use to determine that the UI has completed its initial load.
+ *
+ * This makes assumptions that we will be in a certain state of the UI (eg showing a form vs. a loading bar).
+ * So if the UI flow changes, this may need to be updated.
+ */
+export function getReadyElementId() {
+    // On every initial load, we ASSUME that the user will always be in the connection selection state,
+    // which is why we specifically look for this button.
+    return 'connection-selection-continue-button'
+}
 </script>
 
 <style>

packages/core/src/login/webview/vue/reauthenticate.vue

@@ -127,9 +127,6 @@ export default defineComponent({
 
         this.doShow = true
     },
-    async mounted() {
-        await client.setUiReady('reauth')
-    },
     methods: {
         async reauthenticate() {
             client.emitUiClick('auth_reauthenticate')
@@ -148,6 +145,16 @@ export default defineComponent({
         },
     },
 })
+
+/**
+ * The ID of the element we will use to determine that the UI has completed its initial load.
+ *
+ * This makes assumptions that we will be in a certain state of the UI (eg showing a form vs. a loading bar).
+ * So if the UI flow changes, this may need to be updated.
+ */
+export function getReadyElementId() {
+    return 'button#reauthenticate'
+}
 </script>
 <style>
 @import './base.css';

packages/core/src/login/webview/vue/root.vue

@@ -16,8 +16,8 @@ configure app to AMAZONQ if for Amazon Q login
 </template>
 <script lang="ts">
 import { PropType, defineComponent } from 'vue'
-import Login from './login.vue'
-import Reauthenticate from './reauthenticate.vue'
+import Login, { getReadyElementId as getLoginReadyElementId } from './login.vue'
+import Reauthenticate, { getReadyElementId as getReauthReadyElementId } from './reauthenticate.vue'
 import { AuthFlowState, FeatureId } from './types'
 import { WebviewClientFactory } from '../../../webviews/client'
 import { CommonAuthWebview } from './backend'
@@ -51,15 +51,67 @@ export default defineComponent({
         })
 
         await this.refreshAuthState()
+
+        // We were recieving the 'load' event before refreshAuthState() resolved (I'm assuming behavior w/ Vue + browser loading not blocking),
+        // so post refreshAuhState() if we detect we already loaded, then execute immediately since the event already happened.
+        if (didLoad) {
+            handleLoaded()
+        } else {
+            window.addEventListener('load', () => {
+                handleLoaded()
+            })
+        }
     },
     methods: {
         async refreshAuthState() {
             await client.refreshAuthState()
             this.authFlowState = await client.getAuthState()
+
+            // Used for telemetry purposes
+            if (this.authFlowState === 'LOGIN') {
+                ;(window as any).uiState = 'login'
+                ;(window as any).uiReadyElementId = getLoginReadyElementId()
+            } else if (this.authFlowState && this.authFlowState !== undefined) {
+                ;(window as any).uiState = 'reauth'
+                ;(window as any).uiReadyElementId = getReauthReadyElementId()
+            }
+
             this.refreshKey += 1
         },
     },
 })
+
+// THe following handles the process of indicating the UI has loaded successfully.
+let emittedReady = false
+let errorMessage: string | undefined = undefined
+// Catch JS errors
+window.onerror = function (message) {
+    errorMessage = message.toString()
+}
+// Listen for DOM errors
+document.addEventListener(
+    'error',
+    function (e) {
+        errorMessage = e.message
+    },
+    true
+)
+let didLoad = false
+window.addEventListener('load', () => {
+    didLoad = true
+})
+const handleLoaded = () => {
+    // TODO: See if this ever gets triggered, and if not, delete emittedReady
+    if (emittedReady) {
+        console.log(`NIKOLAS: load event triggered a subsequent time`)
+    }
+
+    if (!emittedReady && errorMessage === undefined && !!document.getElementById((window as any).uiReadyElementId)) {
+        emittedReady = true // ensure we only emit once per load
+        client.setUiReady((window as any).uiState)
+        window.postMessage({ command: `ui-is-ready`, state: (window as any).uiState })
+    }
+}
 </script>
 <style>
 body {

packages/core/src/shared/telemetry/vscodeTelemetry.json

@@ -985,16 +985,6 @@
             ],
             "passive": true
         },
-        {
-            "name": "webview_load",
-            "description": "Represents a webview load event",
-            "metadata": [
-                {
-                    "type": "webviewName",
-                    "required": true
-                }
-            ]
-        },
         {
             "name": "webview_error",
             "description": "Represents an error that occurs in a webview",

packages/core/src/webviews/main.ts

@@ -7,6 +7,9 @@ import * as vscode from 'vscode'
 import { Protocol, registerWebviewServer } from './server'
 import { getIdeProperties } from '../shared/extensionUtilities'
 import { getFunctions } from '../shared/utilities/classUtils'
+import { telemetry } from '../shared/telemetry/telemetry'
+import { randomUUID } from '../shared/crypto'
+import { Timeout } from '../shared/utilities/timeoutUtils'
 
 interface WebviewParams {
     /**
@@ -151,6 +154,16 @@ export abstract class VueWebview {
      */
     public abstract readonly id: string
 
+    /**
+     * A unique identifier used to connect the opening/loaded metrics of a webview
+     */
+    public traceId: string | undefined = undefined
+    /**
+     * When the webview is doing its initial render/load, this times out if it takes too long
+     * to get a "success" message (we assume something went wrong)
+     */
+    public loadTimeout: Timeout | undefined
+
     /**
      * The relative location, from the repository root, to the frontend entrypoint.
      */
@@ -189,6 +202,7 @@ export abstract class VueWebview {
 
     protected dispose(): void {
         this.disposed = true
+        this.loadTimeout?.dispose()
         this.onDidDisposeEmitter.fire()
     }
 
@@ -225,12 +239,38 @@ export abstract class VueWebview {
             }
 
             public async setup(webview: vscode.Webview) {
+                this.setupTelemetry()
+
                 const server = registerWebviewServer(webview, this.instance.protocol, this.instance.id)
                 this.instance.onDidDispose(() => {
                     server.dispose()
                 })
             }
 
+            /**
+             * Setup telemetry events that report on the initial loading of a webview
+             */
+            private setupTelemetry() {
+                this.instance.traceId = randomUUID()
+                // Notify intent to open a module, this does not mean it successfully opened
+                telemetry.toolkit_willOpenModule.emit({
+                    module: this.instance.id,
+                    result: 'Succeeded',
+                    traceId: this.instance.traceId,
+                })
+                this.instance.loadTimeout = new Timeout(10_000)
+                this.instance.loadTimeout.token.onCancellationRequested(() => {
+                    // Timeout expired, so loading failed
+                    telemetry.toolkit_didLoadModule.emit({
+                        module: this.instance.id,
+                        result: 'Failed',
+                        traceId: this.instance.traceId,
+                        reason: 'LoadTimedOut',
+                        reasonDesc: 'Likely due to an error in the frontend',
+                    })
+                })
+            }
+
             public async show(params: Omit<WebviewPanelParams, 'id' | 'webviewJs'>): Promise<vscode.WebviewPanel> {
                 if (this.panel) {
                     this.panel.reveal(params.viewColumn, false)