detached 0d8c582

fix(startup): validate timing artifact consistency

commit
0d8c582e278ce6eac657fcdcad75060964a72aee
author
brice · · 2026-07-14 08:24 UTC
committer
brice · · 2026-07-14 09:35 UTC
parent
ba97260
signature
GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email
2 files · +58 -16
Split
UnifiedSplit
M internal/logging/first_presentation_collector_test.go +53 -14
@@ -10,6 +10,16 @@ import (
1010 "github.com/stretchr/testify/require"
1111 )
1212
13+const validFirstPresentationLog = `{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"}
14+{"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1}
15+{"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1}
16+{"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1}
17+{"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1}
18+{"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1}
19+{"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1}
20+{"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1}
21+{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}`
22+
1323 func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
1424 repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
1525 require.NoError(t, err)
@@ -18,20 +28,7 @@ func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
1828 require.NoError(t, os.Mkdir(runtime, 0o755))
1929
2030 binary := filepath.Join(temp, "dumber")
21- require.NoError(t, os.WriteFile(binary, []byte(`#!/bin/sh
22-cat <<'EOF'
23-{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"}
24-{"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1}
25-{"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1}
26-{"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1}
27-{"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1}
28-{"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1}
29-{"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1}
30-{"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1}
31-{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}
32-EOF
33-exit 139
34-`), 0o755))
31+ require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755))
3532
3633 output := filepath.Join(temp, "artifacts")
3734 cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
@@ -57,6 +54,48 @@ exit 139
5754 }
5855 }
5956
57+func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) {
58+ repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
59+ require.NoError(t, err)
60+
61+ for _, test := range []struct {
62+ name string
63+ old string
64+ new string
65+ }{
66+ {name: "non-integer delta", old: `"delta_ms":1}`, new: `"delta_ms":"1"}`},
67+ {name: "incorrect delta", old: `"delta_ms":1}`, new: `"delta_ms":2}`},
68+ {name: "non-integer summary total", old: `"total_ms":7`, new: `"total_ms":7.5`},
69+ {name: "incorrect summary total", old: `"total_ms":7`, new: `"total_ms":8`},
70+ } {
71+ t.Run(test.name, func(t *testing.T) {
72+ temp := t.TempDir()
73+ runtime := filepath.Join(temp, "cef-147-runtime")
74+ require.NoError(t, os.Mkdir(runtime, 0o755))
75+ binary := filepath.Join(temp, "dumber")
76+ log := strings.Replace(validFirstPresentationLog, test.old, test.new, 1)
77+ require.NoError(t, os.WriteFile(binary, collectorTestBinary(log), 0o755))
78+
79+ cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
80+ cmd.Dir = repoRoot
81+ cmd.Env = append(os.Environ(),
82+ "DISPLAY=:test",
83+ "DUMBER_CEF_DIR="+runtime,
84+ "DUMBER_FIRST_PRESENTATION_BIN="+binary,
85+ "DUMBER_FIRST_PRESENTATION_OUTPUT="+filepath.Join(temp, "artifacts"),
86+ "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1",
87+ )
88+ result, err := cmd.CombinedOutput()
89+ require.Errorf(t, err, "collector accepted malformed timing artifact: %s", result)
90+ require.Contains(t, string(result), "invalid or incomplete non-DMABUF timeline")
91+ })
92+ }
93+}
94+
95+func collectorTestBinary(log string) []byte {
96+ return []byte("#!/bin/sh\ncat <<'EOF'\n" + log + "\nEOF\nexit 139\n")
97+}
98+
6099 func runArtifactNames() []string {
61100 return []string{"run-01.json", "run-02.json", "run-03.json", "run-04.json", "run-05.json"}
62101 }
@@ -10,6 +10,16 @@ import (
10 "github.com/stretchr/testify/require"10 "github.com/stretchr/testify/require"
11 )11 )
12 12
13+const validFirstPresentationLog = `{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"}
14+{"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1}
15+{"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1}
16+{"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1}
17+{"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1}
18+{"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1}
19+{"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1}
20+{"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1}
21+{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}`
22+
13 func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {23 func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
14 repoRoot, err := filepath.Abs(filepath.Join("..", ".."))24 repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
15 require.NoError(t, err)25 require.NoError(t, err)
@@ -18,20 +28,7 @@ func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
18 require.NoError(t, os.Mkdir(runtime, 0o755))28 require.NoError(t, os.Mkdir(runtime, 0o755))
19 29
20 binary := filepath.Join(temp, "dumber")30 binary := filepath.Join(temp, "dumber")
21- require.NoError(t, os.WriteFile(binary, []byte(`#!/bin/sh31+ require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755))
22-cat <<'EOF'
23-{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"}
24-{"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1}
25-{"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1}
26-{"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1}
27-{"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1}
28-{"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1}
29-{"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1}
30-{"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1}
31-{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}
32-EOF
33-exit 139
34-`), 0o755))
35 32
36 output := filepath.Join(temp, "artifacts")33 output := filepath.Join(temp, "artifacts")
37 cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))34 cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
@@ -57,6 +54,48 @@ exit 139
57 }54 }
58 }55 }
59 56
57+func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) {
58+ repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
59+ require.NoError(t, err)
60+
61+ for _, test := range []struct {
62+ name string
63+ old string
64+ new string
65+ }{
66+ {name: "non-integer delta", old: `"delta_ms":1}`, new: `"delta_ms":"1"}`},
67+ {name: "incorrect delta", old: `"delta_ms":1}`, new: `"delta_ms":2}`},
68+ {name: "non-integer summary total", old: `"total_ms":7`, new: `"total_ms":7.5`},
69+ {name: "incorrect summary total", old: `"total_ms":7`, new: `"total_ms":8`},
70+ } {
71+ t.Run(test.name, func(t *testing.T) {
72+ temp := t.TempDir()
73+ runtime := filepath.Join(temp, "cef-147-runtime")
74+ require.NoError(t, os.Mkdir(runtime, 0o755))
75+ binary := filepath.Join(temp, "dumber")
76+ log := strings.Replace(validFirstPresentationLog, test.old, test.new, 1)
77+ require.NoError(t, os.WriteFile(binary, collectorTestBinary(log), 0o755))
78+
79+ cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
80+ cmd.Dir = repoRoot
81+ cmd.Env = append(os.Environ(),
82+ "DISPLAY=:test",
83+ "DUMBER_CEF_DIR="+runtime,
84+ "DUMBER_FIRST_PRESENTATION_BIN="+binary,
85+ "DUMBER_FIRST_PRESENTATION_OUTPUT="+filepath.Join(temp, "artifacts"),
86+ "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1",
87+ )
88+ result, err := cmd.CombinedOutput()
89+ require.Errorf(t, err, "collector accepted malformed timing artifact: %s", result)
90+ require.Contains(t, string(result), "invalid or incomplete non-DMABUF timeline")
91+ })
92+ }
93+}
94+
95+func collectorTestBinary(log string) []byte {
96+ return []byte("#!/bin/sh\ncat <<'EOF'\n" + log + "\nEOF\nexit 139\n")
97+}
98+
60 func runArtifactNames() []string {99 func runArtifactNames() []string {
61 return []string{"run-01.json", "run-02.json", "run-03.json", "run-04.json", "run-05.json"}100 return []string{"run-01.json", "run-02.json", "run-03.json", "run-04.json", "run-05.json"}
62 }101 }
M scripts/collect_first_presentation.sh +5 -2
@@ -60,7 +60,6 @@ EOF
6060 DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \
6161 PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \
6262 timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1
63- exit_code=$?
6463 set -e
6564 # A completed, valid first-presentation summary is the observation success
6665 # signal. The GUI may later be stopped by timeout or terminate independently.
@@ -78,8 +77,12 @@ for line in open(log, errors="replace"):
7877 summary = {key: event.get(key) for key in ("backend", "incomplete_reason", "total_ms")}
7978 names = [event.get("milestone") for event in records]
8079 times = [event.get("t_ms") for event in records]
81-valid = names == order and all(isinstance(t, int) for t in times) and times == sorted(times)
80+deltas = [event.get("delta_ms") for event in records]
81+valid = names == order and all(type(t) is int for t in times) and times == sorted(times)
82+valid = valid and all(type(delta) is int for delta in deltas)
83+valid = valid and all(delta == current - previous for previous, current, delta in zip([0] + times, times, deltas))
8284 valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason")
85+valid = valid and type(summary.get("total_ms")) is int and summary["total_ms"] == times[-1]
8386 result = {"run": run, "valid": valid, "milestones": records, "summary": summary}
8487 json.dump(result, open(destination, "w"), indent=2)
8588 if not valid:
@@ -60,7 +60,6 @@ EOF
60 DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \60 DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \
61 PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \61 PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \
62 timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&162 timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1
63- exit_code=$?
64 set -e63 set -e
65 # A completed, valid first-presentation summary is the observation success64 # A completed, valid first-presentation summary is the observation success
66 # signal. The GUI may later be stopped by timeout or terminate independently.65 # signal. The GUI may later be stopped by timeout or terminate independently.
@@ -78,8 +77,12 @@ for line in open(log, errors="replace"):
78 summary = {key: event.get(key) for key in ("backend", "incomplete_reason", "total_ms")}77 summary = {key: event.get(key) for key in ("backend", "incomplete_reason", "total_ms")}
79 names = [event.get("milestone") for event in records]78 names = [event.get("milestone") for event in records]
80 times = [event.get("t_ms") for event in records]79 times = [event.get("t_ms") for event in records]
81-valid = names == order and all(isinstance(t, int) for t in times) and times == sorted(times)80+deltas = [event.get("delta_ms") for event in records]
81+valid = names == order and all(type(t) is int for t in times) and times == sorted(times)
82+valid = valid and all(type(delta) is int for delta in deltas)
83+valid = valid and all(delta == current - previous for previous, current, delta in zip([0] + times, times, deltas))
82 valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason")84 valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason")
85+valid = valid and type(summary.get("total_ms")) is int and summary["total_ms"] == times[-1]
83 result = {"run": run, "valid": valid, "milestones": records, "summary": summary}86 result = {"run": run, "valid": valid, "milestones": records, "summary": summary}
84 json.dump(result, open(destination, "w"), indent=2)87 json.dump(result, open(destination, "w"), indent=2)
85 if not valid:88 if not valid:

Keyboard shortcuts

Single-key shortcuts are on. ctrl k and esc work whatever this says.

ctrl k :
go to a section, branch, tag, file or repository
?
this list
j k
move the row cursor down / up
enter
open the row under the cursor; on Files, a directory opens or closes in place
↑ ↓ ← → home end
in the file tree (focus on a row): previous / next row, close / open a directory or go to its parent / first entry, first / last row. They never open a file
l h
on Files: open a directory or a file / close a directory or go up to its parent, then to the parent page. Elsewhere: into the side panel (on a merge request, its files) / back to the content; there j k move between its controls
g g G
first / last row
/
filter the list; on Files, find a file anywhere in the repository (esc clears, enter opens the best match)
b
switch branch or tag
g s g f g c g b g m g i g r g a
tabs: summary, files, commits, branches & tags, merge requests, issues, releases, actions (when available)
g h
home
w
wide mode: use the whole width of the screen, or not (remembered)
y
copy a permalink pinned to the commit
d u x
diff: split / unified / collapse or expand all
e E
diff: the whole file in view / every file, with the lines the hunks hide
n
merge request: next note in the diff
esc
close a dialog, leave a field

Branches 8

Tags 42

↑↓ moveenter openesc close