diff --git a/.agents/skills/flats-dev-workflow/playbooks/flaky-or-timing-tests.md b/.agents/skills/flats-dev-workflow/playbooks/flaky-or-timing-tests.md index fd3550e8..8dbee897 100644 --- a/.agents/skills/flats-dev-workflow/playbooks/flaky-or-timing-tests.md +++ b/.agents/skills/flats-dev-workflow/playbooks/flaky-or-timing-tests.md @@ -26,6 +26,14 @@ before changing the test. draft PR runs the CI workflow) and look at the distribution. - [ ] For parallel runs, read `go test -json` pause/cont events to see what ran alongside the failing test before blaming parallelism. +- [ ] When several tests of the `windows` job stall at one time, look at the + clock before the test. The step prints the boot time of the runner in a log + line that begins with `the runner booted at`. The system drive of a hosted + runner can stall flushes for a while at a fixed time after the boot + ([Current state](../../../../docs/spec/windows-support.md#current-state) has + the measurement). Measure the time of a flushed write beside the test before + you change the test, and keep test data below `RUNNER_TEMP`, as the job + does. - [ ] When timing matters locally, run the CI shards one at a time (`scripts/ci-test.sh `) or `go test -p 1 ./...`. A local `go test ./...` runs the runtime and docs packages at once. diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index fcdf186a..041c5b9d 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -201,8 +201,24 @@ jobs: run: FLATS_RELEASE_TARGETS=windows/amd64 scripts/build-release.sh v0.0.0-ci "$RUNNER_TEMP/dist" - name: Tests # Verbose: the log keeps the skips and the timing lines of this job. + # The test data goes to the runner's temporary drive. About 11 minutes + # after a hosted runner boots, its system drive is read for about 45 s. + # A flush there then takes seconds, and a document test that writes + # meets the request limit (docs/gates.md). The step prints the boot + # time, so that a later stall can be compared with it. + # internal/site runs first, with the default temp directory: one of + # its tests needs the short (8.3) names of the system drive, and the + # temporary drive keeps none. It runs with -count=1, so that the test + # runs on this runner and is not a result from the test cache. run: | failed=0 + go test -v -count=1 ./internal/site || failed=1 + mkdir -p "$RUNNER_TEMP/test-tmp" + TMP=$(cygpath -w "$RUNNER_TEMP/test-tmp") + TEMP=$TMP + export TMP TEMP + booted=$(pwsh -NoProfile -Command "(Get-CimInstance Win32_OperatingSystem).LastBootUpTime.ToUniversalTime().ToString('yyyy-MM-dd HH:mm:ss')" | tr -d '\r\n') || booted=unknown + echo "the runner booted at $booted UTC, it is $(date -u '+%Y-%m-%d %H:%M:%S') UTC, and the test data is below $TEMP" for shard in runtime-soak runtime-codec runtime docs-soak docs board; do scripts/ci-test.sh "$shard" -v -timeout 30m || failed=1 done diff --git a/docs/gates.md b/docs/gates.md index 389a34ce..7dafd0ba 100644 --- a/docs/gates.md +++ b/docs/gates.md @@ -145,7 +145,15 @@ service stays stopped on upgrade, and uninstall removes it. The `windows` job runs the test shards on `windows-latest`, without the `docs-budget` shard, whose wall-clock budgets belong to the Linux job, and -without `internal/devreview`, whose run command is Unix only. It then runs +without `internal/devreview`, whose run command is Unix only. Its tests keep +their data below `RUNNER_TEMP`, on the runner's temporary drive. About 11 +minutes after a hosted runner boots, its system drive is read for about 45 s, +and a flush there takes seconds. A document test met that as a guest call at +the request limit ([Current state](spec/windows-support.md#current-state)). +The step prints the boot time of the runner, so that a later stall can be +compared with it. The package `internal/site` runs first, with the default +temp directory: one of its tests needs the short (8.3) names of the system +drive, and the temporary drive keeps none. After the tests the job runs `scripts/install-smoke.ps1` on the Windows release archive. The job runs as an administrator, so the check that the install needs no administrator rights stays manual in [Releases](release.md). diff --git a/docs/network-provider-lifecycle.md b/docs/network-provider-lifecycle.md index 69caf238..df6739ea 100644 --- a/docs/network-provider-lifecycle.md +++ b/docs/network-provider-lifecycle.md @@ -508,6 +508,32 @@ when its predecessor has finished and no `tailscaled.state` remains. State is deleted only after confirmation. `Net.Close` waits for all in-flight retirement attempts, closes every remaining backend, and reports any retained failure. +A close of a backend can end the whole process, and Flats does not prevent it. +tailscale.com v1.104.0 dereferences a nil pointer in +`magicsock.(*Conn).SetFilter` when a status with a network map is still in +work as its backend closes and the connection has no node of its own: before +its first network map, or after a logout reset it. Three parts of the library +combine. The status handler releases the backend lock before it installs a +network map and does not check afterwards that the backend still runs. A +shutdown does not wait for a handler that is in work. A network map that +reaches a closed connection sets the relay flag and not the node. v1.104.7, +the newest release on 2026-11-13, has the same text in each of these +functions, and the root module can carry no patched copy. The development +branch of the library ignores the status of a control client that a logout +replaced (commit `b9d5ff3ae` of 2026-11-10), which removes the case after a +logout. No release holds that commit yet. The case of a backend that closes +while it handles its first network map stays on that branch. A logout followed +by a close meets the fault when a status is in work at that moment. A backend +gets four or five statuses with a network map in the first 0.6 s after its +start, the last of them 7 to 19 ms after it reports `Running`, and none in the +4 s after that (20 starts against the test control server). The retry above +logs out a fresh backend about 1 ms after its start, so it has the highest +risk. The `windows` CI job met the fault once in its first 32 runs. The order +of its log lines and the state rule of the library place that event in the +retry, and its stack names no node. After such an end a host that runs as the +installed service starts again, and a host that runs in the foreground stays +down. + ## Private Tailscale revocation An operator-validated revocation of Tailscale, NetBird or `proxy` confirms Manager teardown of that flat’s current, preview and redirect registrations on that provider before writing the denied permission. The rest of this section describes Tailscale. Local remains registered. The real tsnet backend uses `StopPrivate`: with a sibling Funnel request it closes only Private HTTP and retains the node and approved Funnel listener; without Funnel it retires the node normally. Private listener setup and teardown are serialized so asynchronous startup cannot reopen a revoked route or race a second teardown. An in-progress or terminally failed retirement remains fail-closed. A terminal logout failure closes the consumed backend and preserves its persistent state; the next `StopPrivate` call starts a fresh backend over that state and performs a real logout retry in the same process. Absence from the active-node map does not prove teardown completed. Legacy backends without Private-only stop support refuse if a Funnel registration shares the host. Public provider revocation continues to require an approved Public-to-Private transition. diff --git a/docs/spec/windows-support.md b/docs/spec/windows-support.md index 32457e9e..270eced2 100644 --- a/docs/spec/windows-support.md +++ b/docs/spec/windows-support.md @@ -176,33 +176,45 @@ browser on Windows. The technical design holds the measurements. The status is 16 tests in parallel on Windows: its first `hello` reached the 10 s limit of one guest call after a slow worker start, 3.8 s in the last run. It passed 6 of 6 runs on four processors. The CI job is the first run of the docs tests on a Windows runner. -- The `windows` CI job failed in 2 of its first 12 completed runs because a guest - call soon after a worker start reached the 10 s limit of one guest call, both times - in tests of the `docs-soak` shard and in workers that started within 2 s of each - other. On 2026-11-05 the tests were `TestDocumentOwnershipSoak/1MiBASCII`, at its - first guest call, and `TestConflictPrivacyAndRollbackStorageBudgets/bytes`, at the - first read of its document after a worker start, with - `failed to call QJS_FreeValue: module closed with context deadline exceeded`. On - 2026-11-12 they were the four tests that start the shard, `/bytes` among them, - each at its first guest call, after worker starts of 1.2 to 2.6 s, with - `failed to call js_std_await: allocate ... after the runtime closed`. The two texts - differ because [the guarded JS engine](guarded-js-engine.md) came between the runs - and words a closed runtime differently. Both say that the limit closed the runtime - during the call. Each stalled call reads or writes the flat's database. In each - event another worker started in about 0.3 s during those seconds, so the runner - did not stop. The cause is not identified. Load does not explain the second - event. On four processors that call takes 18 to 212 ms. With three copies of the - shard at once, a worker start takes 5.4 to 7.5 s and the call at most 2.1 s. The - failed run had worker starts of 1.2 to 2.6 s, against 0.9 to 1.8 s in eight runs - in which these tests passed, so its starts were at most 0.8 s slower, while its - first guest calls did not end within 10 s. How long that call takes on the runner - in a run that passes is not measured. At this rate the job can also fail a pull - request that did not cause it. On Windows, a document test that starts its host - with `startAppModule`, as the tests of both events do, now asks the worker for its - goroutine stacks when its first guest call is open after 5 s, and logs them, so - the next event shows where the worker waits (`stall_test.go` in - `internal/apps/docs`). The watch covers that first call only: the document read - of 2026-11-05 would not have started it. +- A guest call that writes waits for the drive, and on a drive with slow flushes it + fails. The worker's database flushes at each commit. The document app also truncates + the write-ahead log inside the call that commits, when the log holds more than 64 + frames, so that the log at rest stays inside the disk quota (`commit` in + `storage.js`). That copies the log into the database and flushes again. When each + flush takes seconds, such a call reaches the 10 s limit of one guest call: the request + answers 504, the limit closes the JavaScript runtime of the call, and a WebSocket + whose message was in work closes with code 1011. The `windows` CI job met this in 4 of + its first 32 completed runs, each time in tests of the `docs-soak` shard, with one to + four failed tests in a run. A measurement on other runners gives the system drive of + the runner as the cause. About 11 minutes after a hosted runner boots, about 1.2 GB + are read from that drive in 36 to 50 s, through page faults. Seventeen runners showed + the reads in the counters. On an eighteenth the counters began after the time at which + the reads come on the others, and recorded none. On the three where a watch looked, + the process of the Windows Storage Service used a full processor in those seconds, and + nothing measured attributes the reads to it. A job started 1 min 44 s to 4 min 55 s + after the boot of its runner on seventeen of the eighteen runners, and 11 min 1 s + after it on one. On that one the reads would fall, by the clock of the others, into + the setup steps of the job, before its tests. The shard runs from about 9 to 10 min + after the job starts. Each of the four events began 9 min 9 s to 9 min 43 s after its + job started, which is the time of the reads on a runner that booted about 2 min before + its job. The boot times of those four runners are not recorded, so the events fit the + clock of the reads, and no record shows the reads in them. Six of the measured runners + repeated the shard 25 times each. On the three that kept the test data in the default + temp directory, which is on that drive, the run that met the reads had a guest call of + 7.9 to 11.2 s and a flushed write of 4 KiB of 1.1 to 2.8 s, and one of the three + failed two tests with the errors of the four events. The stacks of the stalled calls + end in `FlushFileBuffers`, for the commit in one sample and for the truncation in a + later one, and the timers of each process were on time. The longest guest call of the + other 72 runs on those runners took 2.7 s, although single flushed writes took 1.4 and + 2.0 s there in the first run of two jobs. On the three that kept the test data on the + temporary drive, the longest guest call of 75 runs took 2.7 s and the longest flushed + write 0.13 s, the runs during the reads included. The job now keeps its test data on + that drive, below `RUNNER_TEMP`, except for the package `internal/site`, which runs + first with the default temp directory ([the gates](../gates.md#pull-request-baseline) + have the reason). The product is as before: the limit, the flush of each commit and + the truncation inside the commit. A host whose data directory is on a drive with such + delays fails the calls that write during them. The place of the truncation is an + [open question](#open-questions). - Beside CPU and disk load on four processors, `TestHostIdleRealWorkerCycles` saw a worker start stall in two events of 252 runs, with both copies of the test at the same moment: for more than 15 s, which failed those two runs, and for more than @@ -243,4 +255,6 @@ browser on Windows. The technical design holds the measurements. The status is ## Open questions -None. +- Whether the document app can truncate its write-ahead log outside the call that + commits. The truncation keeps the log at rest inside the disk quota. Inside the call + it flushes again, and the call has a limit of 10 s ([Current state](#current-state)). diff --git a/internal/apps/docs/app_test.go b/internal/apps/docs/app_test.go index b2b34dda..c4134f5f 100644 --- a/internal/apps/docs/app_test.go +++ b/internal/apps/docs/app_test.go @@ -93,17 +93,10 @@ func startAppModule(t *testing.T, data, source, version string, environment map[ t.Fatal(err) } a := &app{srv: httptest.NewServer(inst), inst: inst, data: data, pid: int(workerPID.Load())} - // Before the cleanup that stops the worker, so that the cleanup of the - // watch runs after the worker ended. - stacks := watchCall(t, a.pid, firstCallStall) t.Cleanup(a.stop) // The host installs a disk budget before the worker admits live edits; // these tests run without a quota. - status, out := a.hostOp(t, "POST", "budget", map[string]any{"quota": 0, "other": 0, "ttl_ms": 24 * 60 * 60 * 1000}) - if s := stacks(); s != "" { - t.Logf("the first guest call of worker %d was open after %s; its goroutine stacks:\n%s", a.pid, firstCallStall, s) - } - if status != 200 { + if status, out := a.hostOp(t, "POST", "budget", map[string]any{"quota": 0, "other": 0, "ttl_ms": 24 * 60 * 60 * 1000}); status != 200 { t.Fatal("budget", status, out) } return a diff --git a/internal/apps/docs/runtime_test.go b/internal/apps/docs/runtime_test.go index de3bed32..87a8b7e7 100644 --- a/internal/apps/docs/runtime_test.go +++ b/internal/apps/docs/runtime_test.go @@ -38,9 +38,6 @@ func TestMain(m *testing.M) { afterSpec(func() { fmt.Fprintf(os.Stderr, "{\"t\":\"log\",\"level\":\"info\",\"msg\":\"docs test worker pid:%d\"}\n", os.Getpid()) }) - if dir := os.Getenv(stallDirEnv); dir != "" { - go dumpStacksOnRequest(dir) - } if err := flatsruntime.WorkerMain(os.Args[1:]); err != nil { fmt.Fprintln(os.Stderr, err) os.Exit(1) @@ -52,11 +49,6 @@ func TestMain(m *testing.M) { if err != nil { panic(err) } - if ostest.Windows { - if err = os.Mkdir(stallDir(), 0o700); err != nil { - panic(err) - } - } code := m.Run() if sharedManager != nil { sharedManager.Close() @@ -97,14 +89,10 @@ func afterSpec(fn func()) { } // docsWorkerEnv is the environment of test document workers: the dispatch -// variable, on Windows the directory of stack requests (stall_test.go), and -// the suite's document image switches (FLATS_NO_IMAGES, FLATS_FORCE_IMAGES), -// which the worker reads. +// variable and the suite's document image switches (FLATS_NO_IMAGES, +// FLATS_FORCE_IMAGES), which the worker reads. func docsWorkerEnv() []string { env := []string{"FLATS_DOCS_TEST_WORKER=1"} - if ostest.Windows { - env = append(env, stallDirEnv+"="+stallDir()) - } for _, k := range []string{"FLATS_NO_IMAGES", "FLATS_FORCE_IMAGES"} { if v := os.Getenv(k); v != "" { env = append(env, k+"="+v) diff --git a/internal/apps/docs/stall_test.go b/internal/apps/docs/stall_test.go deleted file mode 100644 index f77698e2..00000000 --- a/internal/apps/docs/stall_test.go +++ /dev/null @@ -1,157 +0,0 @@ -package docs - -import ( - "bytes" - "fmt" - "math/rand/v2" - "os" - "path/filepath" - "runtime" - "strconv" - "strings" - "sync" - "testing" - "time" - - "github.com/gosuda/flats/internal/ostest" -) - -// On the Windows CI runner the first guest call of several document workers -// has taken the whole request timeout, and nobody found why (the current state -// in docs/spec/windows-support.md). Until someone does, a Windows test worker -// gives its goroutine stacks to a test whose first call is slow, so that the -// next such run shows where the worker waits. - -// stallDirEnv names, to a test worker, the directory where it looks for -// requests for its stacks. -const stallDirEnv = "FLATS_DOCS_TEST_STALL_DIR" - -// firstCallStall is how long the first guest call of a test host may take -// before the test asks the worker for its stacks: half the request timeout. -const firstCallStall = 5 * time.Second - -// stallDir is outside every flat's data, so no test measures its files. -func stallDir() string { return filepath.Join(cacheRoot, "stall") } - -// dumpStacksOnRequest runs in a test worker. A request is a file -// ..want in dir. The worker answers it with all goroutine stacks in -// ..stacks, twice and 2 s apart, so that a reader sees whether a -// goroutine moved. -func dumpStacksOnRequest(dir string) { - started := time.Now() - mine := strconv.Itoa(os.Getpid()) + "." - for { - time.Sleep(250 * time.Millisecond) - entries, _ := os.ReadDir(dir) - for _, e := range entries { - name, ok := strings.CutSuffix(e.Name(), ".want") - if !ok || !strings.HasPrefix(name, mine) { - continue - } - // Removed first, so that a request gets one answer. A request - // that its writer still holds open stays for the next round. - if os.Remove(filepath.Join(dir, e.Name())) != nil { - continue - } - // Per request: a worker that nobody asks keeps no buffer. - buf := make([]byte, 4<<20) - var out bytes.Buffer - for sample := 1; sample <= 2; sample++ { - if sample > 1 { - time.Sleep(2 * time.Second) - } - start := time.Now() - stacks := buf[:runtime.Stack(buf, true)] - fmt.Fprintf(&out, "sample %d at %s, worker %d up for %s, the dump took %s\n%s\n", - sample, start.Format("15:04:05.000"), os.Getpid(), start.Sub(started).Round(time.Millisecond), time.Since(start), stacks) - } - answer := filepath.Join(dir, name+".stacks") - if os.WriteFile(answer+".tmp", out.Bytes(), 0o600) == nil { - os.Rename(answer+".tmp", answer) - } - } - } -} - -// watchCall asks worker pid for its stacks unless the returned function is -// called within after. That function returns the stacks, or "" when the test -// did not ask or the worker did not answer. -// -// Windows gives the id of an ended process to a new one. Each request has its -// own name, so a test reads only the answer to its own request, and the -// cleanup removes the request and the answer on every way out of the test. -// A caller registers the cleanup that stops the worker after this call, so -// that the worker has ended when this cleanup runs. One case stays: a worker -// that ends with a request open, and a new worker that gets its id within the -// 10 s of the wait. The header of each sample names how long its worker ran. -func watchCall(t *testing.T, pid int, after time.Duration) func() string { - if !ostest.Windows || pid == 0 { - return func() string { return "" } - } - base := filepath.Join(stallDir(), strconv.Itoa(pid)+"."+strconv.FormatUint(rand.Uint64(), 16)) - var mu sync.Mutex - asked, done := false, false - timer := time.AfterFunc(after, func() { - mu.Lock() - defer mu.Unlock() - if !done { - asked = os.WriteFile(base+".want", nil, 0o600) == nil - } - }) - stop := func() bool { - mu.Lock() - defer mu.Unlock() - done = true - timer.Stop() - return asked - } - t.Cleanup(func() { - stop() - os.Remove(base + ".want") - os.Remove(base + ".stacks.tmp") - os.Remove(base + ".stacks") - }) - return func() string { - if !stop() { - return "" - } - defer os.Remove(base + ".stacks") - for end := time.Now().Add(10 * time.Second); time.Now().Before(end); time.Sleep(50 * time.Millisecond) { - if b, err := os.ReadFile(base + ".stacks"); err == nil { - return string(b) - } - } - return "" - } -} - -func TestWorkerGivesItsStacks(t *testing.T) { - if !ostest.Windows { - t.Skip("only a Windows test worker answers a request for its stacks") - } - t.Parallel() - a := startApp(t, t.TempDir(), initialText, "v1") - stacks := watchCall(t, a.pid, time.Millisecond) - time.Sleep(100 * time.Millisecond) - got := stacks() - var samples []string - for line := range strings.Lines(got) { - if strings.HasPrefix(line, "sample ") { - samples = append(samples, strings.TrimSpace(line)) - } - } - t.Log(strings.Join(samples, "\n")) - want := fmt.Sprintf(", worker %d up for ", a.pid) - if len(samples) != 2 || !strings.Contains(samples[0], want) || strings.Count(got, "\ngoroutine ") < 2 { - t.Fatalf("stacks of worker %d:\n%s", a.pid, got) - } - entries, err := os.ReadDir(stallDir()) - if err != nil { - t.Fatal(err) - } - for _, e := range entries { - if strings.HasPrefix(e.Name(), strconv.Itoa(a.pid)+".") { - t.Fatalf("a file of the request stayed: %s", e.Name()) - } - } -} diff --git a/internal/runtime/spare_test.go b/internal/runtime/spare_test.go index f2bdbe1d..9389543d 100644 --- a/internal/runtime/spare_test.go +++ b/internal/runtime/spare_test.go @@ -87,7 +87,13 @@ func TestSpareAdoption(t *testing.T) { mustStart(t, m, "first", spareTestFiles(), "index.js", nil) sp := waitSpare(t, m, 0) pid := sp.p.cmd.Process.Pid + // Windows reads the clock in ticks, so two readings a moment apart can be + // equal. The adoption request begins only when the clock has passed this + // reading: a start time that the adoption sets is then later than it. waiting := time.Now() + for !time.Now().After(waiting) { + time.Sleep(time.Millisecond) + } f := mustStart(t, m, "second", spareTestFiles(), "index.js", nil) in := f.inst.(*instance) if in.pid() != pid {