package lua import ( "net/http" "net/http/httptest" "os" "path/filepath" "testing" "time" ) // TestPluginClockDuringNetworkWait pins the reason the probe budget never // enforced itself. // // Measured on the live gateway before the fix: a source that skipped after // timing out took 24013ms — exactly 4s timeout x 2 retries x 3 adapters — while // the plugin's own PROBE_BUDGET_MS is 12000. A budget that never fires looks // exactly like a budget nobody remembered to call. // // The cause is os.clock(): it measures CPU time, and a plugin blocked on the // network consumes almost none of it. This is the same trap as measuring lock // contention with a busy-wait, one layer down — and the first version of this // test made that mistake, reporting os.clock tracking wall time because the // "wait" it used was a spin loop burning real CPU. It had to be re-measured // against an actual HTTP request. func TestPluginClockDuringNetworkWait(t *testing.T) { dir := t.TempDir() pluginDir := filepath.Join(dir, "plugins") if err := os.MkdirAll(pluginDir, 0o755); err != nil { t.Fatal(err) } vm := NewVM(filepath.Join(dir, "adapters")) if err := vm.Start(); err != nil { t.Fatal(err) } t.Cleanup(vm.Stop) ps := NewPlugins(vm, pluginDir) t.Cleanup(ps.Close) ps.SetOutboundHosts([]string{"127.0.0.1"}) code := ` local P = {} P.name = "clocktest" P.version = "1.0.0" P.exports = { "measure" } P.measure = function(payload) local c0, w0 = os.clock(), os.time() -- The real thing: block on the network. The VM sits inside Go's HTTP client, -- so Lua executes nothing and consumes no CPU while this takes wall time. __llmsproxy_http({ url = payload.url, method = "GET", timeout_ms = 5000 }) return { clock = os.clock() - c0, wall = os.time() - w0, } end return P ` if err := os.WriteFile(filepath.Join(pluginDir, "clocktest.lua"), []byte(code), 0o644); err != nil { t.Fatal(err) } srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { time.Sleep(3 * time.Second) _, _ = w.Write([]byte(`{}`)) })) defer srv.Close() if err := ps.LoadDir(); err != nil { t.Fatal(err) } p := ps.find("clocktest") if p == nil { t.Fatal("plugin not found") } if p.LoadError != "" { t.Fatalf("plugin failed to compile: %s", p.LoadError) } out, err := ps.Call("clocktest", "measure", map[string]interface{}{"url": srv.URL + "/slow"}) if err != nil { t.Fatal(err) } m, _ := out.(map[string]interface{}) clock, _ := m["clock"].(float64) wall, _ := m["wall"].(float64) t.Logf("3s blocked on HTTP: os.clock advanced %.3fs, os.time advanced %.0fs", clock, wall) if wall < 3 { t.Fatalf("the request did not take 3 wall seconds (got %.0f)", wall) } if clock > wall/2 { t.Fatalf("os.clock tracked wall time (%.3f vs %.0f) — the budget is not the cause; "+ "look elsewhere", clock, wall) } t.Logf("CONFIRMED: blocked on the network for %.0fs, os.clock advanced %.3fs. "+ "A budget written in os.clock never fires while a plugin waits on I/O.", wall, clock) }