docs/plans/2026-09-23-build-log-follow.md
1100 lines · 35246 bytes
1# build log --follow Implementation Plan
2
3> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking.
4
5**Goal:** `build log <owner/name> <n> --follow` streams a build's log until the build has an outcome, and the web build page streams the same command without JavaScript.
6
7**Architecture:** The store wakes waiters when a build's row changes and reads the log from a byte offset. The control command loops read → write → wait. The web handler renders `build.html` with a marker where the log goes, writes the part before it, dispatches the command with a writer that HTML-escapes and flushes, then writes the rest.
8
9**Tech Stack:** Go, SQLite (modernc), `golang.org/x/crypto/ssh`, `html/template`, `net/http`.
10
11**Spec:** `docs/specs/2026-09-23-build-log-follow-design.md`
12
13## Global Constraints
14
15- Work in `/Users/cmc/git/krz/gitbay-follow` (branch `build-log-follow`). Never touch `/Users/cmc/git/krz/gitbay`.
16- Every commit is signed (the repo signs by config; do not pass `--no-gpg-sign`). Messages reference `Ref #250`; the last commit says `Closes #250`. No attribution lines of any kind.
17- Write files with the editor tool, not heredocs.
18- Locally run: `go build ./...`, `go vet` on touched packages, unit tests of touched packages, and only the one e2e test being written. CI runs the rest.
19- Comments: plain, factual, match the surrounding density. No before/after narration.
20- Follow cap: 8 per account. Fallback re-read: 2 seconds. Settle after an outcome: 1 second.
21- The outcome line on stderr is exactly `build <n> <status>`; exit 0 whatever the outcome.
22- The web outcome line is exactly `<p class="notice" role="status">build finished: <status></p>`.
23
24---
25
26### Task 1: Store — wake followers and read from an offset
27
28**Files:**
29- Modify: `internal/store/store.go` (the `Store` struct, ~line 22)
30- Modify: `internal/store/builds.go` (`AppendBuildLog` ~228, `FinishBuild` ~248, `CancelBuild` ~393; new functions after `BuildLog` ~325)
31- Test: `internal/store/builds_test.go`
32
33**Interfaces:**
34- Produces: `func (s *Store) BuildLogWait(id int64) <-chan struct{}`; `func (s *Store) BuildLogFrom(id, offset int64) (status string, chunk []byte, err error)`; unexported `func (s *Store) wakeBuild(id int64)`.
35
36- [ ] **Step 1: Write the failing tests** — append to `internal/store/builds_test.go`:
37
38```go
39// A follower's channel closes on each kind of change to its build, and
40// only its build.
41func TestBuildLogWaitWakes(t *testing.T) {
42 s := open(t)
43 if err := s.MigrateUp(); err != nil {
44 t.Fatal(err)
45 }
46 uid, err := s.CreateUser("cmc", true)
47 if err != nil {
48 t.Fatal(err)
49 }
50 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
51 t.Fatal(err)
52 }
53 newBuild := func() int64 {
54 t.Helper()
55 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
56 if err != nil {
57 t.Fatal(err)
58 }
59 return id
60 }
61 closed := func(ch <-chan struct{}) bool {
62 select {
63 case <-ch:
64 return true
65 default:
66 return false
67 }
68 }
69
70 a, b := newBuild(), newBuild()
71 wa, wb := s.BuildLogWait(a), s.BuildLogWait(b)
72 if err := s.AppendBuildLog(a, []byte("x")); err != nil {
73 t.Fatal(err)
74 }
75 if !closed(wa) {
76 t.Error("append did not wake its build")
77 }
78 if closed(wb) {
79 t.Error("append woke another build")
80 }
81
82 mustClaim(t, s, 1) // claims a, the oldest
83 wa = s.BuildLogWait(a)
84 if err := s.FinishBuild(a, "success"); err != nil {
85 t.Fatal(err)
86 }
87 if !closed(wa) {
88 t.Error("finish did not wake")
89 }
90
91 if err := s.CancelBuild(b); err != nil {
92 t.Fatal(err)
93 }
94 if !closed(wb) {
95 t.Error("cancel did not wake")
96 }
97}
98
99// Offsets are bytes, not characters: || stores the log as text, and a
100// multibyte character must not shift where the next read starts.
101func TestBuildLogFrom(t *testing.T) {
102 s := open(t)
103 if err := s.MigrateUp(); err != nil {
104 t.Fatal(err)
105 }
106 uid, err := s.CreateUser("cmc", true)
107 if err != nil {
108 t.Fatal(err)
109 }
110 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
111 t.Fatal(err)
112 }
113 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
114 if err != nil {
115 t.Fatal(err)
116 }
117 first := "héllo — ok\n"
118 for _, c := range []string{first, "wörld\n"} {
119 if err := s.AppendBuildLog(id, []byte(c)); err != nil {
120 t.Fatal(err)
121 }
122 }
123 status, all, err := s.BuildLogFrom(id, 0)
124 if err != nil || status != "pending" || string(all) != first+"wörld\n" {
125 t.Fatalf("from 0: %q %q %v", status, all, err)
126 }
127 _, rest, err := s.BuildLogFrom(id, int64(len(first)))
128 if err != nil || string(rest) != "wörld\n" {
129 t.Fatalf("from %d: %q %v", len(first), rest, err)
130 }
131 _, none, err := s.BuildLogFrom(id, int64(len(all)))
132 if err != nil || len(none) != 0 {
133 t.Fatalf("from the end: %q %v", none, err)
134 }
135 if _, _, err := s.BuildLogFrom(9999, 0); err != ErrNotFound {
136 t.Fatalf("missing build: %v", err)
137 }
138}
139```
140
141- [ ] **Step 2: Run to see them fail**
142
143Run: `go test ./internal/store/ -run 'TestBuildLogWaitWakes|TestBuildLogFrom' -count=1`
144Expected: build failure, `s.BuildLogWait undefined`.
145
146- [ ] **Step 3: Implement**
147
148In `internal/store/store.go`, add `"sync"` to the imports and the fields:
149
150```go
151type Store struct {
152 DB *sql.DB
153
154 // logWait holds one channel per build someone is following, closed
155 // by the next change to that build's row (BuildLogWait).
156 logMu sync.Mutex
157 logWait map[int64]chan struct{}
158}
159```
160
161In `internal/store/builds.go`, after `BuildLog`:
162
163```go
164// BuildLogWait returns a channel closed by the next append to, finish of
165// or cancel of the build. Take it before reading, so a change between the
166// read and the wait still wakes the reader. Only this process's writes
167// wake it.
168func (s *Store) BuildLogWait(id int64) <-chan struct{} {
169 s.logMu.Lock()
170 defer s.logMu.Unlock()
171 if s.logWait == nil {
172 s.logWait = map[int64]chan struct{}{}
173 }
174 ch, ok := s.logWait[id]
175 if !ok {
176 ch = make(chan struct{})
177 s.logWait[id] = ch
178 }
179 return ch
180}
181
182func (s *Store) wakeBuild(id int64) {
183 s.logMu.Lock()
184 defer s.logMu.Unlock()
185 if ch, ok := s.logWait[id]; ok {
186 close(ch)
187 delete(s.logWait, id)
188 }
189}
190
191// BuildLogFrom returns the build's status and its log past offset bytes,
192// read together so a terminal status comes with every byte before it.
193// The cast matters: || stores the log as text, and substr on text counts
194// characters.
195func (s *Store) BuildLogFrom(id, offset int64) (string, []byte, error) {
196 var status string
197 var chunk []byte
198 err := s.DB.QueryRow(`SELECT status, substr(CAST(log AS BLOB), ?) FROM builds WHERE id = ?`,
199 offset+1, id).Scan(&status, &chunk)
200 if errors.Is(err, sql.ErrNoRows) {
201 return "", nil, ErrNotFound
202 }
203 return status, chunk, err
204}
205```
206
207Wake after each successful write. In `AppendBuildLog`, replace the tail so both paths wake:
208
209```go
210 if n, _ := res.RowsAffected(); n > 0 {
211 s.wakeBuild(id)
212 return nil
213 }
214 // Over the cap. The bounds match exactly once: appending the notice puts
215 // the log past the upper bound, so later chunks fall through silently.
216 _, err = s.DB.Exec(`
217 UPDATE builds SET log = log || ?
218 WHERE id = ? AND length(log) >= ? AND length(log) < ?`,
219 truncNotice, id, MaxBuildLog, MaxBuildLog+len(truncNotice))
220 if err == nil {
221 s.wakeBuild(id)
222 }
223 return err
224```
225
226In `FinishBuild`, before the final `return nil`: `s.wakeBuild(id)`. In `CancelBuild`, the same, before its final `return nil`.
227
228- [ ] **Step 4: Run the tests and vet**
229
230Run: `go test ./internal/store/ -count=1 && go vet ./internal/store/`
231Expected: `ok`, vet silent (no copylocks: `Store` is only ever `&Store{...}` in `Open`).
232
233- [ ] **Step 5: Commit**
234
235```bash
236git add internal/store/store.go internal/store/builds.go internal/store/builds_test.go
237git commit -m "store: wake build log followers, read the log from an offset
238
239Ref #250"
240```
241
242---
243
244### Task 2: Control — `build log --follow`
245
246**Files:**
247- Modify: `internal/control/control.go` (`Ctx`, ~line 21)
248- Modify: `internal/control/build.go` (registration ~29, `runBuildLog` ~198)
249- Create: `internal/control/buildfollow.go`
250- Create: `internal/control/buildfollow_test.go`
251- Modify: `cmd/gitbay/main.go:51` (help string)
252
253**Interfaces:**
254- Consumes: `Store.BuildLogWait`, `Store.BuildLogFrom` (Task 1).
255- Produces: `Ctx.Done <-chan struct{}`; the command `build log <owner/name> <n> [--follow]`; package vars `followSettle`, `followPoll` (tests shorten them); `maxFollows = 8`.
256
257- [ ] **Step 1: Write the failing tests** — `internal/control/buildfollow_test.go`:
258
259```go
260package control
261
262import (
263 "bytes"
264 "strings"
265 "testing"
266 "time"
267
268 "gitbay.org/gitbay/internal/protocol"
269 "gitbay.org/gitbay/internal/store"
270)
271
272// follow starts build log --follow on build 1 of repo and returns the
273// buffers and a channel carrying the exit code.
274func follow(t *testing.T, st *store.Store, uid int64, repo store.Repo, done <-chan struct{}) (*bytes.Buffer, *bytes.Buffer, chan int) {
275 t.Helper()
276 u, err := st.UserByID(uid)
277 if err != nil {
278 t.Fatal(err)
279 }
280 var out, errOut bytes.Buffer
281 c := &Ctx{User: u, Scope: "full", Store: st, Stdin: strings.NewReader(""),
282 Stdout: &out, Stderr: &errOut, Done: done}
283 res := make(chan int, 1)
284 go func() { res <- Dispatch(c, []string{"build", "log", repo.Path(), "1", "--follow"}) }()
285 return &out, &errOut, res
286}
287
288func waitExit(t *testing.T, res chan int) int {
289 t.Helper()
290 select {
291 case code := <-res:
292 return code
293 case <-time.After(10 * time.Second):
294 t.Fatal("follow did not end")
295 return -1
296 }
297}
298
299func shortFollowTimers(t *testing.T) {
300 settle, poll := followSettle, followPoll
301 followSettle, followPoll = 200*time.Millisecond, 50*time.Millisecond
302 t.Cleanup(func() { followSettle, followPoll = settle, poll })
303}
304
305// The follow prints the stored log, then what arrives, and ends with the
306// outcome on stderr once the build finishes.
307func TestBuildLogFollow(t *testing.T) {
308 shortFollowTimers(t)
309 st, repo, uid := newQueueTestRepo(t)
310 id, err := st.CreateBuild(repo.ID, "unit", "abc", "main", `["true"]`, "", "", true)
311 if err != nil {
312 t.Fatal(err)
313 }
314 st.AppendBuildLog(id, []byte("queued\n"))
315 out, errOut, res := follow(t, st, uid, repo, nil)
316
317 if _, ok, err := st.ClaimBuild([]int64{repo.ID}, false); err != nil || !ok {
318 t.Fatalf("claim: %v %v", ok, err)
319 }
320 st.AppendBuildLog(id, []byte("step one\n"))
321 st.AppendBuildLog(id, []byte("step two\n"))
322 if err := st.FinishBuild(id, "success"); err != nil {
323 t.Fatal(err)
324 }
325 if code := waitExit(t, res); code != protocol.ExitOK {
326 t.Fatalf("exit %d: %s", code, errOut)
327 }
328 if got := out.String(); got != "queued\nstep one\nstep two\n" {
329 t.Errorf("stdout %q", got)
330 }
331 if got := strings.TrimSpace(errOut.String()); got != "build 1 success" {
332 t.Errorf("stderr %q", got)
333 }
334}
335
336// A cancel ends the follow, and the line the cancel appends after the
337// status change still arrives.
338func TestBuildLogFollowCancel(t *testing.T) {
339 shortFollowTimers(t)
340 st, repo, uid := newQueueTestRepo(t)
341 id, err := st.CreateBuild(repo.ID, "unit", "abc", "main", `["true"]`, "", "", true)
342 if err != nil {
343 t.Fatal(err)
344 }
345 out, errOut, res := follow(t, st, uid, repo, nil)
346 if err := st.CancelBuild(id); err != nil {
347 t.Fatal(err)
348 }
349 st.AppendBuildLog(id, []byte("cancelled by alice before a runner claimed it\n"))
350 if code := waitExit(t, res); code != protocol.ExitOK {
351 t.Fatalf("exit %d: %s", code, errOut)
352 }
353 if !strings.Contains(out.String(), "cancelled by alice") {
354 t.Errorf("the cancel line did not arrive: %q", out)
355 }
356 if got := strings.TrimSpace(errOut.String()); got != "build 1 cancelled" {
357 t.Errorf("stderr %q", got)
358 }
359}
360
361// Closing Done ends a follow of a build that is still running.
362func TestBuildLogFollowDone(t *testing.T) {
363 shortFollowTimers(t)
364 st, repo, uid := newQueueTestRepo(t)
365 if _, err := st.CreateBuild(repo.ID, "unit", "abc", "main", `["true"]`, "", "", true); err != nil {
366 t.Fatal(err)
367 }
368 done := make(chan struct{})
369 _, _, res := follow(t, st, uid, repo, done)
370 close(done)
371 if code := waitExit(t, res); code != protocol.ExitFailure {
372 t.Fatalf("exit %d, want %d", code, protocol.ExitFailure)
373 }
374}
375
376// An account holding maxFollows is refused another.
377func TestBuildLogFollowCap(t *testing.T) {
378 st, repo, uid := newQueueTestRepo(t)
379 if _, err := st.CreateBuild(repo.ID, "unit", "abc", "main", `["true"]`, "", "", true); err != nil {
380 t.Fatal(err)
381 }
382 followMu.Lock()
383 follows[uid] = maxFollows
384 followMu.Unlock()
385 t.Cleanup(func() {
386 followMu.Lock()
387 delete(follows, uid)
388 followMu.Unlock()
389 })
390 _, errOut, res := follow(t, st, uid, repo, nil)
391 if code := waitExit(t, res); code != protocol.ExitDenied {
392 t.Fatalf("exit %d, want %d", code, protocol.ExitDenied)
393 }
394 if !strings.Contains(errOut.String(), "8 follows are already open") {
395 t.Errorf("stderr %q", errOut)
396 }
397}
398```
399
400- [ ] **Step 2: Run to see them fail**
401
402Run: `go test ./internal/control/ -run 'TestBuildLogFollow' -count=1`
403Expected: build failure, `unknown field Done` / `undefined: followSettle`.
404
405- [ ] **Step 3: Implement**
406
407`internal/control/control.go`, in `Ctx` after `Cmd`:
408
409```go
410 // Done, when the surface has one, closes when nobody is reading any
411 // more: the SSH channel closed or the HTTP request ended. A command
412 // that runs until something happens (build log --follow) stops on it.
413 Done <-chan struct{}
414```
415
416`internal/control/build.go` registration:
417
418```go
419 register(Command{Path: []string{"build", "log"},
420 Summary: "print a build's log, or follow it until the build ends",
421 Usage: "build log <owner/name> <n> [--follow]", ReadOnly: true, Run: runBuildLog})
422```
423
424`runBuildLog`:
425
426```go
427func runBuildLog(c *Ctx, args []string) int {
428 f, err := parseFlags(args, flagSpec{Bools: []string{"--follow"}, MaxPos: 2, Usage: c.Cmd.Usage})
429 if err != nil {
430 return c.fail(protocol.ExitUsage, "%v", err)
431 }
432 _, b, code := buildRef(c, f.Pos)
433 if code >= 0 {
434 return code
435 }
436 if f.Has("--follow") {
437 return followBuildLog(c, b)
438 }
439 log, err := c.Store.BuildLog(b.ID)
440 if err != nil {
441 return c.fail(protocol.ExitFailure, "%v", err)
442 }
443 c.Stdout.Write(log)
444 return protocol.ExitOK
445}
446```
447
448Check how `runBuildList` (build.go ~125) reports a `parseFlags` error and match it exactly if it differs from the above.
449
450`internal/control/buildfollow.go`:
451
452```go
453package control
454
455import (
456 "fmt"
457 "sync"
458 "time"
459
460 "gitbay.org/gitbay/internal/protocol"
461 "gitbay.org/gitbay/internal/store"
462)
463
464// maxFollows is how many build log follows one account holds open at
465// once. Signed-out web viewers are account 0 and share it.
466const maxFollows = 8
467
468var (
469 // followPoll bounds a wait with no wake. A write from another process
470 // (gitbayd admin, or any session under gitbayd shell) wakes nobody;
471 // this is how its bytes still arrive.
472 followPoll = 2 * time.Second
473 // followSettle is how long a follow keeps reading after the build has
474 // an outcome: a cancel appends its line after the status changes, and
475 // a cancelled runner's stream runs on until its next check.
476 followSettle = time.Second
477)
478
479var (
480 followMu sync.Mutex
481 follows = map[int64]int{}
482)
483
484func takeFollow(uid int64) bool {
485 followMu.Lock()
486 defer followMu.Unlock()
487 if follows[uid] >= maxFollows {
488 return false
489 }
490 follows[uid]++
491 return true
492}
493
494func dropFollow(uid int64) {
495 followMu.Lock()
496 defer followMu.Unlock()
497 if follows[uid]--; follows[uid] <= 0 {
498 delete(follows, uid)
499 }
500}
501
502// followBuildLog writes the build's log as it grows and returns once the
503// build has an outcome and its last bytes are written. The outcome goes
504// to stderr, so stdout is the log byte for byte.
505func followBuildLog(c *Ctx, b store.Build) int {
506 if !takeFollow(c.User.ID) {
507 return c.fail(protocol.ExitDenied, "%d follows are already open for this account; close one and retry", maxFollows)
508 }
509 defer dropFollow(c.User.ID)
510
511 var off int64
512 var settleBy time.Time
513 for {
514 wake := c.Store.BuildLogWait(b.ID)
515 status, chunk, err := c.Store.BuildLogFrom(b.ID, off)
516 if err != nil {
517 return c.fail(protocol.ExitFailure, "%v", err)
518 }
519 if len(chunk) > 0 {
520 if _, err := c.Stdout.Write(chunk); err != nil {
521 return protocol.ExitFailure
522 }
523 off += int64(len(chunk))
524 }
525 wait := followPoll
526 if status != "pending" && status != "running" {
527 if settleBy.IsZero() {
528 settleBy = time.Now().Add(followSettle)
529 }
530 left := time.Until(settleBy)
531 if left <= 0 && len(chunk) == 0 {
532 fmt.Fprintf(c.Stderr, "build %d %s\n", b.Number, status)
533 return protocol.ExitOK
534 }
535 wait = min(wait, max(left, 0))
536 }
537 t := time.NewTimer(wait)
538 select {
539 case <-wake:
540 case <-t.C:
541 case <-c.Done:
542 t.Stop()
543 return protocol.ExitFailure
544 }
545 t.Stop()
546 }
547}
548```
549
550Check the loop against the spec before moving on: once the status is terminal it keeps reading until `followSettle` has passed *and* a read came back empty, then prints the outcome. A deadline, not a `time.After` channel: a timer channel delivers once, and a second check of it would block. A nil `c.Done` never fires in the select, which is what a surface without one wants. `min`/`max` are Go 1.21 builtins; check `go.mod`'s go line is at least 1.21.
551
552`cmd/gitbay/main.go:51`:
553
554```go
555 pass("log", "a build's log: <owner/name> <n> [--follow]", passOpts{server: []string{"build", "log"}, needsRepo: true}),
556```
557
558- [ ] **Step 4: Run the tests, the race detector, and vet**
559
560Run: `go test ./internal/control/ -run 'TestBuildLog' -count=1 -race && go vet ./internal/control/ ./cmd/gitbay/ && go test ./cmd/gitbay/ -count=1`
561Expected: `ok` for each.
562
563Then run the whole control package once, since `build log` is covered elsewhere too: `go test ./internal/control/ -count=1`.
564
565- [ ] **Step 5: Commit**
566
567```bash
568git add internal/control/control.go internal/control/build.go internal/control/buildfollow.go internal/control/buildfollow_test.go cmd/gitbay/main.go
569git commit -m "build log --follow: stream a build's log until it ends
570
571Ref #250"
572```
573
574---
575
576### Task 3: Surfaces pass Done — SSH channel close, HTTP request end
577
578**Files:**
579- Modify: `internal/sshd/sshd.go` (`handleSession` ~230, `runExec` ~270, `Exec` ~305, the `control.Ctx` at ~335)
580- Modify: `cmd/gitbayd/system.go:96`
581- Modify: `internal/httpd/api.go` (~64), `internal/httpd/apiread.go` (~53)
582
583**Interfaces:**
584- Consumes: `Ctx.Done` (Task 2).
585- Produces: `sshd.Exec(cfg, st, user, scope, source, cmdline string, stdin io.Reader, stdout, stderr io.Writer, done <-chan struct{}) int`.
586
587- [ ] **Step 1: SSH.** In `handleSession`'s `"exec"` case, replace the two lines after `req.Reply(true, nil)`:
588
589```go
590 req.Reply(true, nil)
591 // x/crypto closes reqs when the client closes the channel. That
592 // is how a follow learns nobody is reading: the CLI's shared
593 // connection outlives a Ctrl-C, the channel does not.
594 done := make(chan struct{})
595 go func() {
596 for r := range reqs {
597 r.Reply(false, nil)
598 }
599 close(done)
600 }()
601 code := s.runExec(sconn, ch, payload.Command, done)
602 sendExit(ch, code)
603 return
604```
605
606`runExec` gains `done <-chan struct{}` as its last parameter and passes it to `Exec`. `Exec` gains `done <-chan struct{}` as its last parameter and sets `Done: done` in the `control.Ctx` it builds. `cmd/gitbayd/system.go:96` passes `nil` (that process ends with its session).
607
608Find every other caller: `grep -rn 'sshd.Exec(\|\.runExec(' --include='*.go' .` and update them, test files included.
609
610- [ ] **Step 2: API.** In `internal/httpd/api.go` and `internal/httpd/apiread.go`, add `Done: r.Context().Done(),` to the `control.Ctx` literal.
611
612- [ ] **Step 3: Build, vet, test**
613
614Run: `go build ./... && go vet ./internal/sshd/ ./internal/httpd/ ./cmd/gitbayd/ && go test ./internal/sshd/ ./internal/httpd/ -count=1`
615Expected: `ok`.
616
617- [ ] **Step 4: Commit**
618
619```bash
620git add internal/sshd/sshd.go cmd/gitbayd/system.go internal/httpd/api.go internal/httpd/apiread.go
621git commit -m "sshd, api: end a command when its reader goes away
622
623Ref #250"
624```
625
626---
627
628### Task 4: gzipWriter passes a flush through
629
630**Files:**
631- Modify: `internal/httpd/compress.go`
632- Test: `internal/httpd/compress_test.go`
633
634**Interfaces:**
635- Produces: `(*gzipWriter).Flush()`, `(*gzipWriter).Unwrap() http.ResponseWriter`.
636
637- [ ] **Step 1: Write the failing test** — append to `internal/httpd/compress_test.go` (add missing imports: `bytes`, `compress/gzip`, `io`, `net/http`, `net/http/httptest`, `strings`):
638
639```go
640// A flush mid-response reaches the connection with what was written so
641// far decodable, which is what lets a page stream through gzip.
642func TestGzipWriterFlushes(t *testing.T) {
643 rec := httptest.NewRecorder()
644 h := compressed(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
645 w.Header().Set("Content-Type", "text/html; charset=utf-8")
646 io.WriteString(w, "<p>first</p>")
647 if err := http.NewResponseController(w).Flush(); err != nil {
648 t.Fatalf("flush: %v", err)
649 }
650 if !rec.Flushed {
651 t.Fatal("the flush did not reach the connection")
652 }
653 zr, err := gzip.NewReader(bytes.NewReader(rec.Body.Bytes()))
654 if err != nil {
655 t.Fatalf("gzip header: %v", err)
656 }
657 got, _ := io.ReadAll(zr) // no trailer yet: ends in ErrUnexpectedEOF
658 if !strings.Contains(string(got), "<p>first</p>") {
659 t.Fatalf("flushed body decodes to %q", got)
660 }
661 io.WriteString(w, "<p>second</p>")
662 }))
663 req := httptest.NewRequest("GET", "/", nil)
664 req.Header.Set("Accept-Encoding", "gzip")
665 h.ServeHTTP(rec, req)
666}
667```
668
669- [ ] **Step 2: Run to see it fail**
670
671Run: `go test ./internal/httpd/ -run TestGzipWriterFlushes -count=1`
672Expected: FAIL, `flush: feature not supported`.
673
674- [ ] **Step 3: Implement** — in `internal/httpd/compress.go`, after `Close`:
675
676```go
677// Flush sends what the gzip stream holds, then flushes the connection, so
678// a streamed page reaches the browser as it is written.
679func (g *gzipWriter) Flush() {
680 if !g.decided {
681 g.decide(http.StatusOK)
682 }
683 if g.gz != nil {
684 g.gz.Flush()
685 }
686 http.NewResponseController(g.ResponseWriter).Flush()
687}
688
689func (g *gzipWriter) Unwrap() http.ResponseWriter { return g.ResponseWriter }
690```
691
692- [ ] **Step 4: Run**
693
694Run: `go test ./internal/httpd/ -count=1 && go vet ./internal/httpd/`
695Expected: `ok`.
696
697- [ ] **Step 5: Commit**
698
699```bash
700git add internal/httpd/compress.go internal/httpd/compress_test.go
701git commit -m "httpd: gzipWriter passes a flush through
702
703Ref #250"
704```
705
706---
707
708### Task 5: The build page streams a live build
709
710**Files:**
711- Modify: `internal/httpd/builds.go` (`build`, ~280)
712- Modify: `internal/httpd/control.go` (new `runControlStream` after `runControlCode`)
713- Modify: `internal/web/templates/build.html`
714
715**Interfaces:**
716- Consumes: `build log --follow` (Task 2), `gzipWriter.Flush` (Task 4), `Ctx.Done`.
717- Produces: `func (s *Server) runControlStream(u store.User, argv []string, out io.Writer, done <-chan struct{}) (msg string, code int)`; `type buildView`; `const liveLogMarker`.
718
719- [ ] **Step 1: Template.** Replace the last content line of `build.html`:
720
721```
722{{if .Log}}<pre class="code buildlog" tabindex="0">{{.Log}}</pre>{{else}}<p class="empty-note">no log yet</p>{{end}}
723```
724
725with:
726
727```
728{{if .Live}}<p class="meta">Live: the log streams here until the build ends. If it stops without a “build finished” line, reload to pick it up again. <a href="?follow=0">Show it without updates</a></p>
729<pre class="code buildlog" tabindex="0">{{.Log}}</pre>
730{{else if .Log}}<pre class="code buildlog" tabindex="0">{{.Log}}</pre>{{else}}<p class="empty-note">no log yet</p>{{end}}
731```
732
733- [ ] **Step 2: `runControlStream`** in `internal/httpd/control.go` after `runControlCode` (add `io` to imports):
734
735```go
736// runControlStream runs a command whose output is written as it is
737// produced: stdout goes to out, and done ends the command when the
738// request does. msg is stderr.
739func (s *Server) runControlStream(u store.User, argv []string, out io.Writer, done <-chan struct{}) (msg string, code int) {
740 var stderr bytes.Buffer
741 ctx := &control.Ctx{
742 User: u,
743 Source: "web",
744 Scope: "full",
745 Store: s.st,
746 Cfg: s.cfg,
747 Stdin: strings.NewReader(""),
748 Stdout: out,
749 Stderr: &stderr,
750 ViaAPI: true,
751 Done: done,
752 }
753 code = control.Dispatch(ctx, argv)
754 return strings.TrimSpace(stderr.String()), code
755}
756```
757
758- [ ] **Step 3: Handler.** In `internal/httpd/builds.go`, replace `build` from the `log, _, _ := s.runControl(...)` line to the end with:
759
760```go
761 v := buildView{repoPage: p, Build: b, CanWrite: s.canWriteRepo(r, p.Repo), Notice: s.takeFlash(w, r)}
762 if (b.Status == "pending" || b.Status == "running") && r.URL.Query().Get("follow") != "0" {
763 s.streamBuild(w, r, v, viewer, n)
764 return
765 }
766 v.Log, _, _ = s.runControl(viewer, []string{"build", "log", p.Repo.Path(), n})
767 s.render(w, "build.html", v)
768}
769
770type buildView struct {
771 repoPage
772 Build control.BuildOut
773 Log string
774 Live bool
775 CanWrite bool
776 Notice string
777}
778
779// liveLogMarker stands in for the log when build.html is rendered for a
780// live build; streamBuild splits the page there and streams the log into
781// the gap. Git refs, paths and job names cannot hold the control byte.
782const liveLogMarker = "\x1elive-log\x1e"
783
784// streamBuild writes the build page with the log following the build:
785// the page up to the log, then build log --follow escaped and flushed as
786// it arrives, then the outcome and the rest of the page.
787func (s *Server) streamBuild(w http.ResponseWriter, r *http.Request, v buildView, viewer store.User, n string) {
788 v.Live, v.Log = true, liveLogMarker
789 var buf bytes.Buffer
790 if err := web.Render(&buf, "build.html", v); err != nil {
791 http.Error(w, "template error: "+err.Error(), http.StatusInternalServerError)
792 return
793 }
794 head, tail, ok := strings.Cut(buf.String(), liveLogMarker)
795 if !ok || !strings.HasPrefix(tail, "</pre>") {
796 http.Error(w, "template error: build.html has no live log slot", http.StatusInternalServerError)
797 return
798 }
799 tail = strings.TrimPrefix(tail, "</pre>")
800
801 h := w.Header()
802 h.Set("Content-Type", "text/html; charset=utf-8")
803 h.Set("Cache-Control", "no-store")
804 h.Set("X-Accel-Buffering", "no")
805 rc := http.NewResponseController(w)
806 io.WriteString(w, head)
807 rc.Flush()
808
809 path := v.Repo.Path()
810 msg, code := s.runControlStream(viewer, []string{"build", "log", path, n, "--follow"},
811 htmlStream{w: w, rc: rc}, r.Context().Done())
812 if code == protocol.ExitDenied {
813 // The follow cap: the stored log once, and why it is not live.
814 log, _, _ := s.runControl(viewer, []string{"build", "log", path, n})
815 template.HTMLEscape(w, []byte(log))
816 }
817 io.WriteString(w, "</pre>")
818 switch {
819 case code == protocol.ExitOK:
820 var b control.BuildOut
821 if _, ok := s.runControlInto(viewer, []string{"build", "show", path, n}, &b); ok {
822 fmt.Fprintf(w, `<p class="notice" role="status">build finished: %s</p>`, template.HTMLEscapeString(b.Status))
823 }
824 case code == protocol.ExitDenied:
825 fmt.Fprintf(w, `<p class="error" role="alert">%s</p>`, template.HTMLEscapeString(msg))
826 }
827 io.WriteString(w, tail)
828}
829
830// htmlStream escapes each chunk of a streamed log into the page and
831// flushes it, so the browser draws it as it arrives.
832type htmlStream struct {
833 w io.Writer
834 rc *http.ResponseController
835}
836
837func (h htmlStream) Write(p []byte) (int, error) {
838 template.HTMLEscape(h.w, p)
839 if err := h.rc.Flush(); err != nil {
840 return 0, err
841 }
842 return len(p), nil
843}
844```
845
846Add the imports `builds.go` now needs (`bytes`, `fmt`, `html/template`, `io`, `strings`, `gitbay.org/gitbay/internal/protocol`, `gitbay.org/gitbay/internal/web`) — only those not already present. If `builds.go` already imports `text/template` or another `template`, alias accordingly.
847
848- [ ] **Step 4: Build, vet, unit tests**
849
850Run: `go build ./... && go vet ./internal/httpd/ ./internal/web/ && go test ./internal/httpd/ ./internal/web/ -count=1`
851Expected: `ok`. (`TestMainWidthClass` needs nothing: no new template.)
852
853- [ ] **Step 5: Commit**
854
855```bash
856git add internal/httpd/builds.go internal/httpd/control.go internal/web/templates/build.html
857git commit -m "web: the build page streams a live build's log
858
859Ref #250"
860```
861
862---
863
864### Task 6: e2e — follow over ssh and on the page
865
866**Files:**
867- Modify: `e2e/ssh_test.go` (extract `sshCmd` from `ssh`, ~line 164)
868- Create: `e2e/buildfollow_test.go`
869
870**Interfaces:**
871- Consumes: everything above; e2e helpers `startInstance`, `newKey`, `admin`, `ssh`, `gitEnv`, `sshURL`, `mustGit`, `httpPort`.
872- Produces: `func (i *instance) sshCmd(key string, args ...string) *exec.Cmd`.
873
874- [ ] **Step 1: Extract `sshCmd`.** In `e2e/ssh_test.go`, split `ssh`:
875
876```go
877// sshCmd is the ssh invocation ssh runs, for a test that reads the output
878// as it arrives.
879func (i *instance) sshCmd(key string, args ...string) *exec.Cmd {
880 base := []string{
881 "-p", fmt.Sprint(i.port),
882 "-i", key,
883 "-o", "IdentitiesOnly=yes",
884 "-o", "StrictHostKeyChecking=no",
885 "-o", "UserKnownHostsFile=" + filepath.Join(i.sshDir, "known_hosts"),
886 "-o", "BatchMode=yes",
887 "git@127.0.0.1",
888 }
889 return exec.Command("ssh", append(base, args...)...)
890}
891```
892
893and have `ssh` start with `cmd := i.sshCmd(key, args...)` in place of building `base` itself.
894
895- [ ] **Step 2: Write the test** — `e2e/buildfollow_test.go`:
896
897```go
898package e2e
899
900import (
901 "encoding/json"
902 "fmt"
903 "io"
904 "net/http"
905 "os"
906 "path/filepath"
907 "strings"
908 "testing"
909 "time"
910)
911
912// streamReader collects what r delivers, so a test can wait for text to
913// arrive while the writer is still going.
914type streamReader struct {
915 ch chan []byte
916 buf strings.Builder
917}
918
919func newStreamReader(r io.Reader) *streamReader {
920 s := &streamReader{ch: make(chan []byte, 16)}
921 go func() {
922 b := make([]byte, 4096)
923 for {
924 n, err := r.Read(b)
925 if n > 0 {
926 s.ch <- append([]byte(nil), b[:n]...)
927 }
928 if err != nil {
929 close(s.ch)
930 return
931 }
932 }
933 }()
934 return s
935}
936
937func (s *streamReader) waitFor(t *testing.T, want string) string {
938 t.Helper()
939 deadline := time.After(20 * time.Second)
940 for !strings.Contains(s.buf.String(), want) {
941 select {
942 case b, ok := <-s.ch:
943 if !ok {
944 t.Fatalf("stream ended before %q:\n%s", want, s.buf.String())
945 }
946 s.buf.Write(b)
947 case <-deadline:
948 t.Fatalf("no %q after 20s:\n%s", want, s.buf.String())
949 }
950 }
951 return s.buf.String()
952}
953
954// A running build is followed over ssh and on its page: output the runner
955// sends arrives while the build runs, and both end with the outcome.
956func TestBuildLogFollow(t *testing.T) {
957 t.Parallel()
958 inst := startInstance(t)
959 aliceKey := inst.newKey(t, "alice")
960 runnerKey := inst.newKey(t, "ci")
961 inst.admin(t, "admin", "user", "create", "alice", "--key", aliceKey+".pub")
962 inst.admin(t, "admin", "user", "create", "ci", "--key", runnerKey+".pub", "--admin")
963 if _, _, code := inst.ssh(t, aliceKey, "", "repo", "create", "alice/app"); code != 0 {
964 t.Fatal("repo create failed")
965 }
966 work := t.TempDir()
967 env := inst.gitEnv(aliceKey)
968 mustGit(t, work, env, "clone", inst.sshURL("alice/app"), "w")
969 dir := filepath.Join(work, "w")
970 os.MkdirAll(filepath.Join(dir, ".gitbay"), 0o755)
971 os.WriteFile(filepath.Join(dir, ".gitbay", "ci.yml"), []byte("jobs:\n unit:\n steps:\n - echo fine\n"), 0o644)
972 mustGit(t, dir, env, "checkout", "-q", "-b", "main")
973 mustGit(t, dir, env, "add", ".")
974 mustGit(t, dir, env, "commit", "-q", "-m", "ci")
975 mustGit(t, dir, env, "push", "-q", "origin", "main")
976
977 // Claim build 1 by hand, so the test decides when output arrives.
978 out, errOut, code := inst.ssh(t, runnerKey, "", "runner", "next", "--json")
979 if code != 0 {
980 t.Fatalf("runner next: %s", errOut)
981 }
982 var claim struct {
983 Data struct {
984 ID int64 `json:"id"`
985 } `json:"data"`
986 }
987 if err := json.Unmarshal([]byte(out), &claim); err != nil || claim.Data.ID == 0 {
988 t.Fatalf("runner next output %q: %v", out, err)
989 }
990 id := fmt.Sprint(claim.Data.ID)
991
992 cmd := inst.sshCmd(aliceKey, "build", "log", "alice/app", "1", "--follow")
993 stdout, err := cmd.StdoutPipe()
994 if err != nil {
995 t.Fatal(err)
996 }
997 var stderr strings.Builder
998 cmd.Stderr = &stderr
999 if err := cmd.Start(); err != nil {
1000 t.Fatal(err)
1001 }
1002 follow := newStreamReader(stdout)
1003
1004 page, err := http.Get(fmt.Sprintf("http://127.0.0.1:%d/alice/app/builds/1", inst.httpPort))
1005 if err != nil {
1006 t.Fatal(err)
1007 }
1008 defer page.Body.Close()
1009 web := newStreamReader(page.Body)
1010 web.waitFor(t, "Live: the log streams here")
1011
1012 // A static render while the build runs returns at once.
1013 static := &http.Client{Timeout: 10 * time.Second}
1014 resp, err := static.Get(fmt.Sprintf("http://127.0.0.1:%d/alice/app/builds/1?follow=0", inst.httpPort))
1015 if err != nil {
1016 t.Fatalf("?follow=0 did not return: %v", err)
1017 }
1018 body, _ := io.ReadAll(resp.Body)
1019 resp.Body.Close()
1020 if strings.Contains(string(body), "Live:") {
1021 t.Fatalf("?follow=0 rendered the live page:\n%s", body)
1022 }
1023
1024 if _, errOut, code := inst.ssh(t, runnerKey, "hello from the runner <b>\n", "runner", "log", id); code != 0 {
1025 t.Fatalf("runner log: %s", errOut)
1026 }
1027 follow.waitFor(t, "hello from the runner <b>\n")
1028 web.waitFor(t, "hello from the runner <b>")
1029
1030 if _, errOut, code := inst.ssh(t, runnerKey, "", "runner", "done", id, "success"); code != 0 {
1031 t.Fatalf("runner done: %s", errOut)
1032 }
1033 web.waitFor(t, `<p class="notice" role="status">build finished: success</p>`)
1034 web.waitFor(t, "</html>")
1035 if err := cmd.Wait(); err != nil {
1036 t.Fatalf("follow exited: %v\n%s", err, stderr.String())
1037 }
1038 if got := strings.TrimSpace(stderr.String()); got != "build 1 success" {
1039 t.Errorf("follow stderr %q", got)
1040 }
1041}
1042```
1043
1044- [ ] **Step 3: Run it**
1045
1046Run: `go test ./e2e/ -run 'TestBuildLogFollow$' -count=1 -v 2>&1 | tail -20`
1047Expected: `--- PASS: TestBuildLogFollow`. If `</html>` is not how the layout ends, use the last line `layout.html` renders.
1048
1049- [ ] **Step 4: Check the neighbours.** Run `go vet ./e2e/` and the tests that use `inst.ssh` heavily and build pages: `go test ./e2e/ -run 'TestBuildCancel$|TestControlPlaneOverBareSSH$' -count=1`.
1050
1051- [ ] **Step 5: Commit**
1052
1053```bash
1054git add e2e/ssh_test.go e2e/buildfollow_test.go
1055git commit -m "e2e: follow a running build over ssh and on its page
1056
1057Ref #250"
1058```
1059
1060---
1061
1062### Task 7: Docs
1063
1064**Files:**
1065- Modify: `.gitbay/wiki/Parity.org` (build rows, ~line 212)
1066- Modify: `.gitbay/wiki/CI.org`
1067
1068- [ ] **Step 1: Parity.** After `| build log | yes | yes | yes |` add (columns are cli, web, ios):
1069
1070```
1071| build log follow (until it ends) | yes | yes | no |
1072```
1073
1074- [ ] **Step 2: CI.org.** After the paragraph that begins "Scheduled jobs run on their cron", add:
1075
1076```
1077A running build is followed with =build log <owner/name> <n> --follow=:
1078the stored log, then output as the runner sends it, then the outcome
1079as =build <n> <status>= on stderr once the build ends. The exit code is
10800 whatever the outcome. The build page does the same without
1081JavaScript while a build is queued or running; =?follow=0= renders it
1082once. An account holds at most eight follows open, and signed-out
1083viewers share one account's eight. Over the JSON API the command
1084answers when the build ends, with the whole log.
1085```
1086
1087- [ ] **Step 3: Commit**
1088
1089```bash
1090git add .gitbay/wiki/Parity.org .gitbay/wiki/CI.org
1091git commit -m "wiki: build log --follow
1092
1093Closes #250"
1094```
1095
1096---
1097
1098## Finish
1099
1100Push `build-log-follow`, open the MR with `gitbay mr create --source build-log-follow --target main --title "build log --follow, streamed to the build page" --file - < <body file>`, wait for CI, then `gitbay mr merge <n> --strategy ff` and delete the branch in both places.