Diagnostic tracing and levers for dev session hot reload (#2417)

packages/app/src/cli/services/dev/app-events/app-event-watcher.ts

@@ -81,13 +81,17 @@ export interface AppEvent {
   path: string
   startTime: [number, number]
   appWasReloaded?: boolean
+  /** Monotonic build ID for tracing an event through the pipeline */
+  buildId?: number
 }
 
 type ExtensionBuildResult = {status: 'ok'; uid: string} | {status: 'error'; error: string; file?: string; uid: string}
 
 /**
  * App event watcher will emit events when changes are detected in the file system.
  */
+let nextBuildId = 1
+
 export class AppEventWatcher extends EventEmitter {
   buildOutputPath: string
   private app: AppLinkedInterface
@@ -125,35 +129,72 @@ export class AppEventWatcher extends EventEmitter {
     }
 
     this.fileWatcher = this.fileWatcher ?? new FileWatcher(this.app, this.options)
+    // Mutex for DEV_SERIALIZE_ONCHANGE lever
+    let onChangeLock: Promise<void> = Promise.resolve()
+
     this.fileWatcher.onChange((events) => {
-      handleWatcherEvents(events, this.app, this.options)
-        .then(async (appEvent) => {
-          if (appEvent?.extensionEvents.length === 0) outputDebug('Change detected, but no extensions were affected')
-          if (!appEvent) return
+      const buildId = nextBuildId++
+      outputDebug(`[build:${buildId}] onChange: ${events.length} event(s): ${events.map((e) => `${e.type}:${e.path.split('/').pop()}`).join(', ')}\n`, this.options.stdout)
+
+      const doWork = async () => {
+        const appEvent = await handleWatcherEvents(events, this.app, this.options)
+        if (appEvent?.extensionEvents.length === 0) {
+          outputDebug(`[build:${buildId}] no extensions affected, skipping`)
+          return
+        }
+        if (!appEvent) {
+          outputDebug(`[build:${buildId}] handleWatcherEvents returned undefined, skipping`)
+          return
+        }
 
-          this.app = appEvent.app
-          if (appEvent.appWasReloaded) this.fileWatcher?.updateApp(this.app)
+        appEvent.buildId = buildId
+        const extSummary = appEvent.extensionEvents.map((e) => `${e.type}:${e.extension.handle}`).join(', ')
+        outputDebug(`[build:${buildId}] processing ${appEvent.extensionEvents.length} extension event(s): ${extSummary}\n`, this.options.stdout)
+
+        this.app = appEvent.app
+        if (appEvent.appWasReloaded) this.fileWatcher?.updateApp(this.app)
+
+        // LEVER: DEV_SKIP_RESCAN_IMPORTS — skip rescanImports to test if watcher restart causes the break
+        if (!process.env.DEV_SKIP_RESCAN_IMPORTS) {
           await this.rescanImports(appEvent)
+        } else {
+          outputDebug(`[build:${buildId}] LEVER: skipping rescanImports\n`, this.options.stdout)
+        }
 
-          // Find affected created/updated extensions and build them
-          const buildableEvents = appEvent.extensionEvents.filter((extEvent) => extEvent.type !== EventType.Deleted)
+        // Find affected created/updated extensions and build them
+        const buildableEvents = appEvent.extensionEvents.filter((extEvent) => extEvent.type !== EventType.Deleted)
 
-          // Build the created/updated extensions and update the extension events with the build result
-          await this.buildExtensions(buildableEvents)
+        // Build the created/updated extensions and update the extension events with the build result
+        await this.buildExtensions(buildableEvents)
+        outputDebug(`[build:${buildId}] buildExtensions complete\n`, this.options.stdout)
 
-          // Generate the extension types after building the extensions so new imports are included
-          // Skip if the app was reloaded, as generateExtensionTypes was already called during reload
-          if (!appEvent.appWasReloaded) {
-            await this.app.generateExtensionTypes()
-          }
+        // LEVER: DEV_SKIP_GENERATE_TYPES — skip generateExtensionTypes to test if it hangs
+        if (!appEvent.appWasReloaded && !process.env.DEV_SKIP_GENERATE_TYPES) {
+          await this.app.generateExtensionTypes()
+        } else if (process.env.DEV_SKIP_GENERATE_TYPES) {
+          outputDebug(`[build:${buildId}] LEVER: skipping generateExtensionTypes\n`, this.options.stdout)
+        }
+        outputDebug(`[build:${buildId}] post-build steps complete\n`, this.options.stdout)
+
+        // Find deleted extensions and delete their previous build output
+        await this.deleteExtensionsBuildOutput(appEvent)
+        outputDebug(`[build:${buildId}] emitting 'all'\n`, this.options.stdout)
+        this.emit('all', appEvent)
+        outputDebug(`[build:${buildId}] 'all' emitted, listeners returned\n`, this.options.stdout)
+      }
 
-          // Find deleted extensions and delete their previous build output
-          await this.deleteExtensionsBuildOutput(appEvent)
-          this.emit('all', appEvent)
+      // LEVER: DEV_SERIALIZE_ONCHANGE — serialize onChange handlers to test if concurrency causes the break
+      if (process.env.DEV_SERIALIZE_ONCHANGE) {
+        onChangeLock = onChangeLock.then(doWork).catch((error) => {
+          outputDebug(`[build:${buildId}] ERROR in onChange pipeline: ${error.message}\n`, this.options.stdout)
+          this.emit('error', error)
         })
-        .catch((error) => {
+      } else {
+        doWork().catch((error) => {
+          outputDebug(`[build:${buildId}] ERROR in onChange pipeline: ${error.message}\n`, this.options.stdout)
           this.emit('error', error)
         })
+      }
     })
     await this.fileWatcher.start()
 

packages/app/src/cli/services/dev/extension.ts

@@ -146,7 +146,8 @@ export async function devUIExtensions(options: ExtensionDevOptions): Promise<voi
   const websocketConnection = setupWebsocketConnection({...payloadOptions, httpServer, payloadStore})
   outputDebug(`Setting up the UI extensions bundler and file watching...`, payloadOptions.stdout)
 
-  const eventHandler = async ({appWasReloaded, app, extensionEvents}: AppEvent) => {
+  const eventHandler = async ({appWasReloaded, app, extensionEvents, buildId}: AppEvent) => {
+    outputDebug(`[build:${buildId}] devUIExtensions eventHandler received (${extensionEvents.length} events)`, payloadOptions.stdout)
     if (appWasReloaded) {
       extensions = app.allExtensions.filter((ext) => ext.isPreviewable)
     }
@@ -155,6 +156,7 @@ export async function devUIExtensions(options: ExtensionDevOptions): Promise<voi
     // for the payloed. No other exceptions should be added, if this pattern is needed again we should
     // generalize it.
     payloadStore.updateAdminConfigFromExtensionEvents(extensionEvents)
+    outputDebug(`[build:${buildId}] devUIExtensions: payload store updated`, payloadOptions.stdout)
 
     for (const event of extensionEvents) {
       if (!event.extension.isPreviewable) continue

packages/app/src/cli/services/dev/processes/dev-session/dev-session.ts

@@ -82,9 +82,13 @@ export class DevSession {
    * @param event - The app event
    */
   private async onEvent(event: AppEvent) {
+    await this.logger.debug(`[build:${event.buildId}] DevSession.onEvent received`)
     const eventIsValid = await this.validateAppEvent(event)
-    if (!eventIsValid) return
-
+    if (!eventIsValid) {
+      await this.logger.debug(`[build:${event.buildId}] validateAppEvent returned false, dropping`)
+      return
+    }
+    await this.logger.debug(`[build:${event.buildId}] enqueuing to SerialBatchProcessor`)
     this.appEventsProcessor.enqueue(event)
   }
 
@@ -95,21 +99,44 @@ export class DevSession {
    * @param event - The app event to process
    */
   private async processEvents(events: AppEvent[]) {
+    const buildIds = events.map((e) => e.buildId).join(',')
+    await this.logger.debug(`[build:${buildIds}] processEvents: ${events.length} event(s), ${this.failedEvents.length} failed retries`)
     // Include any previously failed events to be processed again
     const allEvents = [...this.failedEvents, ...events]
     const event = this.consolidateAppEvents(allEvents)
     this.failedEvents = []
-    if (!event) return
+    if (!event) {
+      await this.logger.debug(`[build:${buildIds}] processEvents: consolidate returned undefined, skipping`)
+      return
+    }
 
     this.statusManager.setMessage('CHANGE_DETECTED')
     this.updatePreviewURL(event)
     await this.logger.logExtensionEvents(event)
 
     const networkStartTime = startHRTime()
-    const result = await this.bundleExtensionsAndUpload(event)
+    await this.logger.debug(`[build:${event.buildId}] processEvents: starting bundleExtensionsAndUpload`)
+
+    // LEVER: DEV_UPLOAD_TIMEOUT_MS — detect if bundleExtensionsAndUpload hangs forever
+    const timeoutMs = process.env.DEV_UPLOAD_TIMEOUT_MS ? parseInt(process.env.DEV_UPLOAD_TIMEOUT_MS, 10) : 0
+    let result: DevSessionResult
+    if (timeoutMs > 0) {
+      const timeout = new Promise<DevSessionResult>((_, reject) =>
+        setTimeout(() => reject(new Error(`[build:${event.buildId}] bundleExtensionsAndUpload TIMED OUT after ${timeoutMs}ms`)), timeoutMs),
+      )
+      try {
+        result = await Promise.race([this.bundleExtensionsAndUpload(event), timeout])
+      } catch (error: any) {
+        await this.logger.debug(error.message)
+        result = {status: 'unknown-error', error}
+      }
+    } else {
+      result = await this.bundleExtensionsAndUpload(event)
+    }
+    await this.logger.debug(`[build:${event.buildId}] processEvents: result=${result.status}`)
     await this.handleDevSessionResult(result, event)
     await this.logger.debug(
-      `✅ Event handled [Network: ${endHRTimeInMs(networkStartTime)}ms - Total: ${endHRTimeInMs(event.startTime)}ms]`,
+      `[build:${event.buildId}] Event handled [Network: ${endHRTimeInMs(networkStartTime)}ms - Total: ${endHRTimeInMs(event.startTime)}ms]`,
     )
   }
 
@@ -184,25 +211,29 @@ export class DevSession {
    */
   private async validateAppEvent(event: AppEvent): Promise<boolean> {
     if (!this.statusManager.status.isReady) {
+      await this.logger.debug(`[build:${event.buildId}] validate: NOT READY`)
       await this.logger.warning('Change detected, but dev preview is not ready yet.')
       return false
     }
 
     // If there are any build errors, don't update the dev session
     const errors = this.parseBuildErrors(event)
     if (errors.length) {
+      await this.logger.debug(`[build:${event.buildId}] validate: BUILD ERRORS (${errors.length})`)
       await this.logger.logMultipleErrors(errors)
       this.statusManager.setMessage('BUILD_ERROR')
       return false
     }
 
     if (event.extensionEvents.length === 0) {
+      await this.logger.debug(`[build:${event.buildId}] validate: NO EXTENSION EVENTS`)
       // The app was probably reloaded, but no extensions were affected, we are ready for new changes.
       // But we shouldn't trigger a new dev session update in this case.
       this.statusManager.setMessage('READY')
       return false
     }
 
+    await this.logger.debug(`[build:${event.buildId}] validate: VALID (${event.extensionEvents.length} events)`)
     return true
   }
 

scripts/dev-session-stress-test.sh

@@ -0,0 +1,72 @@
+#!/bin/bash
+#
+# Stress test for dev session hot reloading (issue #2417).
+#
+# Makes small source code changes to a hosted app at a configurable interval
+# to trigger repeated vite rebuilds → admin extension builds → dev session updates.
+# Designed for apps generated from the Preact template with a home/ directory.
+#
+# Usage:
+#   ./dev-session-stress-test.sh <app_path> [interval_seconds] [duration_minutes]
+#
+# Example:
+#   ./dev-session-stress-test.sh ~/src/apps/my-app 5 10
+#
+# The script toggles strings back and forth so the app stays valid.
+# Kill with: kill $(pgrep -f dev-session-stress-test)
+
+set -euo pipefail
+
+APP_PATH="${1:?Usage: $0 <app_path> [interval_seconds] [duration_minutes]}"
+INTERVAL="${2:-5}"
+DURATION="${3:-10}"
+ITERATIONS=$(( (DURATION * 60) / INTERVAL ))
+
+# Verify the app has the expected structure
+if [ ! -f "$APP_PATH/home/pages/home.tsx" ]; then
+  echo "Error: $APP_PATH/home/pages/home.tsx not found."
+  echo "This script is designed for apps with a home/ directory (Preact template)."
+  exit 1
+fi
+
+cd "$APP_PATH"
+echo "Stress test: $ITERATIONS changes every ${INTERVAL}s for ${DURATION}m in $APP_PATH"
+
+toggle() {
+  local file="$1" from="$2" to="$3"
+  if grep -q "$from" "$file" 2>/dev/null; then
+    sed -i '' "s|$from|$to|" "$file"
+  else
+    sed -i '' "s|$to|$from|" "$file"
+  fi
+}
+
+for i in $(seq 1 $ITERATIONS); do
+  case $((i % 6)) in
+    1) toggle home/pages/home.tsx \
+         'Create frequently asked questions to boost sales.' \
+         'Add FAQs to help customers find answers quickly.'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: home.tsx paragraph" ;;
+    2) toggle home/pages/home.tsx \
+         'alt="Illustration of FAQ creation"' \
+         'alt="FAQ empty state illustration"'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: home.tsx alt text" ;;
+    3) toggle home/pages/faq.tsx \
+         'e.g. What is your return policy?' \
+         'e.g. How long does shipping take?'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: faq.tsx placeholder" ;;
+    4) toggle home/pages/faq.tsx \
+         'Provide a clear, helpful answer' \
+         'Write a concise and informative response'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: faq.tsx details" ;;
+    5) toggle home/pages/_404.tsx \
+         'Go to home' 'Back to FAQs'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: _404.tsx button" ;;
+    0) toggle home/index.html \
+         '<title>Vite + Preact</title>' '<title>FAQ Manager</title>'
+       echo "[$(date '+%H:%M:%S')] $i/$ITERATIONS: index.html title" ;;
+  esac
+  [ "$i" -lt "$ITERATIONS" ] && sleep "$INTERVAL"
+done
+
+echo "[$(date '+%H:%M:%S')] Done. $ITERATIONS changes over ${DURATION}m."