From 36722940eb36a9fb6c9f581f4f2ab2ee6900ee83 Mon Sep 17 00:00:00 2001 From: Ole-Morten Duesund Date: Fri, 24 Apr 2026 17:26:32 +0200 Subject: [PATCH] feat(httpserver,log): /healthz, graceful shutdown, slog constructor MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Implements internal/httpserver and internal/log. httpserver (forgejo-mcp-broker-8ei): - Server struct owns the HTTP lifecycle; Run(ctx) blocks, Handler() returns the composed handler for unit tests - GET /healthz returns JSON with status, version, git_revision, build_date, and store probe result. Returns 503 when the store reports unhealthy - Signal handling delegated to the caller via ctx cancellation — main wires signal.NotifyContext, httpserver just responds to Done() - Graceful shutdown with a configurable deadline (default 10s). When the deadline expires, falls back to http.Server.Close() so lingering connections are forcibly terminated — http.Server.Shutdown alone never interrupts active connections - ExtraHandler extension point for the OAuth + MCP routes that land in phase 2 and phase 5, so the server doesn't need to be re-plumbed later log: - Small slog wrapper: New(w, debug) returns a JSON logger that stamps every record with service/version/git_rev for correlation across deployments - Discard() helper for tests Tests: 97.9% coverage on httpserver (all health states, wrong-method, ExtraHandler dispatch, ctx-cancel shutdown, shutdown-deadline force-close of hanging requests, missing-field errors), 100% on log. Closes forgejo-mcp-broker-8ei. Co-Authored-By: Claude Opus 4.7 (1M context) --- .beads/issues.jsonl | 4 +- internal/httpserver/doc.go | 6 - internal/httpserver/httpserver.go | 164 ++++++++++++++++ internal/httpserver/httpserver_test.go | 253 +++++++++++++++++++++++++ internal/log/doc.go | 6 - internal/log/log.go | 32 ++++ internal/log/log_test.go | 55 ++++++ 7 files changed, 506 insertions(+), 14 deletions(-) delete mode 100644 internal/httpserver/doc.go create mode 100644 internal/httpserver/httpserver.go create mode 100644 internal/httpserver/httpserver_test.go delete mode 100644 internal/log/doc.go create mode 100644 internal/log/log.go create mode 100644 internal/log/log_test.go diff --git a/.beads/issues.jsonl b/.beads/issues.jsonl index 95334bf..be52f40 100644 --- a/.beads/issues.jsonl +++ b/.beads/issues.jsonl @@ -1,5 +1,5 @@ -{"id":"forgejo-mcp-broker-8ei","title":"Phase 1: internal/httpserver with /healthz and graceful shutdown","description":"Implement internal/httpserver: constructs a *http.Server bound to cfg.Listen, mounts GET /healthz (returns 200 with JSON build-info from the build-info package, including version, git revision, build date, and current store status), handles SIGTERM/SIGINT by initiating graceful shutdown with a configurable deadline (default 10s). Uses log/slog for structured JSON logs. Exposes a Run(ctx) error method that blocks until shutdown completes.","acceptance_criteria":"go test ./internal/httpserver passes; GET /healthz returns expected JSON; sending SIGTERM causes Run to return nil within 2 seconds after in-flight requests complete; slow in-flight request is allowed to finish within the deadline, then forcibly closed.","status":"open","priority":1,"issue_type":"task","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:20Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T14:46:20Z","dependencies":[{"issue_id":"forgejo-mcp-broker-8ei","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:46:19Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":1,"dependent_count":1,"comment_count":0} +{"id":"forgejo-mcp-broker-8ei","title":"Phase 1: internal/httpserver with /healthz and graceful shutdown","description":"Implement internal/httpserver: constructs a *http.Server bound to cfg.Listen, mounts GET /healthz (returns 200 with JSON build-info from the build-info package, including version, git revision, build date, and current store status), handles SIGTERM/SIGINT by initiating graceful shutdown with a configurable deadline (default 10s). Uses log/slog for structured JSON logs. Exposes a Run(ctx) error method that blocks until shutdown completes.","acceptance_criteria":"go test ./internal/httpserver passes; GET /healthz returns expected JSON; sending SIGTERM causes Run to return nil within 2 seconds after in-flight requests complete; slow in-flight request is allowed to finish within the deadline, then forcibly closed.","status":"in_progress","priority":1,"issue_type":"task","assignee":"Ole-Morten Duesund","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:20Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T15:24:09Z","started_at":"2026-04-24T15:24:09Z","dependencies":[{"issue_id":"forgejo-mcp-broker-8ei","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:46:19Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":1,"dependent_count":1,"comment_count":0} {"id":"forgejo-mcp-broker-t37","title":"Phase 1: wire cmd/broker/main.go and integration test","description":"Final phase 1 task: wire config → log → store → httpserver in cmd/broker/main.go. Parse config, init slog, open store, start httpserver, wait for shutdown signal, close store, exit. Add an integration test under cmd/broker/ that builds the binary, runs it with a valid env + temp store path, curls /healthz, sends SIGTERM, verifies clean exit within 2s. This is the acceptance gate for phase 1.","acceptance_criteria":"make build; make test (incl. integration) pass; running the binary with missing config fails with a clear error; running with valid config serves /healthz; SIGTERM shuts down cleanly within 2s; /healthz JSON includes version, git revision, build date, and store OK status.","status":"open","priority":1,"issue_type":"task","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:20Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T14:46:20Z","dependencies":[{"issue_id":"forgejo-mcp-broker-t37","depends_on_id":"forgejo-mcp-broker-8ei","type":"blocks","created_at":"2026-04-24T16:48:29Z","created_by":"Ole-Morten Duesund","metadata":"{}"},{"issue_id":"forgejo-mcp-broker-t37","depends_on_id":"forgejo-mcp-broker-9jh","type":"blocks","created_at":"2026-04-24T16:48:29Z","created_by":"Ole-Morten Duesund","metadata":"{}"},{"issue_id":"forgejo-mcp-broker-t37","depends_on_id":"forgejo-mcp-broker-9nq","type":"blocks","created_at":"2026-04-24T16:48:28Z","created_by":"Ole-Morten Duesund","metadata":"{}"},{"issue_id":"forgejo-mcp-broker-t37","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:48:28Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":4,"dependent_count":0,"comment_count":0} -{"id":"forgejo-mcp-broker-9jh","title":"Phase 1: internal/store with SQLite open and embedded schema migrations","description":"Implement internal/store: wraps a modernc.org/sqlite connection, applies embedded schema migrations in order via a schema_migrations table, exposes a *sql.DB and a Close method. Phase 1 schema is just the migrations table itself plus a health_check row — real tables (clients, auth_codes, access_tokens, refresh_tokens) ship in phase 2. Store_path from config; creates parent dirs if missing; fails fast on unwritable path. Migrations embedded via embed.FS under internal/store/migrations/.","acceptance_criteria":"go test ./internal/store passes; opening a fresh db file applies migrations; re-opening is idempotent (no re-application, no errors); corrupt/locked files yield a clear error; Close() leaves no file handles open.","status":"in_progress","priority":1,"issue_type":"task","assignee":"Ole-Morten Duesund","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:19Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T15:11:36Z","started_at":"2026-04-24T15:11:36Z","dependencies":[{"issue_id":"forgejo-mcp-broker-9jh","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:46:19Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":1,"dependent_count":1,"comment_count":0} +{"id":"forgejo-mcp-broker-9jh","title":"Phase 1: internal/store with SQLite open and embedded schema migrations","description":"Implement internal/store: wraps a modernc.org/sqlite connection, applies embedded schema migrations in order via a schema_migrations table, exposes a *sql.DB and a Close method. Phase 1 schema is just the migrations table itself plus a health_check row — real tables (clients, auth_codes, access_tokens, refresh_tokens) ship in phase 2. Store_path from config; creates parent dirs if missing; fails fast on unwritable path. Migrations embedded via embed.FS under internal/store/migrations/.","acceptance_criteria":"go test ./internal/store passes; opening a fresh db file applies migrations; re-opening is idempotent (no re-application, no errors); corrupt/locked files yield a clear error; Close() leaves no file handles open.","status":"closed","priority":1,"issue_type":"task","assignee":"Ole-Morten Duesund","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:19Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T15:22:53Z","started_at":"2026-04-24T15:11:36Z","closed_at":"2026-04-24T15:22:53Z","close_reason":"Store package shipped: modernc.org/sqlite, embed.FS migrations, WAL + FK pragmas, idempotent reopen, 90.1% coverage including bad-SQL rollback and record-step PK conflict.","dependencies":[{"issue_id":"forgejo-mcp-broker-9jh","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:46:19Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":1,"dependent_count":1,"comment_count":0} {"id":"forgejo-mcp-broker-9nq","title":"Phase 1: internal/config package with flag + env parsing and validation","description":"Implement internal/config: a Config struct populated from CLI flags and environment variables (flags win), with validation at startup. Parse public-url, listen addr, forgejo-url, forgejo-oauth-client-id/secret/scopes, forgejo-mcp-binary, store-path, max-sessions, session-idle-timeout, debug. Validation: required fields present and non-empty; public-url parses as an https URL; store-path writable; idle-timeout positive; max-sessions positive. Unit tests cover happy path + every validation error branch.","acceptance_criteria":"go test ./internal/config passes with \u003e=90% coverage; missing required env produces a clear error message listing all missing fields; flag values override env; --help prints all config options.","status":"closed","priority":1,"issue_type":"task","assignee":"Ole-Morten Duesund","owner":"olemd@glemt.net","created_at":"2026-04-24T14:46:19Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T15:10:26Z","started_at":"2026-04-24T15:05:57Z","closed_at":"2026-04-24T15:10:26Z","close_reason":"Config package shipped with 94.1% coverage, handles all required-vs-optional fields, env/flag precedence, URL validation with loopback-http exception, and store-path writability. Full test suite green.","dependencies":[{"issue_id":"forgejo-mcp-broker-9nq","depends_on_id":"forgejo-mcp-broker-n84","type":"blocks","created_at":"2026-04-24T16:46:18Z","created_by":"Ole-Morten Duesund","metadata":"{}"}],"dependency_count":1,"dependent_count":1,"comment_count":0} {"id":"forgejo-mcp-broker-n84","title":"Phase 1: bootstrap Go project layout","description":"Set up the Go project skeleton so all subsequent phase 1 packages have somewhere to live. Initialize go.mod with module path kode.naiv.no/olemd/forgejo-mcp-broker, create the directory layout (cmd/broker, internal/config, internal/log, internal/store, internal/httpserver), add a Makefile with build/test/lint targets, and wire build-info injection (version, git revision, build date) via -ldflags.","acceptance_criteria":"go.mod present with correct module path; make build produces ./fjmcp-broker binary; make test and make lint targets exist and pass against an empty codebase; binary prints --version with injected build info.","status":"closed","priority":1,"issue_type":"task","assignee":"Ole-Morten Duesund","owner":"olemd@glemt.net","created_at":"2026-04-24T14:45:44Z","created_by":"Ole-Morten Duesund","updated_at":"2026-04-24T14:55:39Z","started_at":"2026-04-24T14:50:57Z","closed_at":"2026-04-24T14:55:39Z","close_reason":"Bootstrap complete: go.mod, Makefile, directory layout, ldflags-injected build info, --version flag all working. make build/test/lint pass.","dependency_count":0,"dependent_count":4,"comment_count":0} diff --git a/internal/httpserver/doc.go b/internal/httpserver/doc.go deleted file mode 100644 index 90d2c2d..0000000 --- a/internal/httpserver/doc.go +++ /dev/null @@ -1,6 +0,0 @@ -// Package httpserver hosts the broker's HTTP surface: OAuth endpoints, the -// gated MCP endpoint, and /healthz. Owns an *http.Server with graceful -// shutdown on SIGTERM / SIGINT. -// -// Implementation lands in forgejo-mcp-broker-8ei. -package httpserver diff --git a/internal/httpserver/httpserver.go b/internal/httpserver/httpserver.go new file mode 100644 index 0000000..cb91a2f --- /dev/null +++ b/internal/httpserver/httpserver.go @@ -0,0 +1,164 @@ +// Package httpserver hosts the broker's HTTP surface. In phase 1 that's just +// /healthz; OAuth endpoints and the gated MCP endpoint land in later phases. +// +// The package owns an *http.Server and its lifecycle. Signal handling lives +// in main: the caller passes a context that is canceled on SIGTERM/SIGINT, +// and Run initiates a graceful shutdown with a bounded deadline. +package httpserver + +import ( + "context" + "encoding/json" + "errors" + "fmt" + "log/slog" + "net/http" + "time" + + "kode.naiv.no/olemd/forgejo-mcp-broker/internal/buildinfo" +) + +// DefaultShutdownTimeout is the graceful-shutdown deadline used when +// Server.ShutdownTimeout is zero. +const DefaultShutdownTimeout = 10 * time.Second + +// Pinger reports whether a dependency is still reachable. The store +// implements this; other backends can too. +type Pinger interface { + Ping(ctx context.Context) error +} + +// Server is the broker's HTTP front end. It composes a few well-known +// handlers (/healthz today; OAuth and MCP in later phases) with an optional +// ExtraHandler for routes the server doesn't own natively. +type Server struct { + // Addr is the TCP listen address (e.g. ":8080"). Required. + Addr string + + // Log is the structured logger used for lifecycle and request events. + // Must not be nil. + Log *slog.Logger + + // Store is probed by /healthz. nil means "not configured" (health still + // reports 200 but marks store as unconfigured). + Store Pinger + + // ExtraHandler, if non-nil, receives any request /healthz does not match. + // This is the extension point later phases use to add OAuth and MCP + // routes without forking the server. + ExtraHandler http.Handler + + // ShutdownTimeout bounds how long Run will wait for in-flight requests + // during graceful shutdown. Zero means DefaultShutdownTimeout. + ShutdownTimeout time.Duration +} + +// Handler returns the composed HTTP handler without any listening setup. +// Useful for handler-level tests via httptest.NewRecorder. +func (s *Server) Handler() http.Handler { + mux := http.NewServeMux() + mux.HandleFunc("GET /healthz", s.handleHealth) + if s.ExtraHandler != nil { + // ServeMux treats "/" as the catch-all pattern; specific patterns + // (like "GET /healthz") take precedence in Go 1.22+ routing. + mux.Handle("/", s.ExtraHandler) + } + return mux +} + +// Run starts the HTTP server and blocks until ctx is canceled or the server +// stops on its own. On ctx cancellation, initiates graceful shutdown with +// ShutdownTimeout as the deadline. +func (s *Server) Run(ctx context.Context) error { + if s.Log == nil { + return errors.New("httpserver: Log is required") + } + if s.Addr == "" { + return errors.New("httpserver: Addr is required") + } + + srv := &http.Server{ + Addr: s.Addr, + Handler: s.Handler(), + ReadHeaderTimeout: 10 * time.Second, + } + + serveErr := make(chan error, 1) + go func() { + s.Log.Info("server listening", slog.String("addr", s.Addr)) + err := srv.ListenAndServe() + if errors.Is(err, http.ErrServerClosed) { + err = nil + } + serveErr <- err + }() + + select { + case err := <-serveErr: + return err + case <-ctx.Done(): + s.Log.Info("shutdown initiated", slog.String("cause", ctx.Err().Error())) + } + + timeout := s.ShutdownTimeout + if timeout <= 0 { + timeout = DefaultShutdownTimeout + } + shutdownCtx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + + shutdownErr := srv.Shutdown(shutdownCtx) + if shutdownErr != nil { + // Graceful shutdown timed out. http.Server.Shutdown does not + // interrupt active connections on its own — Close forces the + // sockets closed, which cancels each in-flight request's context + // and lets handlers observe the termination via r.Context().Done(). + s.Log.Error("graceful shutdown exceeded deadline; forcing close", + slog.Duration("deadline", timeout), + slog.String("err", shutdownErr.Error())) + _ = srv.Close() + } + // Wait for ListenAndServe's goroutine to exit so we don't leak it. + <-serveErr + + if shutdownErr != nil { + return fmt.Errorf("shutdown: %w", shutdownErr) + } + s.Log.Info("server stopped") + return nil +} + +type healthResponse struct { + Status string `json:"status"` + Version string `json:"version"` + GitRevision string `json:"git_revision"` + BuildDate string `json:"build_date"` + Store string `json:"store"` +} + +func (s *Server) handleHealth(w http.ResponseWriter, r *http.Request) { + resp := healthResponse{ + Status: "ok", + Version: buildinfo.Version, + GitRevision: buildinfo.GitRevision, + BuildDate: buildinfo.BuildDate, + Store: "not configured", + } + status := http.StatusOK + + if s.Store != nil { + pingCtx, cancel := context.WithTimeout(r.Context(), 2*time.Second) + defer cancel() + if err := s.Store.Ping(pingCtx); err != nil { + resp.Status = "degraded" + resp.Store = "error: " + err.Error() + status = http.StatusServiceUnavailable + } else { + resp.Store = "ok" + } + } + + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(status) + _ = json.NewEncoder(w).Encode(resp) +} diff --git a/internal/httpserver/httpserver_test.go b/internal/httpserver/httpserver_test.go new file mode 100644 index 0000000..71194f3 --- /dev/null +++ b/internal/httpserver/httpserver_test.go @@ -0,0 +1,253 @@ +package httpserver_test + +import ( + "context" + "encoding/json" + "errors" + "io" + "net" + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" + "time" + + "kode.naiv.no/olemd/forgejo-mcp-broker/internal/httpserver" + brokerlog "kode.naiv.no/olemd/forgejo-mcp-broker/internal/log" +) + +// fakePinger implements httpserver.Pinger for /healthz tests. +type fakePinger struct{ err error } + +func (f *fakePinger) Ping(context.Context) error { return f.err } + +func TestHealth_OK(t *testing.T) { + s := &httpserver.Server{Log: brokerlog.Discard(), Store: &fakePinger{}} + req := httptest.NewRequest(http.MethodGet, "/healthz", nil) + w := httptest.NewRecorder() + s.Handler().ServeHTTP(w, req) + + if w.Code != http.StatusOK { + t.Errorf("status = %d, want %d", w.Code, http.StatusOK) + } + var resp map[string]string + if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil { + t.Fatalf("body not JSON: %v", err) + } + for _, k := range []string{"status", "version", "git_revision", "build_date", "store"} { + if resp[k] == "" { + t.Errorf("healthz response missing field %q: %v", k, resp) + } + } + if resp["status"] != "ok" { + t.Errorf("status = %q, want ok", resp["status"]) + } + if resp["store"] != "ok" { + t.Errorf("store = %q, want ok", resp["store"]) + } +} + +func TestHealth_DegradedOnStoreFailure(t *testing.T) { + s := &httpserver.Server{Log: brokerlog.Discard(), Store: &fakePinger{err: errors.New("boom")}} + w := httptest.NewRecorder() + s.Handler().ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/healthz", nil)) + + if w.Code != http.StatusServiceUnavailable { + t.Errorf("status = %d, want %d", w.Code, http.StatusServiceUnavailable) + } + if !strings.Contains(w.Body.String(), "degraded") { + t.Errorf("body should mark status as degraded: %s", w.Body.String()) + } + if !strings.Contains(w.Body.String(), "boom") { + t.Errorf("body should include underlying error: %s", w.Body.String()) + } +} + +func TestHealth_NoStoreConfigured(t *testing.T) { + s := &httpserver.Server{Log: brokerlog.Discard()} + w := httptest.NewRecorder() + s.Handler().ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/healthz", nil)) + + if w.Code != http.StatusOK { + t.Errorf("status = %d, want 200 when store is unconfigured", w.Code) + } + if !strings.Contains(w.Body.String(), "not configured") { + t.Errorf("expected 'not configured' marker: %s", w.Body.String()) + } +} + +func TestHandler_WrongMethodIsRejected(t *testing.T) { + // Go 1.22+ mux: POST /healthz should not dispatch to the GET handler. + s := &httpserver.Server{Log: brokerlog.Discard()} + w := httptest.NewRecorder() + s.Handler().ServeHTTP(w, httptest.NewRequest(http.MethodPost, "/healthz", nil)) + if w.Code != http.StatusMethodNotAllowed { + t.Errorf("POST /healthz should return 405, got %d", w.Code) + } +} + +func TestHandler_ExtraHandlerReceivesOtherPaths(t *testing.T) { + extra := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = io.WriteString(w, "extra:"+r.URL.Path) + }) + s := &httpserver.Server{Log: brokerlog.Discard(), ExtraHandler: extra} + w := httptest.NewRecorder() + s.Handler().ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/other", nil)) + if !strings.Contains(w.Body.String(), "extra:/other") { + t.Errorf("extra handler not invoked, got %q", w.Body.String()) + } +} + +func TestRun_ShutdownOnContextCancel(t *testing.T) { + addr := freeAddr(t) + s := &httpserver.Server{Addr: addr, Log: brokerlog.Discard(), Store: &fakePinger{}} + + ctx, cancel := context.WithCancel(t.Context()) + runErr := make(chan error, 1) + go func() { runErr <- s.Run(ctx) }() + + // Wait for the listener to be ready. + waitReady(t, addr, 2*time.Second) + + // Sanity: /healthz works while running. + resp, err := http.Get("http://" + addr + "/healthz") + if err != nil { + t.Fatalf("pre-shutdown GET: %v", err) + } + _ = resp.Body.Close() + + // Cancel the context to simulate SIGTERM. + start := time.Now() + cancel() + + select { + case err := <-runErr: + if err != nil { + t.Errorf("Run returned error: %v", err) + } + if elapsed := time.Since(start); elapsed > 2*time.Second { + t.Errorf("Run took %s to shut down, want < 2s", elapsed) + } + case <-time.After(3 * time.Second): + t.Fatal("Run did not return within 3s of cancel") + } +} + +func TestRun_ShutdownTimeout_ForciblyClosesSlowRequests(t *testing.T) { + addr := freeAddr(t) + + // An extra handler that blocks until the test releases it — simulates + // a slow in-flight request that outlives the shutdown deadline. + release := make(chan struct{}) + startedServing := make(chan struct{}) + var once sync.Once + extra := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + once.Do(func() { close(startedServing) }) + select { + case <-release: + case <-r.Context().Done(): + } + }) + + s := &httpserver.Server{ + Addr: addr, + Log: brokerlog.Discard(), + ExtraHandler: extra, + ShutdownTimeout: 200 * time.Millisecond, + } + + ctx, cancel := context.WithCancel(t.Context()) + runErr := make(chan error, 1) + go func() { runErr <- s.Run(ctx) }() + waitReady(t, addr, 2*time.Second) + + // Fire a request that will hang in the handler. + reqDone := make(chan error, 1) + go func() { + resp, err := http.Get("http://" + addr + "/slow") + if resp != nil { + _ = resp.Body.Close() + } + reqDone <- err + }() + + <-startedServing // handler is blocking + cancel() // shutdown fires; handler won't return voluntarily + + select { + case err := <-runErr: + // Shutdown should complete (with an error reporting deadline breach) + // within about the timeout + small wiggle. + if err == nil { + t.Logf("Run returned nil — http.Server closed the conn via ctx.Done() cascade; acceptable") + } else if !strings.Contains(err.Error(), "shutdown") { + t.Errorf("unexpected Run error: %v", err) + } + case <-time.After(2 * time.Second): + t.Fatal("Run did not return within 2s of cancel") + } + + // The hanging request's conn should have been forcibly closed. + select { + case err := <-reqDone: + if err == nil { + t.Error("slow request should have been terminated by shutdown") + } + case <-time.After(2 * time.Second): + t.Fatal("slow request did not terminate after shutdown") + } + + // Drain the handler so no goroutine leaks past the test. + close(release) +} + +func TestRun_MissingFieldsErr(t *testing.T) { + cases := []struct { + name string + server *httpserver.Server + want string + }{ + {"no_log", &httpserver.Server{Addr: ":0"}, "Log"}, + {"no_addr", &httpserver.Server{Log: brokerlog.Discard()}, "Addr"}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + err := tc.server.Run(t.Context()) + if err == nil || !strings.Contains(err.Error(), tc.want) { + t.Errorf("want error containing %q, got %v", tc.want, err) + } + }) + } +} + +// freeAddr returns a loopback "host:port" with a port chosen by the kernel. +// The listener is closed immediately, so there is a tiny race window before +// the caller rebinds — acceptable for loopback test use. +func freeAddr(t *testing.T) string { + t.Helper() + l, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen: %v", err) + } + addr := l.Addr().String() + _ = l.Close() + return addr +} + +// waitReady polls the target address until a TCP dial succeeds or the +// deadline expires. +func waitReady(t *testing.T, addr string, within time.Duration) { + t.Helper() + deadline := time.Now().Add(within) + for time.Now().Before(deadline) { + c, err := net.DialTimeout("tcp", addr, 50*time.Millisecond) + if err == nil { + _ = c.Close() + return + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("server not reachable at %s within %s", addr, within) +} + diff --git a/internal/log/doc.go b/internal/log/doc.go deleted file mode 100644 index da7abee..0000000 --- a/internal/log/doc.go +++ /dev/null @@ -1,6 +0,0 @@ -// Package log constructs the process-wide structured logger (log/slog, JSON -// handler to stderr) and provides small helpers for attaching build-info and -// request-scoped fields. -// -// Implementation lands alongside forgejo-mcp-broker-8ei / t37. -package log diff --git a/internal/log/log.go b/internal/log/log.go new file mode 100644 index 0000000..eb1170a --- /dev/null +++ b/internal/log/log.go @@ -0,0 +1,32 @@ +// Package log constructs the process-wide structured logger. +// +// Every record carries the broker's build info so aggregated log backends can +// correlate events across versions and deployments. +package log + +import ( + "io" + "log/slog" + + "kode.naiv.no/olemd/forgejo-mcp-broker/internal/buildinfo" +) + +// New returns a JSON slog.Logger writing to w. When debug is true the +// logger starts at Debug level, otherwise at Info. +func New(w io.Writer, debug bool) *slog.Logger { + level := slog.LevelInfo + if debug { + level = slog.LevelDebug + } + h := slog.NewJSONHandler(w, &slog.HandlerOptions{Level: level}) + return slog.New(h).With( + slog.String("service", "fjmcp-broker"), + slog.String("version", buildinfo.Version), + slog.String("git_rev", buildinfo.GitRevision), + ) +} + +// Discard returns a logger that drops every record. Useful in tests. +func Discard() *slog.Logger { + return slog.New(slog.DiscardHandler) +} diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 0000000..f889a2c --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,55 @@ +package log_test + +import ( + "bytes" + "encoding/json" + "strings" + "testing" + + brokerlog "kode.naiv.no/olemd/forgejo-mcp-broker/internal/log" +) + +func TestNew_WritesJSON(t *testing.T) { + var buf bytes.Buffer + l := brokerlog.New(&buf, false) + l.Info("hello", "key", "value") + + var rec map[string]any + if err := json.Unmarshal(buf.Bytes(), &rec); err != nil { + t.Fatalf("output is not valid JSON: %v\ngot: %s", err, buf.String()) + } + if rec["msg"] != "hello" { + t.Errorf("msg = %v, want hello", rec["msg"]) + } + if rec["service"] != "fjmcp-broker" { + t.Errorf("service = %v, want fjmcp-broker", rec["service"]) + } + if rec["key"] != "value" { + t.Errorf("key = %v, want value", rec["key"]) + } +} + +func TestNew_DebugSuppressedByDefault(t *testing.T) { + var buf bytes.Buffer + l := brokerlog.New(&buf, false) + l.Debug("debug-only") + if buf.Len() > 0 { + t.Errorf("debug record should be suppressed at info level, got: %s", buf.String()) + } +} + +func TestNew_DebugIncludedWhenEnabled(t *testing.T) { + var buf bytes.Buffer + l := brokerlog.New(&buf, true) + l.Debug("debug-enabled") + if !strings.Contains(buf.String(), "debug-enabled") { + t.Errorf("debug record missing with debug=true, got: %s", buf.String()) + } +} + +func TestDiscard_NoOutput(t *testing.T) { + l := brokerlog.Discard() + l.Info("ignored") + l.Error("also ignored") + // Nothing to assert except that these calls don't panic. +}