diff --git a/.github/workflows/server-test.yaml b/.github/workflows/server-test.yaml index b3bc43e60..0d6f52936 100644 --- a/.github/workflows/server-test.yaml +++ b/.github/workflows/server-test.yaml @@ -51,6 +51,9 @@ jobs: git diff --exit-code -- lib/events/category_gen.go working-directory: server + - name: Install recording regression dependencies + run: sudo apt-get update && sudo apt-get install -y ffmpeg + - name: Run server unit tests run: make test-unit working-directory: server @@ -133,3 +136,13 @@ jobs: env: E2E_CHROMIUM_HEADFUL_IMAGE: onkernel/chromium-headful:${{ steps.vars.outputs.short_sha }} E2E_CHROMIUM_HEADLESS_IMAGE: onkernel/chromium-headless:${{ steps.vars.outputs.short_sha }} + RECORDING_AUDIO_OUTPUT_PATH: ${{ runner.temp }}/replay-audio/recording.mp4 + + - name: Upload replay audio diagnostics + if: always() + uses: actions/upload-artifact@v4 + with: + name: replay-audio-${{ github.run_id }}-${{ github.run_attempt }} + path: ${{ runner.temp }}/replay-audio/ + retention-days: 14 + if-no-files-found: warn diff --git a/server/Makefile b/server/Makefile index 5934802e0..090559bb5 100644 --- a/server/Makefile +++ b/server/Makefile @@ -46,7 +46,7 @@ test-e2e: @echo "" @echo "=== Running e2e tests (this may take a few minutes) ===" @echo "" - go test -v -race -timeout 120m ./e2e/ + go test -v -race -count=1 -timeout 120m ./e2e/ clean: @rm -rf $(BIN_DIR) diff --git a/server/e2e/e2e_recording_audio_test.go b/server/e2e/e2e_recording_audio_test.go index 35ea9e793..ad76633f5 100644 --- a/server/e2e/e2e_recording_audio_test.go +++ b/server/e2e/e2e_recording_audio_test.go @@ -41,6 +41,14 @@ func TestReplayRecordingIncludesAudioTrack(t *testing.T) { require.NoError(t, c.WaitReady(ctx), "api not ready") require.NoError(t, c.WaitDevTools(ctx), "devtools not ready") + // WIDTH/HEIGHT configure Xvfb, not headful Xorg. Apply the intended size + // through the API instead of recording the dummy display's 4K default. + initialWidth, initialHeight, err := getXRootResolution(ctx, c) + require.NoError(t, err) + t.Logf("[replay-audio] initial display=%dx%d", initialWidth, initialHeight) + patchDisplayExpectingOK(t, ctx, c, 1280, 720, 60) + waitForXRootResolution(t, ctx, c, 1280, 720, 15*time.Second) + // Verify the browser sees a real sound card over pure CDP/websocket. Chromium // excludes PulseAudio monitor sources from enumerateDevices(), so the // recorder's capture sink alone is invisible as an input. The standalone @@ -151,6 +159,10 @@ func TestReplayRecordingZombocomArchiveAudio(t *testing.T) { func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, playwrightCode string, outputPath string, minPeakLevel float64) { t.Helper() + if outputPath != "" { + defer captureReplayAudioDiagnostics(t, c, outputPath) + } + client, err := c.APIClient() require.NoError(t, err, "failed to create API client") @@ -160,6 +172,7 @@ func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, play maxDuration := 120 maxFileSize := 100 recordAudio := true + startTime := time.Now() startResp, err := client.StartRecordingWithResponse(ctx, instanceoapi.StartRecordingJSONRequestBody{ MaxDurationInSeconds: &maxDuration, MaxFileSizeInMB: &maxFileSize, @@ -168,6 +181,7 @@ func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, play require.NoError(t, err, "POST /recording/start failed") require.Equal(t, http.StatusCreated, startResp.StatusCode(), "unexpected start status: %s body=%s", startResp.Status(), string(startResp.Body)) + t.Logf("[replay-audio] recording start took %s", time.Since(startTime)) stopped := false defer func() { if !stopped { @@ -176,9 +190,11 @@ func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, play } }() + playwrightStart := time.Now() runResp, err := client.ExecutePlaywrightCodeWithResponse(ctx, instanceoapi.ExecutePlaywrightCodeJSONRequestBody{ Code: playwrightCode, }) + t.Logf("[replay-audio] playwright took %s", time.Since(playwrightStart)) require.NoError(t, err, "playwright request failed") require.Equal(t, http.StatusOK, runResp.StatusCode(), "unexpected playwright status: %s body=%s", runResp.Status(), string(runResp.Body)) require.NotNil(t, runResp.JSON200, "expected playwright JSON response") @@ -186,7 +202,9 @@ func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, play t.Fatalf("playwright execution failed: error=%s stderr=%s result=%#v", stringValue(runResp.JSON200.Error), stringValue(runResp.JSON200.Stderr), runResp.JSON200.Result) } + stopTime := time.Now() stopResp, err := client.StopRecordingWithResponse(ctx, instanceoapi.StopRecordingJSONRequestBody{}) + t.Logf("[replay-audio] recording stop took %s; elapsed %s", time.Since(stopTime), time.Since(startTime)) stopped = true require.NoError(t, err, "POST /recording/stop failed") require.Equal(t, http.StatusOK, stopResp.StatusCode(), "unexpected stop status: %s body=%s", stopResp.Status(), string(stopResp.Body)) @@ -205,6 +223,7 @@ func recordReplayAudio(t *testing.T, ctx context.Context, c *TestContainer, play require.True(t, mp4HasAudioTrack(downloadResp.Body), "downloaded recording does not contain an audio track") require.Greater(t, mp4AudioPeakLevel(t, ctx, c, recordingPath), minPeakLevel, "downloaded recording audio track is silent") formatDuration, audioDuration := mp4Durations(t, ctx, c, recordingPath) + t.Logf("[replay-audio] format_duration=%.6f audio_duration=%.6f gap=%.6f", formatDuration, audioDuration, formatDuration-audioDuration) require.GreaterOrEqual(t, audioDuration, formatDuration-2, "downloaded recording audio track ends before the recording does") } diff --git a/server/e2e/recording_audio_diagnostics_test.go b/server/e2e/recording_audio_diagnostics_test.go new file mode 100644 index 000000000..e7ddc78a4 --- /dev/null +++ b/server/e2e/recording_audio_diagnostics_test.go @@ -0,0 +1,48 @@ +package e2e + +import ( + "context" + "net/http" + "os" + "path/filepath" + "testing" + "time" +) + +// Capture only the isolated audio fixture's services, never environment variables +// or browser storage. Run before the test container is removed, including on failure. +func captureReplayAudioDiagnostics(t *testing.T, c *TestContainer, outputPath string) { + t.Helper() + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) + defer cancel() + if err := os.MkdirAll(filepath.Dir(outputPath), 0o755); err != nil { + t.Logf("audio diagnostics: %v", err) + return + } + // A failed Playwright request still leaves a useful recording after cleanup. + if _, err := os.Stat(outputPath); os.IsNotExist(err) { + client, err := c.APIClient() + if err == nil { + response, err := client.DownloadRecordingWithResponse(ctx, nil) + if err == nil && response.StatusCode() == http.StatusOK { + if err := os.WriteFile(outputPath, response.Body, 0o644); err != nil { + t.Logf("audio diagnostics recording: %v", err) + } + } + } + } + commands := map[string][]string{ + "probe.json": {"ffprobe", "-v", "error", "-show_format", "-show_streams", "-show_packets", "-of", "json", "/recordings/default.mp4"}, + "services.log": {"sh", "-c", "for f in /var/log/supervisord/kernel-images-api /var/log/supervisord/pulseaudio /var/log/supervisord.log; do echo ==== $f; cat $f; done"}, + "pulse.log": {"sh", "-c", "PULSE_SERVER=unix:/tmp/pulse/native pactl list sinks; PULSE_SERVER=unix:/tmp/pulse/native pactl list source-outputs"}, + } + for suffix, command := range commands { + code, out, err := c.Exec(ctx, command) + if err != nil || code != 0 { + t.Logf("audio diagnostics %s: exit=%d err=%v", suffix, code, err) + } + if err := os.WriteFile(outputPath+"."+suffix, []byte(out), 0o644); err != nil { + t.Logf("audio diagnostics: %v", err) + } + } +} diff --git a/server/lib/recorder/audio_integration_test.go b/server/lib/recorder/audio_integration_test.go new file mode 100644 index 000000000..2b42b6a2a --- /dev/null +++ b/server/lib/recorder/audio_integration_test.go @@ -0,0 +1,102 @@ +package recorder + +import ( + "encoding/json" + "os/exec" + "path/filepath" + "runtime" + "strconv" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestFFmpegAudioPreservesInputStartOffset(t *testing.T) { + if runtime.GOOS != "linux" { + t.Skip("separate PulseAudio input is Linux-only") + } + for _, binary := range []string{"ffmpeg", "ffprobe"} { + if _, err := exec.LookPath(binary); err != nil { + t.Skipf("%s required: %v", binary, err) + } + } + dir := t.TempDir() + path := filepath.Join(dir, "audio.mp4") + params := defaultParams(dir) + audio := true + params.RecordAudio = &audio + args, err := ffmpegArgs(params, path) + require.NoError(t, err) + + // Model live devices opened three seconds apart on the same clock. Both + // finish at timestamp 16, so their final output packets must still coincide. + // Replace only capture devices; retain the production sync/encode/mux flags. + fixtureArgs := make([]string, 0, len(args)) + for i := 0; i < len(args); i++ { + switch { + case args[i] == "-framerate": + i++ + case args[i] == "-f" && (args[i+1] == "x11grab" || args[i+1] == "pulse"): + fixtureArgs = append(fixtureArgs, "-f", "lavfi") + i++ + case args[i] == "-i": + input := "testsrc2=size=320x240:rate=10:duration=6,setpts=PTS+10/TB" + if args[i+1] == "KernelOutput.monitor" { + input = "sine=frequency=440:sample_rate=48000:duration=3,asetpts=PTS+13/TB" + } + fixtureArgs = append(fixtureArgs, "-i", input) + i++ + default: + fixtureArgs = append(fixtureArgs, args[i]) + } + } + out, err := exec.CommandContext(t.Context(), "ffmpeg", fixtureArgs...).CombinedOutput() + require.NoError(t, err, "%s", out) + for _, name := range []string{"fragmented", "finalized"} { + t.Run(name, func(t *testing.T) { + if name == "finalized" { + finalized := filepath.Join(dir, "finalized.mp4") + out, err := exec.CommandContext(t.Context(), "ffmpeg", remuxArgs(path, finalized, "")...).CombinedOutput() + require.NoError(t, err, "%s", out) + path = finalized + } + out, err := exec.CommandContext(t.Context(), "ffprobe", "-v", "error", "-show_packets", "-of", "json", path).Output() + require.NoError(t, err) + var probe struct { + Packets []struct { + CodecType string `json:"codec_type"` + PTS string `json:"pts_time"` + Duration string `json:"duration_time"` + } `json:"packets"` + } + require.NoError(t, json.Unmarshal(out, &probe)) + var videoEnd, audioEnd float64 + audioPTS := make([]float64, 0) + for _, p := range probe.Packets { + pts, err := strconv.ParseFloat(p.PTS, 64) + require.NoError(t, err) + var duration float64 + if p.Duration != "" { + duration, err = strconv.ParseFloat(p.Duration, 64) + require.NoError(t, err) + } + if p.CodecType == "video" { + videoEnd = pts + duration + } else if p.CodecType == "audio" { + audioEnd = pts + duration + audioPTS = append(audioPTS, pts) + } + } + t.Logf("video_end=%.6f audio_end=%.6f", videoEnd, audioEnd) + require.InDelta(t, videoEnd, audioEnd, 0.1, "independently zeroing input timestamps moves audio three seconds early") + // empty_moov starts the first packet at zero. Subsequent packets must + // preserve the device offset, without padding the gap with silent samples. + require.Greater(t, len(audioPTS), 1) + require.InDelta(t, 3, audioPTS[1], 0.03) + pcm, err := exec.CommandContext(t.Context(), "ffmpeg", "-v", "error", "-i", path, + "-map", "0:a:0", "-f", "s16le", "-ac", "2", "-ar", "48000", "-").Output() + require.NoError(t, err) + require.InDelta(t, 3, float64(len(pcm))/(48000*2*2), 0.05, "sync must not add silent samples") + }) + } +} diff --git a/server/lib/recorder/ffmpeg.go b/server/lib/recorder/ffmpeg.go index f7961e9da..34b84358a 100644 --- a/server/lib/recorder/ffmpeg.go +++ b/server/lib/recorder/ffmpeg.go @@ -748,10 +748,8 @@ func ffmpegArgs(params FFmpegRecordingParams, outputPath string) ([]string, erro "-pix_fmt", "yuv420p", // Web-standard pixel format }...) - // Timestamp handling for reliable playback. Single-input video-only capture - // overwrites x11grab's timestamps with wall-clock time for stable playback. - // With audio we must not: it would stamp the separate video and audio inputs - // independently and desync them, so we keep their input PTS instead. + // Keep the legacy timestamp options for video-only capture. Audio capture + // synchronizes the two device clocks with -isync on the PulseAudio input. if !recordAudio { args = append(args, "-use_wallclock_as_timestamps", "1") } @@ -783,6 +781,10 @@ func ffmpegArgs(params FFmpegRecordingParams, outputPath string) ([]string, erro func audioInputArgs(params FFmpegRecordingParams) []string { return []string{ "-thread_queue_size", "512", + // Both devices use wall-clock timestamps, but open at different times. + // Without -isync, ffmpeg subtracts each input's start independently, + // shifting the later-opened audio earlier by the device startup gap. + "-isync", "0", "-f", "pulse", "-i", params.audioSource(), } diff --git a/server/runtime/playwright-daemon.test.ts b/server/runtime/playwright-daemon.test.ts new file mode 100644 index 000000000..1b5f1dec4 --- /dev/null +++ b/server/runtime/playwright-daemon.test.ts @@ -0,0 +1,71 @@ +import assert from 'node:assert/strict'; +import { spawn } from 'node:child_process'; +import { once } from 'node:events'; +import { existsSync } from 'node:fs'; +import { mkdtemp, rm, writeFile } from 'node:fs/promises'; +import { createConnection } from 'node:net'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { setTimeout } from 'node:timers/promises'; +import { pathToFileURL } from 'node:url'; +import test from 'node:test'; + +test('socket readiness does not wait for cold browser-engine imports', { timeout: 10000 }, async t => { + const dir = await mkdtemp(join(tmpdir(), 'playwright-startup-')); + const socketPath = join(dir, 'daemon.sock'); + const started = join(dir, 'import-started'); + const release = join(dir, 'release-import'); + const loader = join(dir, 'loader.mjs'); + // Hold package evaluation until released, rather than depending on CPU load + // or the speed of installed Playwright packages to reproduce cold startup. + const engine = ` + import { existsSync, writeFileSync } from 'node:fs'; + import { setTimeout } from 'node:timers/promises'; + writeFileSync(${JSON.stringify(started)}, ''); + while (!existsSync(${JSON.stringify(release)})) await setTimeout(20); + export const chromium = { connectOverCDP: async () => ({ + on() {}, isConnected() { return true; }, async close() {} + }) }; + export const transform = async code => ({ code }); + export const Browser = null, CDPSession = null, Page = null; + `; + await writeFile(loader, ` + export async function resolve(specifier, context, nextResolve) { + if (['playwright-core', 'patchright', 'esbuild'].includes(specifier)) { + return { url: 'data:text/javascript,' + encodeURIComponent(${JSON.stringify(engine)}), shortCircuit: true }; + } + if (['./page-target-id-cache', './webmcp'].includes(specifier)) specifier += '.ts'; + return nextResolve(specifier, context); + } + `); + const child = spawn(process.execPath, [ + '--experimental-loader', pathToFileURL(loader).href, + new URL('./playwright-daemon.ts', import.meta.url).pathname, + ], { env: { ...process.env, PLAYWRIGHT_DAEMON_SOCKET: socketPath }, stdio: ['ignore', 'ignore', 'pipe'] }); + let stderr = ''; + child.stderr.on('data', chunk => { stderr += chunk; }); + const exited = once(child, 'exit'); + t.after(async () => { + child.kill('SIGKILL'); + await exited; + await rm(dir, { recursive: true, force: true }); + }); + const deadline = performance.now() + 4000; + while ((!existsSync(started) || !existsSync(socketPath)) && performance.now() < deadline && child.exitCode === null) { + await setTimeout(20); + } + assert.ok(existsSync(started), `engine import was not exercised: ${stderr}`); + assert.ok(existsSync(socketPath), `socket blocked by engine initialization: ${stderr}`); + const socket = createConnection(socketPath); + try { + await once(socket, 'connect'); + } finally { + socket.destroy(); + } + await writeFile(release, ''); + const connectedDeadline = performance.now() + 2000; + while (!stderr.includes('CDP connection established') && performance.now() < connectedDeadline) { + await setTimeout(20); + } + assert.match(stderr, /CDP connection established/); +}); diff --git a/server/runtime/playwright-daemon.ts b/server/runtime/playwright-daemon.ts index b46d28e7c..9dfca8436 100644 --- a/server/runtime/playwright-daemon.ts +++ b/server/runtime/playwright-daemon.ts @@ -11,9 +11,7 @@ import { createServer, Socket } from 'net'; import { unlinkSync, existsSync } from 'fs'; -import { transform } from 'esbuild'; -import { chromium as chromiumPW, Browser, CDPSession, Page } from 'playwright-core'; -import { chromium as chromiumPR } from 'patchright'; +import type { Browser, CDPSession, Page } from 'playwright-core'; import { PageTargetIdCache } from './page-target-id-cache'; import { createWebMCPClient } from './webmcp'; @@ -71,6 +69,7 @@ async function transformCode(code: string): Promise { // Wrap in async function so top-level await/return are valid for esbuild const wrapped = `async function __userCode__() {\n${code}\n}`; + const { transform } = await import('esbuild'); const result = await transform(wrapped, { loader: 'ts', target: 'es2022', @@ -117,7 +116,11 @@ async function ensureBrowserConnection(): Promise { connecting = true; try { - const chromium = USE_PATCHRIGHT ? chromiumPR : chromiumPW; + // Load the engine after socket binding, outside the API's short + // socket-ready deadline. Only initialize the selected engine. + const { chromium } = USE_PATCHRIGHT + ? await import('patchright') + : await import('playwright-core'); if (browser) { try {