Feature/network debugging

.github/workflows/node.js.yml

@@ -117,3 +117,11 @@ jobs:
     - name: MCP end-to-end test
       timeout-minutes: 5
       run: npm run test:mcp-e2e
+
+    - name: Upload MCP end-to-end screenshots
+      if: failure()
+      uses: actions/upload-artifact@v4
+      with:
+        name: mcp-e2e-screenshots-${{ matrix.os }}
+        path: e2e/mcp/screenshots
+        if-no-files-found: ignore

e2e/mcp/run.mjs

@@ -5,8 +5,9 @@
  * 2. a player joins in Chrome
  * 3. an MCP client starts `mavonengine mcp` over stdio, like an AI assistant would, and reads the server
  *    and the player's tab: scene on both sides, renderer stats, the client's world, network, console
- *    output, a screenshot, and the player compared on server and client
- * 4. a second tab opens the editor: both tabs are listed, and `auto` still picks the player's tab
+ *    output, a screenshot, the player compared on server and client, and the packets and state sync of both sides
+ * 4. a second tab opens the editor: both tabs are listed, and `auto` still picks the player's tab.
+ *    Its Network panel lists the server's packets, and the overlay draws the player's ghost and sync ring
  *
  * Needs Chrome, core and the CLI built and the template's dependencies installed. The docs tools are left out
  * (--no-docs): they read mavonengine.com, which CI shouldn't depend on.
@@ -31,6 +32,76 @@ async function waitFor(page, fn, arg, timeout = 30000) {
   await page.waitForFunction(fn, arg, { timeout, polling: 200 })
 }
 
+/**
+ * What went wrong on a page besides thrown errors: console errors, requests that failed or were refused.
+ * A module of the editor that doesn't load shows up here and nowhere else
+ */
+function watchPage(page, name, problems) {
+  page.on('console', (message) => {
+    if (message.type() === 'error')
+      problems.push(`${name} console: ${message.text()}`)
+  })
+  page.on('requestfailed', request => problems.push(`${name} request failed: ${request.url()} (${request.failure()?.errorText})`))
+  page.on('response', (response) => {
+    if (response.status() >= 400)
+      problems.push(`${name} ${response.status()}: ${response.url()}`)
+  })
+}
+
+/** How long the editor's UI may take to load: it is built from source by the dev server, next to a game that renders in software */
+const EDITOR_UI_TIMEOUT = 120000
+
+/**
+ * The editor exists as soon as `.` is pressed, its UI only once the dev server has built it and React has drawn it.
+ * Fails with what the page reported when that doesn't happen, instead of a bare timeout
+ */
+async function waitForEditorUi(page, errors, problems) {
+  const started = Date.now()
+  const tab = page.getByRole('tab', { name: 'Network' })
+
+  while (true) {
+    if (await tab.count() > 0)
+      break
+    if (errors.length)
+      throw new Error(`the editor's UI did not load:\n  ${errors.join('\n  ')}`)
+    if (Date.now() - started > EDITOR_UI_TIMEOUT)
+      throw new Error(`the editor's UI was not there after ${EDITOR_UI_TIMEOUT / 1000}s${problems.length ? `:\n  ${problems.slice(-20).join('\n  ')}` : ', and the page reported nothing'}`)
+    await delay(500)
+  }
+
+  log(`  the editor's UI took ${((Date.now() - started) / 1000).toFixed(1)}s to load`)
+  return tab
+}
+
+/** Everything that helps to tell why a run failed, since CI can't be looked at afterwards */
+async function reportFailure(context, server, errors, problems) {
+  log('\n== failure details')
+  if (errors.length)
+    log(`page errors:\n  ${errors.join('\n  ')}`)
+  if (problems.length)
+    log(`page problems (last 30):\n  ${problems.slice(-30).join('\n  ')}`)
+
+  for (const [index, page] of (context?.pages() ?? []).entries()) {
+    try {
+      const state = await page.evaluate(() => ({
+        title: document.title,
+        editor: !!window.Game?.editor,
+        uiChildren: window.Game?.uiRoot?.childElementCount ?? null,
+        tabs: Array.from(document.querySelectorAll('[role=tab]'), tab => tab.textContent),
+        text: document.body.textContent.replace(/\s+/g, ' ').slice(0, 300),
+      }))
+      log(`page ${index}: ${JSON.stringify(state)}`)
+      await page.screenshot({ path: join(screenshots, `failure-page-${index}.png`), timeout: 15000 })
+    }
+    catch (err) {
+      log(`page ${index}: could not be looked at: ${err.message.split('\n')[0]}`)
+    }
+  }
+
+  if (server)
+    log(`server output (last 40 lines):\n${server.output().split('\n').slice(-40).join('\n')}`)
+}
+
 async function joinGame(page, name) {
   await page.goto(base)
   await page.locator('.name-input').fill(name)
@@ -42,7 +113,9 @@ async function main() {
   let server
   let browser
   let mcp
+  let context
   const errors = []
+  const problems = []
 
   rmSync(screenshots, { recursive: true, force: true })
   mkdirSync(screenshots, { recursive: true })
@@ -54,9 +127,10 @@ async function main() {
 
     log('\n== player')
     browser = await chromium.launch({ channel: 'chrome', headless: true, args: ['--use-gl=angle', '--use-angle=swiftshader', '--enable-unsafe-swiftshader'] })
-    const context = await browser.newContext({ viewport: { width: 1200, height: 800 } })
+    context = await browser.newContext({ viewport: { width: 1200, height: 800 } })
     const player = await context.newPage()
     player.on('pageerror', error => errors.push(`player: ${error.message}`))
+    watchPage(player, 'player', problems)
     await joinGame(player, 'Alice')
 
     log('\n== mcp')
@@ -72,7 +146,7 @@ async function main() {
     const data = async (name, args) => JSON.parse((await call(name, args)).content[0].text)
 
     const { tools } = await mcp.listTools()
-    check(tools.length === 18 && tools.every(tool => tool.annotations?.readOnlyHint), 'it lists 18 read-only tools')
+    check(tools.length === 24 && tools.every(tool => tool.annotations?.readOnlyHint), 'it lists 24 read-only tools')
 
     const serverPlayers = await data('list_players')
     check(serverPlayers.length === 1 && serverPlayers[0].displayName === 'Alice', 'list_players shows Alice on the server')
@@ -109,6 +183,44 @@ async function main() {
     check(compared.positionDelta.length < 1, `the client's player is where the server has it (${compared.positionDelta.length.toFixed(3)} apart)`)
     check(Math.abs(compared.server.position.z) + Math.abs(compared.server.position.x) > 0.1, 'after it moved')
 
+    log('\n== network')
+    const sent = await data('network_packets', { peer: playerId, type: 'sv_state', direction: 'out', limit: 5 })
+    const ticks = sent.records.map(record => record.tick)
+    check(sent.records.length === 5 && ticks.every((tick, i) => i === 0 || tick === ticks[i - 1] + 1), `network_packets lists the states sent to the player, one per tick (${ticks.join(', ')})`)
+    check(sent.records.every(record => record.bytes > 0 && record.info.entities >= 1), 'with their size and entity count')
+
+    const packet = await data('network_packet', { id: sent.records.at(-1).id })
+    check(packet.payload.tick === ticks.at(-1) && packet.payload.entities.some(e => e.id === playerId) && typeof packet.payload.ack === 'number', 'network_packet shows the payload: tick, ack and the player')
+
+    const moves = await data('network_packets', { peer: playerId, type: 'command', direction: 'in' })
+    check(moves.records.length > 0 && moves.records.every(record => typeof record.sequenceId === 'number'), `and the server recorded the player's inputs (${moves.records.length})`)
+    check(packet.payload.ack === moves.records.at(-1).sequenceId, `the last state acknowledges the last input (${packet.payload.ack})`)
+
+    const received = await data('client_packets', { type: 'sv_state', limit: 5 })
+    check(received.records.length === 5 && received.records.every(record => record.direction === 'in' && record.tick > 0), 'client_packets lists the states the tab received')
+    const joined = await data('client_packets', { type: 'cl_init' })
+    check(joined.records.length === 1 && joined.records[0].reliable === true, 'and the game\'s own reliable message, once')
+    const lastState = (await data('client_network')).network.lastState
+    check(lastState.tick > 0 && lastState.ack === packet.payload.ack && lastState.ageMs < 1000, `client_network tells the last state: tick ${lastState.tick}, ack ${lastState.ack}, ${lastState.ageMs}ms ago`)
+
+    const sync = await data('network_sync')
+    check(sync.syncDistance === 200 && sync.players.length === 1 && sync.players[0].tracked.includes(playerId), 'network_sync shows what the player is sent')
+    check(sync.players[0].lastState.tick <= sync.tick && sync.entities.find(e => e.id === playerId).trackedBy === 1, 'and by how many players each entity is tracked')
+
+    // The newest arrival and the newest handled input: their other halves are older, so well inside the window
+    const timeline = await data('network_timeline', { sinceMs: 10000, limit: 2000 })
+    const arrived = timeline.entries.findLast(e => e.side === 'client' && e.type === 'sv_state')
+    const left = timeline.entries.find(e => e.side === 'server' && e.type === 'sv_state' && e.tick === arrived?.tick)
+    // Two clocks a millisecond apart can swap the two on localhost, so the order is not checked
+    const travelMs = arrived && left ? new Date(arrived.time) - new Date(left.time) : Number.NaN
+    check(Math.abs(travelMs) < 1000, `network_timeline shows a state on both sides (tick ${arrived?.tick}, ${travelMs}ms apart)`)
+    const handled = timeline.entries.findLast(e => e.side === 'server' && e.type === 'command')
+    const input = timeline.entries.find(e => e.side === 'client' && e.type === 'command' && e.sequenceId === handled?.sequenceId)
+    check(input && handled, `and an input on both sides (seq ${handled?.sequenceId}, ${handled && input && new Date(handled.time) - new Date(input.time)}ms apart)`)
+    const events = await data('network_timeline', { sinceMs: 60000, eventsOnly: true })
+    check(events.entries.some(e => e.side === 'server' && e.type === 'sync_enter' && e.info.entities.includes(playerId)), 'and, events only, the player coming into its own sync range')
+    check(events.entries.some(e => e.side === 'client' && e.type === 'connect'), 'next to the tab\'s own connect')
+
     await player.evaluate(() => console.error('e2e marker', { id: 1 }))
     const errorLogs = await data('client_logs', { level: 'error', contains: 'e2e marker' })
     check(errorLogs.entries.length === 1 && errorLogs.entries[0].message === 'e2e marker {"id":1}', 'client_logs has the console error')
@@ -129,6 +241,7 @@ async function main() {
     log('\n== editor')
     const editor = await context.newPage()
     editor.on('pageerror', error => errors.push(`editor: ${error.message}`))
+    watchPage(editor, 'editor', problems)
     await editor.goto(base)
     await waitFor(editor, () => window.Game?.activeScene?.name === 'main')
     await editor.locator('canvas').click({ position: { x: 600, y: 400 }, force: true })
@@ -148,19 +261,42 @@ async function main() {
     const editorId = both.clients.find(c => c.editor).id
     check((await data('client_network', { clientId: editorId })).network.editorMode === true, 'and the editor tab by its id')
 
+    log('\n== editor network panel')
+    await (await waitForEditorUi(editor, errors, problems)).click()
+    await editor.getByText('sv_state').first().waitFor({ timeout: 10000 })
+    check(await editor.getByText('Alice').count() === 1, 'the Network panel lists the server\'s packets and the players it syncs')
+
+    await editor.getByLabel('Server ghosts').check()
+    await editor.getByLabel('Sync radius').check()
+    await waitFor(editor, () => window.Game.editor.networkOverlay.counts.ghosts > 0 && window.Game.editor.networkOverlay.counts.rings === 1, undefined, 10000)
+    const overlay = await editor.evaluate((id) => {
+      const { group, counts } = window.Game.editor.networkOverlay
+      const ghost = group.getObjectByName(`ServerGhost:${id}`)
+      const ring = group.getObjectByName(`SyncRing:${id}`)
+      return { counts, ghost: ghost && { x: ghost.position.x, z: ghost.position.z }, ringScale: ring?.scale.x }
+    }, playerId)
+    const onServer = (await data('get_entity', { id: playerId })).position
+    check(overlay.ghost && Math.hypot(overlay.ghost.x - onServer.x, overlay.ghost.z - onServer.z) < 0.5, 'the overlay draws the player\'s ghost where the server has it')
+    check(overlay.ringScale === 200, 'and a ring of the sync distance around it')
+    await editor.screenshot({ path: join(screenshots, 'editor-network.png') })
+
     await editor.close()
-    let left
+    let remaining
     for (let tries = 0; tries < 20; tries++) {
-      left = (await data('list_clients')).clients
-      if (left.length === 1)
+      remaining = (await data('list_clients')).clients
+      if (remaining.length === 1)
         break
       await delay(250)
     }
-    check(left.length === 1 && left[0].playerId === playerId, 'a closed tab leaves the list')
+    check(remaining.length === 1 && remaining[0].playerId === playerId, 'a closed tab leaves the list')
 
     check(errors.length === 0, `no page errors${errors.length ? `:\n  ${errors.join('\n  ')}` : ''}`)
     log('\nmcp end-to-end test passed')
   }
+  catch (err) {
+    await reportFailure(context, server, errors, problems).catch(() => {})
+    throw err
+  }
   finally {
     await mcp?.close().catch(() => {})
     await browser?.close()