From c5785340bb0a6b36f8f5c9209ab41eff3a92c759 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 16 Oct 2026 16:41:49 +0000 Subject: [PATCH 1/3] Port the service skeleton from standalone: config, logger, errors, gin router, container (T16) - cmd/server: signals, errgroup, one report per failure, a stop during the start exits 0; the port is bound before the startup line. - internal/config: viper over declared CANVAS_* variables only; CANVAS_ENV local by default and prod-only where K_SERVICE is set; the shutdown budget shared between drain and close. - internal/logger, internal/apierror: Cloud Run keys; flat {code, message} with optional details. - internal/transport/http: gin router, /health on GET and HEAD, 404 and 405 as apierror, LastResort, SecurityHeaders, RequestID (X-Request-Id), request log and panic recovery. - internal/app: hand-written container closing in reverse order, also on a start that fails halfway; the server with its drain. - Terraform sets CANVAS_ENV=prod; spec 8.3 and 15.4; .env.example, launch.json, THIRD_PARTY_LICENSES; RUN.md T16 done. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01U1MCDC5QUpgX5xmPSJYn5W --- .env.example | 36 + .vscode/launch.json | 19 +- RUN.md | 25 +- THIRD_PARTY_LICENSES | 33 + cmd/server/main.go | 249 +++---- cmd/server/main_test.go | 512 +++++++------ docs/spec.md | 8 +- go.mod | 50 ++ go.sum | 126 ++++ infra/terraform/service_api.tf | 7 + .../terraform/tests/configuration.tftest.hcl | 5 + internal/apierror/apierror.go | 31 + internal/apierror/apierror_test.go | 80 +++ internal/app/app_test.go | 302 ++++++++ internal/app/container.go | 91 +++ internal/app/container_internal_test.go | 111 +++ internal/app/server.go | 139 ++++ internal/app/server_internal_test.go | 122 ++++ internal/config/config.go | 270 +++++++ internal/config/config_test.go | 246 +++++++ internal/logger/logger.go | 120 ++++ internal/logger/logger_test.go | 212 ++++++ internal/logger/panic.go | 70 ++ internal/logger/panic_test.go | 82 +++ internal/logger/request.go | 22 + internal/logger/request_test.go | 20 + internal/transport/http/health.go | 32 + internal/transport/http/middleware/logger.go | 98 +++ .../http/middleware/middleware_test.go | 673 ++++++++++++++++++ internal/transport/http/middleware/probe.go | 22 + .../transport/http/middleware/recovery.go | 116 +++ .../transport/http/middleware/requestid.go | 98 +++ .../middleware/requestid_internal_test.go | 115 +++ internal/transport/http/middleware/route.go | 49 ++ .../transport/http/middleware/security.go | 20 + internal/transport/http/router.go | 69 ++ internal/transport/http/router_test.go | 202 ++++++ 37 files changed, 4081 insertions(+), 401 deletions(-) create mode 100644 .env.example create mode 100644 go.sum create mode 100644 internal/apierror/apierror.go create mode 100644 internal/apierror/apierror_test.go create mode 100644 internal/app/app_test.go create mode 100644 internal/app/container.go create mode 100644 internal/app/container_internal_test.go create mode 100644 internal/app/server.go create mode 100644 internal/app/server_internal_test.go create mode 100644 internal/config/config.go create mode 100644 internal/config/config_test.go create mode 100644 internal/logger/logger.go create mode 100644 internal/logger/logger_test.go create mode 100644 internal/logger/panic.go create mode 100644 internal/logger/panic_test.go create mode 100644 internal/logger/request.go create mode 100644 internal/logger/request_test.go create mode 100644 internal/transport/http/health.go create mode 100644 internal/transport/http/middleware/logger.go create mode 100644 internal/transport/http/middleware/middleware_test.go create mode 100644 internal/transport/http/middleware/probe.go create mode 100644 internal/transport/http/middleware/recovery.go create mode 100644 internal/transport/http/middleware/requestid.go create mode 100644 internal/transport/http/middleware/requestid_internal_test.go create mode 100644 internal/transport/http/middleware/route.go create mode 100644 internal/transport/http/middleware/security.go create mode 100644 internal/transport/http/router.go create mode 100644 internal/transport/http/router_test.go diff --git a/.env.example b/.env.example new file mode 100644 index 0000000..f20901a --- /dev/null +++ b/.env.example @@ -0,0 +1,36 @@ +# The service's variables, with the values a developer's machine runs with. +# Every value here is also the one the service assumes when the variable is +# unset, except where a line says otherwise. +# +# Copy this file to .env and change what you need: .env is never committed. +# Nothing reads .env by itself — the service reads its environment only — so +# export it into the shell before `just run`: +# +# set -a; . ./.env; set +a; just run +# +# The debugger's configurations in .vscode/launch.json set their own values. + +# The port the server listens on. Cloud Run sets it on every revision. +PORT=8080 + +# local or prod. Local switches on what development alone may do; Cloud Run, +# where K_SERVICE is set, refuses to start as local. +CANVAS_ENV=local + +# debug, info, warn or error. +CANVAS_LOG_LEVEL=info + +# json for a log collector, console to read by eye. The service assumes json +# when unset, and refuses console where K_SERVICE is set. +CANVAS_LOG_FORMAT=console + +# How long the server waits for each part of a request, and how long it keeps +# an idle connection open. +CANVAS_HTTP_READ_HEADER_TIMEOUT=5s +CANVAS_HTTP_READ_TIMEOUT=30s +CANVAS_HTTP_WRITE_TIMEOUT=60s +CANVAS_HTTP_IDLE_TIMEOUT=120s + +# The whole way out once a stop is asked for: three quarters for the requests +# in flight, a quarter for closing what the service ran on. +CANVAS_SHUTDOWN_TIMEOUT=9s diff --git a/.vscode/launch.json b/.vscode/launch.json index ddba4bc..d42bf9b 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -9,7 +9,24 @@ "mode": "debug", "program": "${workspaceFolder}/cmd/server", "env": { - "PORT": "8080" + "PORT": "8080", + "CANVAS_ENV": "local", + "CANVAS_LOG_LEVEL": "debug", + "CANVAS_LOG_FORMAT": "console" + } + }, + { + "name": "Run the server as Cloud Run sees it", + "type": "go", + "request": "launch", + "mode": "debug", + "program": "${workspaceFolder}/cmd/server", + "env": { + "PORT": "8080", + "K_SERVICE": "canvas-api", + "CANVAS_ENV": "prod", + "CANVAS_LOG_LEVEL": "info", + "CANVAS_LOG_FORMAT": "json" } }, { diff --git a/RUN.md b/RUN.md index 06d0f99..3fbc383 100644 --- a/RUN.md +++ b/RUN.md @@ -142,7 +142,7 @@ |---|---|---|---|---|---| | [x] | T61 | Документы: журнал решений и CLAUDE.md | Claude, проверяю я | — | — | | [x] | T62 | Документы: product, privacy, spec, stack | Claude, проверяю я | — | T61 | -| [ ] | T16 | Каркас сервиса | Claude | — | T61 | +| [x] | T16 | Каркас сервиса | Claude | — | T61 | | [ ] | T63 | Terraform: провайдеры 8.7.0 | Claude | — | — | | [ ] | T64 | Облако E2: секрет ключа, Agent Platform, бюджет | Claude | да | T63 | | [ ] | T65 | Доступ: CORS и ключ | Claude | да | T16, T64 | @@ -546,6 +546,29 @@ - строки лога — JSON с `severity`; - после мержа CD выкатывает каркас, `/health` отвечает релизом и коммитом. - **Не делать:** телеметрию — E15 (черновик T17); protobuf — T18; CORS и ключ — T65. +- **Решено автором (2026-10-16):** `CANVAS_ENV` по умолчанию `local`, при `K_SERVICE` — только `prod`, и Terraform ставит его; в spec 8.3 добавлены `INTERNAL_ERROR` (500) и `METHOD_NOT_ALLOWED` (405) — их отвечают паника и неразрешённый метод. +- **Сделано (2026-10-16):** образец — `mathtrail-standalone` на коммите c6cbeb2, склонированный только для чтения: в облачной сессии нет `reference/`. + - **Перенесено из образца:** + - `cmd/server/main.go` — `signalled`, `run`, `exitCode`, ошибка, которую записал лог, печатается один раз, остановка во время старта — выход 0, `errgroup`. Строка `startup` пишется zap и называет `version`, `commit`, `date`, `port`, `env`, `deployed`. В отличие от образца порт занимается до неё: занятый порт — сбой старта, а не `shutdown`; + - `internal/app` — `server.go` целиком: тайм-ауты, drain — 3/4 пути остановки, обрыв запросов по сроку — предупреждение, а не сбой. `container.go` — `Config`, `Logger`, `Router` и закрытие в обратном порядке; сборка идёт списком шагов, и сбой шага закрывает уже построенное на отдельном контексте; + - `internal/config` — viper, только объявленные ключи, пустое значение — незаданное, `Validate()` называет переменную. Переменные — `PORT`, `CANVAS_ENV`, `CANVAS_LOG_LEVEL`, `CANVAS_LOG_FORMAT`, `CANVAS_HTTP_*_TIMEOUT`, `CANVAS_SHUTDOWN_TIMEOUT`, `K_SERVICE`; + - `internal/logger` — без изменений, кроме модуля и примеров в тестах; + - `internal/apierror` — `{code, message}` и `details` с `omitempty`; коды `NOT_FOUND`, `METHOD_NOT_ALLOWED`, `INTERNAL_ERROR`. Остальные коды E2 придут с T18, T65 и T70; + - `internal/transport/http` на gin — роутер, `/health` на GET и HEAD, 404 и 405 телом `apierror`; middleware в порядке образца: `LastResort`, `SecurityHeaders`, `RequestID`, `ZapLogger`, `ZapRecovery`. + - **Отличия от образца:** нет телеметрии, метрик, лимитов, проверки `Host` и `Origin`, полей query в логе и продуктовых маршрутов; заголовок — `X-Request-Id`, как в spec 8.1; `CANVAS_ENV` и его защита при `K_SERVICE` — своё; при `K_SERVICE` `CANVAS_SHUTDOWN_TIMEOUT` меньше 10 с — Cloud Run убивает экземпляр через 10 с после SIGTERM. Косвенные модули подняты до версий образца. + - **Облако:** `CANVAS_ENV=prod` в `service_api.tf` и тест `terraform test` на него. + - **Ещё:** `.env.example`, `.vscode/launch.json` — локальный запуск и «как видит Cloud Run», `THIRD_PARTY_LICENSES`, spec 8.3 и 15.4. + - **Проверки** (облачная сессия; `just`, golangci-lint 2.14.0 и Terraform 1.16.3 скачаны по закреплённым версиям): зелёные `ci-lint`, `ci-test` (покрытие 97,6 %), `ci-mocks-check`, `ci-secrets`, `release-version`, `release-artifacts`, `terraform fmt -check`. Вживую: `/health` отвечает версией и коммитом, 404 и 405 — телом `apierror`, каждый ответ несёт `X-Request-Id`, строки лога — JSON с `severity`; с `K_SERVICE` и без `CANVAS_ENV=prod` сервис не стартует. + - **Выключены, чтобы доказать тесты, — 16 проверок, каждая краснила свой тест:** `local` и `console` при `K_SERVICE`, неизвестный `CANVAS_ENV`, предел `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании, имя переменной в точном регистре, `PORT` только цифрами, закрытие при сбое сборки, отдельный контекст закрытия, обратный порядок, `RequestID` в цепочке, `HEAD /health`, 405, порт до строки `startup`, сброс заголовков обработчика при панике, алфавит и длина `X-Request-Id` под fuzz. + - **Fuzz:** `FuzzRequestID` — заголовок `X-Request-Id`, единственный внешний ввод каркаса, — 60 с, без находок. Правило id в нём записано отдельно от кода: первая версия сверяла id тем же `usableRequestID` и пропустила ослабленное правило. + - **Ревью `/code-review high`, два круга.** + - Первый — 9 находок. Исправлено 6: `.env.example` обещал, что `.env` прочтут, — теперь сказано, как его загрузить; занятый порт писался как сбой `shutdown` после строки `startup` — порт теперь занимается до неё; тесты `run()` зависели от переменных оболочки — они их обнуляют; `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании ограничен 10 с; повтор перехвата stdout в тесте заменён помощником; нет fuzz на `X-Request-Id` — добавлен. Отброшено 3: верхняя граница теста drain — тест о самих часах ставит свои сроки, как и в образце; 5-секундные сторожа ожиданий — предел для событий, которые занимают миллисекунды, а не мера скорости кода; список шагов контейнера — его требует задача (закрытие при сбое посередине), следующий ресурс принесёт T35. + - Второй — 8 находок. Исправлено 5: ответ на панику нёс заголовки обработчика; имена переменных сравнивались без учёта регистра; `PORT` принимал `+8080` и `08080`; комментарий `Listen` называл вызов только тестовым; у четырёх полей тайм-аутов не было doc-комментариев. Отброшено 1: список шагов контейнера — повтор находки первого круга. В «Открыто» — 2, ниже. +- **Открыто:** + - `http.Server.ErrorLog` не задан, как и в образце: свои ошибки net/http пишет в stderr простым текстом, без `severity`, и в них бывает адрес клиента. Предлагаю `zap.NewStdLog` с правилом для адреса в задаче, которая вводит таблицу событий лога (T70); + - `freePort` в тестах `main` освобождает порт до того, как `run` его займёт, как и в образце: другой процесс может занять его в этом окне. Флейка не было; лечится, если `run` начнёт принимать готовый listener; + - не запускались — сеть сессии их не пускает: `tf-check` (реестр Terraform), `ci-vuln` (vuln.go.dev), сверка `ci-licenses` со списком (ссылки на тексты лицензий пяти модулей с vanity-адресами взяты из списка образца — версии те же); без демона Docker — `ci-image-smoke`, `ci-image-scan`, `ci-workflows`. Их прогонит CI на PR; + - описания правил depguard в `.golangci.yml` ещё называют порты `Recognizer` и `Tutor` — поправит T35 вместе с портом (долг Д23). - **Разделы:** spec 8.1–8.3, 15.4, 16, 18; R11, R30; standalone: R18, R19, R74, R77. #### T63. Terraform: провайдеры 8.7.0 diff --git a/THIRD_PARTY_LICENSES b/THIRD_PARTY_LICENSES index 7765934..f5665b6 100644 --- a/THIRD_PARTY_LICENSES +++ b/THIRD_PARTY_LICENSES @@ -9,6 +9,39 @@ builds them, listed as std. Each line is a license, what it covers, and the text of that license at the exact version that is built. BSD-3-Clause std https://github.com/golang/go/blob/go1.27.2/LICENSE +BSD-3-Clause github.com/fsnotify/fsnotify https://github.com/fsnotify/fsnotify/blob/v1.9.0/LICENSE +MIT github.com/gabriel-vasile/mimetype https://github.com/gabriel-vasile/mimetype/blob/v1.4.15/LICENSE +MIT github.com/gin-contrib/sse https://github.com/gin-contrib/sse/blob/v1.1.2/LICENSE +MIT github.com/gin-gonic/gin https://github.com/gin-gonic/gin/blob/v1.12.0/LICENSE +MIT github.com/go-playground/locales https://github.com/go-playground/locales/blob/v0.14.2/LICENSE +MIT github.com/go-playground/universal-translator https://github.com/go-playground/universal-translator/blob/v0.18.2/LICENSE +MIT github.com/go-playground/validator/v10 https://github.com/go-playground/validator/blob/v10.30.5/LICENSE +MIT github.com/go-viper/mapstructure/v2 https://github.com/go-viper/mapstructure/blob/v2.5.0/LICENSE +MIT github.com/goccy/go-yaml https://github.com/goccy/go-yaml/blob/v1.19.2/LICENSE +BSD-3-Clause github.com/google/uuid https://github.com/google/uuid/blob/v1.6.0/LICENSE +MIT github.com/leodido/go-urn https://github.com/leodido/go-urn/blob/v1.5.0/LICENSE +MIT github.com/mattn/go-isatty https://github.com/mattn/go-isatty/blob/v0.0.24/LICENSE +MIT github.com/pelletier/go-toml/v2 https://github.com/pelletier/go-toml/blob/v2.4.3/LICENSE +MIT github.com/quic-go/qpack https://github.com/quic-go/qpack/blob/v0.6.0/LICENSE.md +MIT github.com/quic-go/quic-go https://github.com/quic-go/quic-go/blob/v0.63.0/LICENSE +MIT github.com/sagikazarmark/locafero https://github.com/sagikazarmark/locafero/blob/v0.11.0/LICENSE +MIT github.com/sourcegraph/conc https://github.com/sourcegraph/conc/blob/5f936abd7ae8/LICENSE +Apache-2.0 github.com/spf13/afero https://github.com/spf13/afero/blob/v1.15.0/LICENSE.txt +MIT github.com/spf13/cast https://github.com/spf13/cast/blob/v1.10.0/LICENSE +BSD-3-Clause github.com/spf13/pflag https://github.com/spf13/pflag/blob/v1.0.10/LICENSE +MIT github.com/spf13/viper https://github.com/spf13/viper/blob/v1.21.0/LICENSE +MIT github.com/subosito/gotenv https://github.com/subosito/gotenv/blob/v1.6.0/LICENSE +MIT github.com/ugorji/go/codec https://github.com/ugorji/go/blob/codec/v1.3.2/codec/LICENSE +Apache-2.0 go.mongodb.org/mongo-driver/v2 https://github.com/mongodb/mongo-go-driver/blob/v2.9.1/LICENSE +MIT go.uber.org/multierr https://github.com/uber-go/multierr/blob/v1.10.0/LICENSE.txt +MIT go.uber.org/zap https://github.com/uber-go/zap/blob/v1.28.0/LICENSE +MIT go.yaml.in/yaml/v3 https://github.com/yaml/go-yaml/blob/v3.0.5/LICENSE +BSD-3-Clause golang.org/x/crypto https://cs.opensource.google/go/x/crypto/+/v0.57.0:LICENSE +BSD-3-Clause golang.org/x/net https://cs.opensource.google/go/x/net/+/v0.60.0:LICENSE +BSD-3-Clause golang.org/x/sync/errgroup https://cs.opensource.google/go/x/sync/+/v0.23.0:LICENSE +BSD-3-Clause golang.org/x/sys https://cs.opensource.google/go/x/sys/+/v0.48.0:LICENSE +BSD-3-Clause golang.org/x/text https://cs.opensource.google/go/x/text/+/v0.42.0:LICENSE +BSD-3-Clause google.golang.org/protobuf https://github.com/protocolbuffers/protobuf-go/blob/v1.36.12/LICENSE The npm packages below are what the SPA is built from: every package its lockfile needs outside development, and every package one of those names diff --git a/cmd/server/main.go b/cmd/server/main.go index fd344e9..e13b153 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -1,180 +1,149 @@ -// Command server runs canvas-api: one process on the one port Cloud Run gives -// it, answering the health probe and stopping gracefully when asked to. +// Command server runs canvas-api: one process, one port, and no +// state of its own between requests. package main import ( "context" - "encoding/json" + "errors" "fmt" "io" - "net" - "net/http" "os" "os/signal" "syscall" - "time" - "github.com/MathTrail/canvas-api/internal/version" -) + "github.com/gin-gonic/gin" + "go.uber.org/zap" + "golang.org/x/sync/errgroup" -// defaultPort is served when PORT is unset. Cloud Run always sets PORT, so -// this is the port of a run on a developer's machine. -const defaultPort = "8080" - -// The server's timeouts, every one of them set: a client that stalls while -// sending its request, or while reading the answer, must not hold its -// connection for as long as it likes. -const ( - readHeaderTimeout = 5 * time.Second - readTimeout = 30 * time.Second - writeTimeout = 60 * time.Second - idleTimeout = 120 * time.Second + "github.com/MathTrail/canvas-api/internal/app" + "github.com/MathTrail/canvas-api/internal/config" + "github.com/MathTrail/canvas-api/internal/logger" + "github.com/MathTrail/canvas-api/internal/version" ) -// shutdownTimeout is how long a stop waits for the requests in flight. Cloud -// Run kills an instance ten seconds after its SIGTERM, so the wait ends a -// second sooner, while the process can still exit on its own. -const shutdownTimeout = 9 * time.Second - +// main owns the two things a process owns and a function should not: the +// signals it listens for and the code it exits with. Everything else is run, +// which stops because its context was cancelled and says so by returning. func main() { ctx, stop := signalled() - err := run(ctx, listenAddr(), os.Stdout) + err := run(ctx) stop() - if err != nil { - fmt.Fprintf(os.Stderr, "canvas-api: %v\n", err) - os.Exit(1) + // The exit is the last statement of the process on purpose: os.Exit runs + // no deferred call, so nothing may be left to one after this point. + os.Exit(exitCode(os.Stderr, err)) +} + +// exitCode is the code the process exits with once run has returned err, and +// it prints the one failure nobody else will have: a failure the log has +// recorded is not printed again, and one from before there was a log has +// nowhere else to go. +func exitCode(stderr io.Writer, err error) int { + if err == nil { + return 0 } + if !errors.Is(err, errLogged) { + fmt.Fprintf(stderr, "canvas-api: %v\n", err) + } + return 1 } -// signalled is a context that ends when a stop is asked for: SIGTERM is how -// Cloud Run asks, SIGINT is Ctrl-C at a terminal. Once one has arrived, both -// go back to what they do by default, so a second signal ends the process at -// once instead of waiting out the drain. +// signalled is a context that ends when a stop is asked for, by either of the +// signals that ask for one. One signal asks; a second ends the process at once. +// Once the first has arrived the signals go back to what they do by default, +// rather than being caught for the whole of the way out, which can take +// seconds nobody pressing Ctrl-C twice means to wait. func signalled() (context.Context, context.CancelFunc) { ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) context.AfterFunc(ctx, stop) return ctx, stop } -// listenAddr is every interface, on the port PORT names or on defaultPort. -func listenAddr() string { - port := os.Getenv("PORT") - if port == "" { - port = defaultPort +// errLogged marks a failure the log has already recorded, so that it is +// reported once. +var errLogged = errors.New("logged") + +// logged writes a failure to the log under the name of the moment it happened +// at, and marks it as written. +func logged(log *zap.Logger, moment string, err error) error { + log.Error(moment, zap.Error(err)) + return fmt.Errorf("%w: %s: %w", errLogged, moment, err) +} + +// startupFailed is what run returns when the service could not be built. A +// build cut short by the stop that was asked for is that stop, not a failure: +// a platform may take an instance away while it is still starting, and doing +// so is no fault of the instance. Anything else is a failure, and is written +// down as one. +func startupFailed(ctx context.Context, log *zap.Logger, err error) error { + if ctx.Err() != nil && errors.Is(err, context.Canceled) { + log.Info("shutdown", zap.Bool("started", false)) + return nil } - return net.JoinHostPort("", port) + return logged(log, "startup", err) } -// run serves the service on addr until ctx ends, and says on log which build -// it is once the port is its own. It takes the port before it serves, so a -// port that is already in use is reported as the failure it is, even when a -// stop arrives at the same moment. -func run(ctx context.Context, addr string, log io.Writer) error { - var lc net.ListenConfig - listener, err := lc.Listen(ctx, "tcp", addr) +// run starts the service, serves until ctx is cancelled and closes it again. +// Every deferred call runs on the way out, which is why nothing here calls +// os.Exit. +func run(ctx context.Context) error { + // The configuration is read before anything else exists, so a service that + // is configured wrongly says so and exits instead of half-starting. + cfg, err := config.Load() if err != nil { - return fmt.Errorf("listen: %w", err) + return err } - announce(log, listener.Addr()) - return serve(ctx, newServer(), listener) -} -// startup is the one line the service logs until it gets a logger of its -// own: which build is starting, and where it listens. Its first keys are the -// ones Cloud Logging reads a structured entry by and the logger will write, so -// that a deployment's log names the release and the commit it runs. -type startup struct { - Severity string `json:"severity"` - Message string `json:"message"` - Time string `json:"time"` - Version string `json:"version"` - Commit string `json:"commit"` - Date string `json:"date"` - Address string `json:"address"` -} + log, err := logger.New(cfg.LogLevel, cfg.LogFormat) + if err != nil { + return err + } + defer func() { _ = log.Sync() }() -// announce writes the startup line for a server that listens on addr. A line -// that cannot be written is no reason to stop serving: the platform logs every -// request, and the probe names the build all the same. -func announce(log io.Writer, addr net.Addr) { - _ = json.NewEncoder(log).Encode(startup{ - Severity: "INFO", - Message: "startup", - Time: time.Now().UTC().Format(time.RFC3339Nano), - Version: version.Version, - Commit: version.Commit, - Date: version.Date, - Address: addr.String(), - }) -} + // The web framework keeps its mode in a package variable, so it belongs + // where the process is set up rather than inside whatever builds a router. + gin.SetMode(gin.ReleaseMode) -// newServer is the service's HTTP server: its routes, and every timeout set. -func newServer() *http.Server { - return &http.Server{ - Handler: routes(), - ReadHeaderTimeout: readHeaderTimeout, - ReadTimeout: readTimeout, - WriteTimeout: writeTimeout, - IdleTimeout: idleTimeout, + container, err := app.NewContainer(ctx, cfg, log) + if err != nil { + return startupFailed(ctx, log, err) } -} - -// serve runs server on listener until ctx ends, then stops it gracefully: the -// server takes no new connections, and the requests in flight get -// shutdownTimeout to finish. -func serve(ctx context.Context, server *http.Server, listener net.Listener) error { - served := make(chan error, 1) - go func() { served <- server.Serve(listener) }() - - select { - case err := <-served: - // Nothing asked the server to stop, so whatever stopped it is a failure. - return fmt.Errorf("serve: %w", err) - case <-ctx.Done(): + // Deferred, so that the container is closed on every way out of here. It + // gets the share of the way out the server's drain always leaves it. + defer func() { + closing, cancel := context.WithTimeout(context.WithoutCancel(ctx), cfg.CloseTimeout()) + defer cancel() + container.Close(closing) + }() + + // The port is taken before the service says it has started, so that a port + // already in use is the failed start it is, and the startup line never + // names a port the process does not hold. + server := app.NewServer(container) + if err := server.Listen(ctx); err != nil { + return startupFailed(ctx, log, err) } - // ctx has ended already, so the drain gets a deadline of its own, and it - // starts now rather than when the signal arrived. - drain, cancel := context.WithTimeout(context.WithoutCancel(ctx), shutdownTimeout) - defer cancel() - if err := server.Shutdown(drain); err != nil { - return fmt.Errorf("shutdown: %w", err) + // The delivery's checklist finds the release a revision runs by this line, + // its message and its version and commit. + log.Info("startup", + zap.String("version", version.Version), + zap.String("commit", version.Commit), + zap.String("date", version.Date), + zap.String("port", cfg.Port), + zap.String("env", cfg.Env), + zap.Bool("deployed", cfg.Deployed()), + ) + + // Everything that runs for the life of the process shares one group: when + // one part fails, the others are told to stop, and the deferred close runs + // only after all of them have. + group, groupCtx := errgroup.WithContext(ctx) + group.Go(func() error { return server.Run(groupCtx) }) + + if err := group.Wait(); err != nil && !errors.Is(err, context.Canceled) { + return logged(log, "shutdown", err) } + log.Info("shutdown") return nil } - -// routes is every path the service answers; any other is not found. -func routes() http.Handler { - mux := http.NewServeMux() - // /health rather than /healthz: Cloud Run's front end intercepts paths - // that end in z. - mux.HandleFunc("GET /health", health) - return mux -} - -// healthBody is what the probe answers. It is a type rather than a map so that -// the shape of the answer is stated once, and a mistyped key is a compile -// error rather than a field nobody notices is missing. -type healthBody struct { - Status string `json:"status"` - Version string `json:"version"` - Commit string `json:"commit"` -} - -// health says the process is up and serving, and which build it is: the -// delivery reads the commit here to know that the revision it rolled out is -// the one that answers, so no cache on the way may answer for it. It -// checks nothing else on purpose: a probe that reached for a dependency would -// turn that dependency's outage into restarts of this service. -func health(w http.ResponseWriter, _ *http.Request) { - w.Header().Set("Cache-Control", "no-store") - w.Header().Set("Content-Type", "application/json") - // A body that cannot be written means the caller has gone, and nobody is - // left to tell. - _ = json.NewEncoder(w).Encode(healthBody{ - Status: "ok", - Version: version.Version, - Commit: version.Commit, - }) -} diff --git a/cmd/server/main_test.go b/cmd/server/main_test.go index c23e8d3..6ddf66b 100644 --- a/cmd/server/main_test.go +++ b/cmd/server/main_test.go @@ -2,271 +2,286 @@ package main import ( "bufio" + "bytes" "context" "encoding/json" "errors" "fmt" "io" - "maps" "net" - "net/http" - "net/http/httptest" "os" "os/exec" "os/signal" - "strings" - "sync" + "strconv" "syscall" "testing" "time" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/MathTrail/canvas-api/internal/config" "github.com/MathTrail/canvas-api/internal/version" ) -// The service answers its health probe and nothing else. /healthz is not the -// probe, and HEAD is answered wherever GET is, since a probe may ask -// either way. -func TestRoutes(t *testing.T) { - t.Parallel() - - for _, tc := range []struct { - name string - method string - path string - want int - }{ - {name: "the health probe", method: http.MethodGet, path: "/health", want: http.StatusOK}, - {name: "the health probe asked with HEAD", method: http.MethodHead, path: "/health", want: http.StatusOK}, - {name: "the path Cloud Run intercepts", method: http.MethodGet, path: "/healthz", want: http.StatusNotFound}, - {name: "an unknown path", method: http.MethodGet, path: "/unknown", want: http.StatusNotFound}, - } { - t.Run(tc.name, func(t *testing.T) { - t.Parallel() - - rec := httptest.NewRecorder() - req := httptest.NewRequestWithContext(t.Context(), tc.method, tc.path, http.NoBody) - newServer().Handler.ServeHTTP(rec, req) +// run must stop because its context was cancelled — the same way a signal +// reaches it — and it must stop without an error. +func TestRunStopsWhenContextIsCancelled(t *testing.T) { + ownEnvironment(t) + port := freePort(t) + t.Setenv("PORT", port) + t.Setenv("CANVAS_LOG_LEVEL", "error") + t.Setenv("CANVAS_SHUTDOWN_TIMEOUT", "2s") - if rec.Code != tc.want { - t.Errorf("%s %s status = %d, want %d", tc.method, tc.path, rec.Code, tc.want) - } - }) - } -} - -// The probe names the build that answers it, and nothing on the way may keep -// the answer: the delivery reads the commit to know which revision serves. -func TestHealthNamesTheBuild(t *testing.T) { - stamp(t) + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- run(ctx) }() - rec := httptest.NewRecorder() - req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/health", http.NoBody) - newServer().Handler.ServeHTTP(rec, req) + // Cancel only once the service is actually listening, so that a pass + // means "it started and then stopped" rather than "it never started". + waitUntilListening(t, port) + cancel() - if rec.Code != http.StatusOK { - t.Fatalf("GET /health status = %d, want %d", rec.Code, http.StatusOK) - } - for header, want := range map[string]string{ - "Cache-Control": "no-store", - "Content-Type": "application/json", - } { - if got := rec.Header().Get(header); got != want { - t.Errorf("%s = %q, want %q", header, got, want) + select { + case err := <-stopped: + if err != nil { + t.Fatalf("run() error = %v, want nil", err) } - } - var body map[string]string - if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { - t.Fatalf("the body is not a JSON object of strings: %v; body = %s", err, rec.Body.String()) - } - want := map[string]string{"status": "ok", "version": "v1.2.3", "commit": "abc1234"} - if !maps.Equal(body, want) { - t.Errorf("body = %v, want %v", body, want) + case <-time.After(10 * time.Second): + t.Fatal("run() did not return within 10s of the context being cancelled") } } -// Once the port is its own, the server says which build it is and where it -// listens, in the one line a deployment's log names its release and its -// commit by; a stop then ends it as usual. -func TestRunAnnouncesTheBuildItStarts(t *testing.T) { - stamp(t) - - said, log := io.Pipe() - t.Cleanup(func() { _ = said.Close() }) - ctx, stop := context.WithCancel(t.Context()) - defer stop() - started := time.Now() - stopped := make(chan error, 1) - go func() { stopped <- run(ctx, "127.0.0.1:0", log) }() +// Once it serves, the service says which build it is in the line the +// delivery's checklist reads a revision's release by: JSON a collector reads +// the severity of, with the message startup, the version and the commit. +func TestTheStartupLineNamesTheBuild(t *testing.T) { + ownEnvironment(t) + was := [3]string{version.Version, version.Commit, version.Date} + version.Version, version.Commit, version.Date = "v1.2.3", "abc1234", "2026-10-12T00:00:00Z" + t.Cleanup(func() { version.Version, version.Commit, version.Date = was[0], was[1], was[2] }) + port := freePort(t) + t.Setenv("PORT", port) + t.Setenv("CANVAS_SHUTDOWN_TIMEOUT", "2s") - first := make(chan string, 1) - go func() { - lines := bufio.NewScanner(said) - lines.Scan() - first <- lines.Text() - }() - var line string - select { - case line = <-first: - case err := <-stopped: - t.Fatalf("run() returned %v before it said which build it is", err) - case <-time.After(5 * time.Second): - t.Fatal("waited 5s for the startup line") - } - heard := time.Now() - stop() - if err := receive(t, stopped, "run() to return"); err != nil { - t.Errorf("run() error = %v, want nil", err) + lines := capturedStdout(t) + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- run(ctx) }() + waitUntilListening(t, port) + cancel() + if err := <-stopped; err != nil { + t.Fatalf("run() error = %v, want nil", err) } - var got map[string]string - if err := json.Unmarshal([]byte(line), &got); err != nil { - t.Fatalf("the startup line is not a JSON object of strings: %v; line = %s", err, line) - } - if !strings.HasPrefix(got["address"], "127.0.0.1:") { - t.Errorf("address = %q, want the loopback address it listens on", got["address"]) + var startup map[string]any + for line := range bytes.Lines(lines()) { + var entry map[string]any + if err := json.Unmarshal(line, &entry); err != nil { + t.Fatalf("a line of the log is not JSON: %v; line = %s", err, line) + } + if entry["message"] == "startup" { + startup = entry + } } - if at, err := time.Parse(time.RFC3339Nano, got["time"]); err != nil || at.Before(started) || at.After(heard) { - t.Errorf("time = %q, want the moment of the line in RFC 3339, between %v and %v", got["time"], started, heard) + if startup == nil { + t.Fatal("no startup line in the log") } - delete(got, "address") - delete(got, "time") - want := map[string]string{ + for key, want := range map[string]any{ "severity": "INFO", - "message": "startup", "version": "v1.2.3", "commit": "abc1234", "date": "2026-10-12T00:00:00Z", - } - if !maps.Equal(got, want) { - t.Errorf("the startup line = %v, want %v and the address", got, want) + "port": port, + "env": "local", + "deployed": false, + } { + if startup[key] != want { + t.Errorf("startup[%q] = %v, want %v", key, startup[key], want) + } } } -// Every timeout of the server is set. -func TestEveryTimeoutIsSet(t *testing.T) { - t.Parallel() +// ownEnvironment clears every variable the service reads, so that what the +// shell running the tests exported — a console log format, a K_SERVICE — does +// not decide the outcome. An empty value counts as unset. +func ownEnvironment(t *testing.T) { + t.Helper() - server := newServer() - for _, timeout := range []struct { - name string - value time.Duration - }{ - {name: "ReadHeaderTimeout", value: server.ReadHeaderTimeout}, - {name: "ReadTimeout", value: server.ReadTimeout}, - {name: "WriteTimeout", value: server.WriteTimeout}, - {name: "IdleTimeout", value: server.IdleTimeout}, + for _, name := range []string{ + "PORT", "K_SERVICE", "CANVAS_ENV", "CANVAS_LOG_LEVEL", "CANVAS_LOG_FORMAT", + "CANVAS_HTTP_READ_HEADER_TIMEOUT", "CANVAS_HTTP_READ_TIMEOUT", "CANVAS_HTTP_WRITE_TIMEOUT", + "CANVAS_HTTP_IDLE_TIMEOUT", "CANVAS_SHUTDOWN_TIMEOUT", } { - if timeout.value <= 0 { - t.Errorf("%s = %v, want a positive duration", timeout.name, timeout.value) - } + t.Setenv(name, "") } } -// The port is the one PORT names, as Cloud Run sets it, or 8080 when PORT is -// empty; the host is empty, so every interface is served. -func TestListenAddr(t *testing.T) { - for _, tc := range []struct { - port string - want string - }{ - {port: "", want: ":8080"}, - {port: "9090", want: ":9090"}, - } { - t.Run("PORT="+tc.port, func(t *testing.T) { - t.Setenv("PORT", tc.port) +// capturedStdout sends what the process writes to stdout into a pipe until the +// returned function is called, which hands back everything written. +func capturedStdout(t *testing.T) func() []byte { + t.Helper() - if got := listenAddr(); got != tc.want { - t.Errorf("listenAddr() = %q, want %q", got, tc.want) - } - }) + read, write, err := os.Pipe() + if err != nil { + t.Fatalf("os.Pipe() error = %v, want nil", err) + } + t.Cleanup(func() { _ = read.Close() }) + written := make(chan []byte, 1) + go func() { + all, _ := io.ReadAll(read) + written <- all + }() + stdout := os.Stdout + os.Stdout = write + t.Cleanup(func() { os.Stdout = stdout }) + return func() []byte { + os.Stdout = stdout + _ = write.Close() + return <-written } } -// A stop lets the request in flight finish: the request the server is already -// handling when the stop begins still gets its answer, and serve then returns -// without an error. -func TestServeStopsGracefully(t *testing.T) { - t.Parallel() +// A failure is reported once: in the log, as one line a collector reads the +// severity of, and marked as written so that the process does not print it a +// second time on its way out. +func TestAFailureIsReportedOnce(t *testing.T) { + ownEnvironment(t) + var lc net.ListenConfig + taken, err := lc.Listen(t.Context(), "tcp", ":0") + if err != nil { + t.Fatalf("listen for a port to take: %v", err) + } + t.Cleanup(func() { _ = taken.Close() }) + addr, ok := taken.Addr().(*net.TCPAddr) + if !ok { + t.Fatalf("listener address = %T, want *net.TCPAddr", taken.Addr()) + } + t.Setenv("PORT", strconv.Itoa(addr.Port)) - arrived, release := make(chan struct{}), make(chan struct{}) - releaseHandler := sync.OnceFunc(func() { close(release) }) - t.Cleanup(releaseHandler) // a test that fails early must not leave the handler waiting - server := newServer() - server.Handler = http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { - close(arrived) - <-release - w.WriteHeader(http.StatusOK) - }) - stopping := make(chan struct{}) - server.RegisterOnShutdown(func() { close(stopping) }) - - listener := listen(t) - ctx, cancel := context.WithCancel(t.Context()) - stopped := make(chan error, 1) - go func() { stopped <- serve(ctx, server, listener) }() - answered := make(chan error, 1) - go func() { answered <- getOK(t.Context(), "http://"+listener.Addr().String()+"/") }() + lines := capturedStdout(t) + err = run(t.Context()) + written := lines() - receive(t, arrived, "the request to reach the handler") - cancel() - receive(t, stopping, "the graceful stop to begin") - releaseHandler() + if !errors.Is(err, errLogged) { + t.Fatalf("run() error = %v, want the taken port reported and marked as logged", err) + } + var failures, starts int + for line := range bytes.Lines(written) { + var entry map[string]any + if err := json.Unmarshal(line, &entry); err != nil { + t.Fatalf("a line of the log is not JSON: %v; line = %s", err, line) + } + switch { + case entry["severity"] == "ERROR" && entry["message"] == "startup": + failures++ + case entry["severity"] == "ERROR": + t.Errorf("an error line = %s, want the failure named startup: the start is what failed", line) + case entry["message"] == "startup": + starts++ + } + } + // A port the process never held is a start that failed, written once, and + // no line says the service started on it. + if failures != 1 || starts != 0 { + t.Errorf("the log has %d failed starts and %d announced ones, want 1 and 0:\n%s", failures, starts, written) + } +} - if err := receive(t, answered, "the answer to the request in flight"); err != nil { - t.Errorf("the request in flight: %v, want its 200", err) +// A configuration it cannot satisfy is reported, not worked around: nothing is +// started and the error says which variable is wrong. +func TestRunRefusesBadConfiguration(t *testing.T) { + ownEnvironment(t) + t.Setenv("PORT", "eighty") + + err := run(t.Context()) + if !errors.Is(err, config.ErrInvalid) { + t.Fatalf("run() error = %v, want it to wrap config.ErrInvalid", err) } - if err := receive(t, stopped, "serve() to return"); err != nil { - t.Errorf("serve() error = %v, want nil", err) + // There is no log yet to have written it, so it is the process that + // reports it. + if errors.Is(err, errLogged) { + t.Errorf("run() error = %v, want it left for the process to print", err) } } -// A server that stops serving on its own is a failure: serve returns it at -// once, rather than waiting for a stop that nobody has asked for. -func TestServeReportsAServerThatStoppedOnItsOwn(t *testing.T) { +// The process exits with 1 whenever run failed, and prints a failure only when +// nothing else has reported it: the one the log recorded stays a single line, +// and the one from before there was a log has nowhere else to go. +func TestAFailureIsPrintedOnlyWhenTheLogDidNotRecordIt(t *testing.T) { t.Parallel() - listener := listen(t) - _ = listener.Close() // the server's first Accept fails, and nothing asked it to stop - - stopped := make(chan error, 1) - go func() { stopped <- serve(t.Context(), newServer(), listener) }() + refused := fmt.Errorf("%w: PORT must be a number from 1 to 65535", config.ErrInvalid) + for _, tc := range []struct { + name string + err error + code int + printed string + }{ + {name: "a stop that was asked for", err: nil, code: 0, printed: ""}, + {name: "a failure from before there was a log", err: refused, code: 1, + printed: "canvas-api: " + refused.Error() + "\n"}, + {name: "a failure the log recorded", err: logged(zap.NewNop(), "startup", refused), code: 1, printed: ""}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() - if err := receive(t, stopped, "serve() to return"); !errors.Is(err, net.ErrClosed) { - t.Errorf("serve() error = %v, want the closed listener reported", err) + var stderr bytes.Buffer + if code := exitCode(&stderr, tc.err); code != tc.code { + t.Errorf("exitCode() = %d, want %d", code, tc.code) + } + if printed := stderr.String(); printed != tc.printed { + t.Errorf("printed %q, want %q", printed, tc.printed) + } + }) } } -// A port that is already taken is reported as the failure it is, even when a -// stop is asked for at the same moment: run takes the port before it serves. -func TestRunReportsATakenPort(t *testing.T) { +// A stop asked for while the service is still being built ends the process as +// the stop it is, with nothing written as an error. A failure of the build is +// a failure even when a stop arrived beside it, and so is a cancellation that +// nobody asked this process for. +func TestAStopDuringTheStartIsNoFailure(t *testing.T) { t.Parallel() - taken := listen(t).Addr().String() + stopped, stop := context.WithCancel(t.Context()) + stop() + cutShort := fmt.Errorf("app: build the router: %w", context.Canceled) + broken := errors.New("app: a piece could not be built") + for _, tc := range []struct { - name string - stopAsked bool + name string + ctx context.Context + err error + failed bool + errorLines int }{ - {name: "no stop asked for", stopAsked: false}, - {name: "a stop asked for at the same moment", stopAsked: true}, + {name: "the build cut short by the stop", ctx: stopped, err: cutShort, failed: false, errorLines: 0}, + {name: "a build that failed while a stop arrived", ctx: stopped, err: broken, failed: true, errorLines: 1}, + {name: "a cancellation nobody asked for", ctx: t.Context(), err: cutShort, failed: true, errorLines: 1}, } { t.Run(tc.name, func(t *testing.T) { t.Parallel() - ctx, stop := context.WithCancel(t.Context()) - defer stop() - if tc.stopAsked { - stop() - } + core, logs := observer.New(zapcore.DebugLevel) + err := startupFailed(tc.ctx, zap.New(core), tc.err) - if err := run(ctx, taken, io.Discard); !errors.Is(err, syscall.EADDRINUSE) { - t.Errorf("run() error = %v, want the port reported in use", err) + if errors.Is(err, errLogged) != tc.failed { + t.Errorf("startupFailed() = %v, want a failure: %v", err, tc.failed) + } + if lines := logs.FilterLevelExact(zapcore.ErrorLevel).Len(); lines != tc.errorLines { + t.Errorf("error lines = %d, want %d", lines, tc.errorLines) + } + if !tc.failed && err != nil { + t.Errorf("startupFailed() = %v, want nil for the stop that was asked for", err) } }) } } // Either signal a stop arrives by ends the context: the interrupt of a person -// at a terminal, and the termination Cloud Run sends before it takes an +// at a terminal, and the termination a platform sends before it takes an // instance away. The signal is sent to this test binary itself. func TestEitherStopSignalEndsTheContext(t *testing.T) { self, err := os.FindProcess(os.Getpid()) @@ -290,21 +305,61 @@ func TestEitherStopSignalEndsTheContext(t *testing.T) { if err := self.Signal(sig); err != nil { t.Fatalf("send %v: %v", sig, err) } - receive(t, ctx.Done(), "the context to end") + select { + case <-ctx.Done(): + case <-time.After(10 * time.Second): + t.Fatalf("the context is still live 10s after %v, want it ended", sig) + } }) } } +// freePort asks the kernel for a port and gives it straight back, so the test +// binds a port nobody else is using rather than a number somebody guessed. +func freePort(t *testing.T) string { + t.Helper() + + var lc net.ListenConfig + listener, err := lc.Listen(t.Context(), "tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen for a free port: %v", err) + } + addr, ok := listener.Addr().(*net.TCPAddr) + if !ok { + t.Fatalf("listener address = %T, want *net.TCPAddr", listener.Addr()) + } + if err := listener.Close(); err != nil { + t.Fatalf("close the probe listener: %v", err) + } + return strconv.Itoa(addr.Port) +} + +func waitUntilListening(t *testing.T, port string) { + t.Helper() + + var dialer net.Dialer + deadline := time.Now().Add(10 * time.Second) + for time.Now().Before(deadline) { + conn, err := dialer.DialContext(t.Context(), "tcp", net.JoinHostPort("127.0.0.1", port)) + if err == nil { + _ = conn.Close() + return + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("nothing is listening on port %s after 10s", port) +} + // signalHelper names the variable that makes this test binary, started again // by the test below, play a process on its way out instead of testing. const signalHelper = "CANVAS_TEST_SIGNAL_HELPER" // A second signal ends the process at once, whatever it is still doing: the -// first asked for a stop, and the drain can take seconds that nobody pressing -// Ctrl-C twice means to wait. The process is this test binary again, asked to -// stop and then stuck on its way out; a signal after that has to end it. -// Signals are sent until it ends or ten seconds pass, because the moment the -// first one stops being caught is the process's own. +// first asked for a stop, and the way out can take seconds that nobody +// pressing Ctrl-C twice means to wait. The process is this test binary again, +// asked to stop and then stuck on its way out; a signal after that has to end +// it. Signals are sent until it ends or ten seconds pass, because the moment +// the first one stops being caught is the process's own. func TestASecondSignalEndsTheProcess(t *testing.T) { if os.Getenv(signalHelper) == "1" { ctx, _ := signalled() @@ -314,7 +369,6 @@ func TestASecondSignalEndsTheProcess(t *testing.T) { time.Sleep(time.Minute) // a way out that does not end by itself return } - t.Parallel() child := exec.CommandContext(t.Context(), os.Args[0], "-test.run=^TestASecondSignalEndsTheProcess$") child.Env = append(os.Environ(), signalHelper+"=1") @@ -349,64 +403,6 @@ func TestASecondSignalEndsTheProcess(t *testing.T) { } } -// stamp sets the build identity as the linker would, and puts the placeholders -// back when the test ends. The identity is the whole process's, so a test that -// stamps it does not run in parallel: the parallel tests wait until it is over. -func stamp(t *testing.T) { - t.Helper() - - was := [3]string{version.Version, version.Commit, version.Date} - version.Version, version.Commit, version.Date = "v1.2.3", "abc1234", "2026-10-12T00:00:00Z" - t.Cleanup(func() { version.Version, version.Commit, version.Date = was[0], was[1], was[2] }) -} - -// listen takes a free loopback port and holds it until the test ends, so that -// a test hands over a port it already has rather than one it hopes is free. -func listen(t *testing.T) net.Listener { - t.Helper() - - var lc net.ListenConfig - listener, err := lc.Listen(t.Context(), "tcp", "127.0.0.1:0") - if err != nil { - t.Fatalf("listen on a free port: %v", err) - } - t.Cleanup(func() { _ = listener.Close() }) - return listener -} - -// receive waits up to five seconds for what ch delivers, and fails the test, -// naming what it waited for, if nothing comes. -func receive[T any](t *testing.T, ch <-chan T, what string) T { - t.Helper() - - select { - case v := <-ch: - return v - case <-time.After(5 * time.Second): - t.Fatalf("waited 5s for %s", what) - } - var zero T - return zero -} - -// getOK asks for url and says what went wrong unless the answer is 200. It -// runs beside the test, so it reports rather than failing the test itself. -func getOK(ctx context.Context, url string) error { - req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, http.NoBody) - if err != nil { - return err - } - resp, err := http.DefaultClient.Do(req) - if err != nil { - return err - } - _ = resp.Body.Close() - if resp.StatusCode != http.StatusOK { - return fmt.Errorf("status %d", resp.StatusCode) - } - return nil -} - // endedBySignal says whether a process that ended with err was ended by a // signal rather than by returning. func endedBySignal(err error) bool { diff --git a/docs/spec.md b/docs/spec.md index 31d0d1f..1946d0d 100644 --- a/docs/spec.md +++ b/docs/spec.md @@ -663,12 +663,14 @@ Previous questions on this sheet: none | `NOT_IN_BETA` | 403 | инвайт-код беты не погашен (О-11) | | `REAUTH_REQUIRED` | 401 | нужен свежий вход: `auth_time` старше 5 минут | | `NOT_FOUND` | 404 | ресурса нет | +| `METHOD_NOT_ALLOWED` | 405 | путь есть, но не принимает этот метод; заголовок `Allow` называет те, что принимает | | `INVALID_ARGUMENT` | 400 | ошибка в теле запроса, в том числе картинка проверки не прошла проверку 4.3 | | `PAYLOAD_TOO_LARGE` | 413 | тело больше предела (раздел 13) или картинка проверки больше своего предела (4.3) | | `CHECK_IN_PROGRESS` | 409 | на холсте уже идёт проверка — эта же или другая (R42). Клиент повторяет через паузу (8.4); ребёнку это не показывается | | `CANVAS_CLOSED` | 409 | холст не активен: задача на нём решена или для неё начат новый холст. SPA перечитывает холст (8.2) и показывает задачу решённой или предлагает начать заново | | `LIMIT_EXCEEDED` | 429 | лимит частоты или числа детей. Дневной лимит проверок **не** даёт 429: он даёт вердикт `UNCHECKED` с причиной `limit` (5.4, 14.5) | | `UNAVAILABLE` | 503 | Neon или OpenFGA недоступны. После аренды — если не удалась запись в базу: проверку доводит повтор, когда истечёт аренда (8.4) | +| `INTERNAL_ERROR` | 500 | паника обработчика или middleware: ответ без подробностей, что и где упало — в строке лога запроса | Сбой Gemini или внутренняя ошибка после аренды **не** дают ошибку HTTP: проверка получает вердикт `UNCHECKED` или запасной текст подсказки (5.4, 5.5, 6.3). Исключение — сама база: без неё результат не записать. @@ -1854,7 +1856,11 @@ infra/terraform/ | Переменная | Пример | Секрет | |---|---|---| -| `CANVAS_ENV` | `prod` | нет | +| `PORT` | `8080`; в Cloud Run его ставит платформа | нет | +| `CANVAS_ENV` | `prod`; по умолчанию `local`. При `K_SERVICE` сервис стартует только с `prod`: Terraform ставит его в `service_api.tf` | нет | +| `CANVAS_LOG_LEVEL`, `CANVAS_LOG_FORMAT` | `info`, `json` (умолчания). `console` — только локально: при `K_SERVICE` сервис с ним не стартует | нет | +| `CANVAS_HTTP_READ_HEADER_TIMEOUT`, `CANVAS_HTTP_READ_TIMEOUT`, `CANVAS_HTTP_WRITE_TIMEOUT`, `CANVAS_HTTP_IDLE_TIMEOUT` | `5s`, `30s`, `60s`, `120s` (умолчания) | нет | +| `CANVAS_SHUTDOWN_TIMEOUT` | `9s` (умолчание): весь путь остановки — 3/4 на запросы в полёте, 1/4 на закрытие ресурсов; Cloud Run убивает экземпляр через 10 с после SIGTERM | нет | | `CANVAS_ALLOWED_ORIGINS` | `https://mathtrail-canvas-prod.web.app` (R55) | нет | | `CANVAS_FIREBASE_PROJECT_ID` | `mathtrail-canvas-prod` | нет | | `CANVAS_DATABASE_URL` | `postgres://…/canvas?sslmode=require` | да | diff --git a/go.mod b/go.mod index eac42ce..d24e3eb 100644 --- a/go.mod +++ b/go.mod @@ -7,3 +7,53 @@ go 1.27.2 // lint them as packages of this module. GO_FILES in the justfile and the // pre-commit hook keep gofmt out of node_modules in the same way. ignore node_modules + +require ( + github.com/gin-gonic/gin v1.12.0 + github.com/google/uuid v1.6.0 + github.com/spf13/viper v1.21.0 + go.uber.org/zap v1.28.0 + golang.org/x/sync v0.23.0 +) + +require ( + github.com/bytedance/gopkg v0.1.4 // indirect + github.com/bytedance/sonic v1.15.4 // indirect + github.com/bytedance/sonic/loader v0.5.2 // indirect + github.com/cloudwego/base64x v0.1.7 // indirect + github.com/fsnotify/fsnotify v1.9.0 // indirect + github.com/gabriel-vasile/mimetype v1.4.15 // indirect + github.com/gin-contrib/sse v1.1.2 // indirect + github.com/go-playground/locales v0.14.2 // indirect + github.com/go-playground/universal-translator v0.18.2 // indirect + github.com/go-playground/validator/v10 v10.30.5 // indirect + github.com/go-viper/mapstructure/v2 v2.5.0 // indirect + github.com/goccy/go-json v0.11.2 // indirect + github.com/goccy/go-yaml v1.19.2 // indirect + github.com/json-iterator/go v1.1.12 // indirect + github.com/klauspost/cpuid/v2 v2.4.0 // indirect + github.com/leodido/go-urn v1.5.0 // indirect + github.com/mattn/go-isatty v0.0.24 // indirect + github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect + github.com/modern-go/reflect2 v1.0.2 // indirect + github.com/pelletier/go-toml/v2 v2.4.3 // indirect + github.com/quic-go/qpack v0.6.0 // indirect + github.com/quic-go/quic-go v0.63.0 // indirect + github.com/sagikazarmark/locafero v0.11.0 // indirect + github.com/sourcegraph/conc v0.3.1-0.20240121214520-5f936abd7ae8 // indirect + github.com/spf13/afero v1.15.0 // indirect + github.com/spf13/cast v1.10.0 // indirect + github.com/spf13/pflag v1.0.10 // indirect + github.com/subosito/gotenv v1.6.0 // indirect + github.com/twitchyliquid64/golang-asm v0.15.1 // indirect + github.com/ugorji/go/codec v1.3.2 // indirect + go.mongodb.org/mongo-driver/v2 v2.9.1 // indirect + go.uber.org/multierr v1.10.0 // indirect + go.yaml.in/yaml/v3 v3.0.5 // indirect + golang.org/x/arch v0.31.0 // indirect + golang.org/x/crypto v0.57.0 // indirect + golang.org/x/net v0.60.0 // indirect + golang.org/x/sys v0.48.0 // indirect + golang.org/x/text v0.42.0 // indirect + google.golang.org/protobuf v1.36.12 // indirect +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..edd68d6 --- /dev/null +++ b/go.sum @@ -0,0 +1,126 @@ +github.com/bytedance/gopkg v0.1.4 h1:oZnQwnX82KAIWb7033bEwtxvTqXcYMxDBaQxo5JJHWM= +github.com/bytedance/gopkg v0.1.4/go.mod h1:v1zWfPm21Fb+OsyXN2VAHdL6TBb2L88anLQgdyje6R4= +github.com/bytedance/sonic v1.15.4 h1:FgtV/4aBHpla9AxuMpuuzVUpa/Cf3izufkxNmnEzdI8= +github.com/bytedance/sonic v1.15.4/go.mod h1:8e51yTPdY8M6t+vvGL1c2Y1xL9i+frEeIAQAEl75NUc= +github.com/bytedance/sonic/loader v0.5.2 h1:0QtP1gevc1OZ6/H8Lb9BRZiCXd1Ftjd3OKuj1T1lBIo= +github.com/bytedance/sonic/loader v0.5.2/go.mod h1:AR4NYCk5DdzZizZ5djGqQ92eEhCCcdf5x77udYiSJRo= +github.com/cloudwego/base64x v0.1.7 h1:NppS+Fgzg5ovhn4NkUXaDT3x9jldgH5ToMCqzBSi2zI= +github.com/cloudwego/base64x v0.1.7/go.mod h1:Cu1PV9zfrSf7ET2tIbWbbEy7jO7HHJ13q4X2SQ8aWYg= +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/frankban/quicktest v1.14.6 h1:7Xjx+VpznH+oBnejlPUj8oUpdxnVs4f8XU8WnHkI4W8= +github.com/frankban/quicktest v1.14.6/go.mod h1:4ptaffx2x8+WTWXmUCuVU6aPUX1/Mz7zb5vbUoiM6w0= +github.com/fsnotify/fsnotify v1.9.0 h1:2Ml+OJNzbYCTzsxtv8vKSFD9PbJjmhYF14k/jKC7S9k= +github.com/fsnotify/fsnotify v1.9.0/go.mod h1:8jBTzvmWwFyi3Pb8djgCCO5IBqzKJ/Jwo8TRcHyHii0= +github.com/gabriel-vasile/mimetype v1.4.15 h1:05iP/CYtZ/w455R/KZM6rZ5ieAdh99UPtd+d3YzLmaI= +github.com/gabriel-vasile/mimetype v1.4.15/go.mod h1:azpTcoLcDZRNgFou5j+APrqQx9HqVPWa6ijYQIIVswQ= +github.com/gin-contrib/sse v1.1.2 h1:MU2fgl1RrdYTMcgJLtz2kJF+vPg3xrqaaKfUUU18tCo= +github.com/gin-contrib/sse v1.1.2/go.mod h1:QXzuVkA0YO7o/gun03UI1Q+FTI8ZV/n5t03kIQAI89s= +github.com/gin-gonic/gin v1.12.0 h1:b3YAbrZtnf8N//yjKeU2+MQsh2mY5htkZidOM7O0wG8= +github.com/gin-gonic/gin v1.12.0/go.mod h1:VxccKfsSllpKshkBWgVgRniFFAzFb9csfngsqANjnLc= +github.com/go-playground/assert/v2 v2.2.0 h1:JvknZsQTYeFEAhQwI4qEt9cyV5ONwRHC+lYKSsYSR8s= +github.com/go-playground/assert/v2 v2.2.0/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4= +github.com/go-playground/locales v0.14.2 h1:d8UmcrM6Nip0hfGZKLGpAvZH37XB4TS0xzK9B56YNCY= +github.com/go-playground/locales v0.14.2/go.mod h1:hxrqLVvrK65+Rwrd5Fc6F2O76J/NuW9t0sjnWqG1slY= +github.com/go-playground/universal-translator v0.18.2 h1:LCsMLC9RzmbUMNUPVYD15dmcjwYAJhmX8mPZRW4rAVU= +github.com/go-playground/universal-translator v0.18.2/go.mod h1:67VZIMp5lQpDWlnStOct22q1bkdJGJqHghbOtmkawxk= +github.com/go-playground/validator/v10 v10.30.5 h1:YyCXvVShZbs2Sm3Mb53eNOlhRXctSOzW5QJAouCTZL4= +github.com/go-playground/validator/v10 v10.30.5/go.mod h1:wEqiaov48pXX1kjhc3Da8y0M0Dtg/BK7gurFBLgwFrQ= +github.com/go-viper/mapstructure/v2 v2.5.0 h1:vM5IJoUAy3d7zRSVtIwQgBj7BiWtMPfmPEgAXnvj1Ro= +github.com/go-viper/mapstructure/v2 v2.5.0/go.mod h1:oJDH3BJKyqBA2TXFhDsKDGDTlndYOZ6rGS0BRZIxGhM= +github.com/goccy/go-json v0.11.2 h1:jdZv93Tt4ioR8yW1CoNsvSxrcZlCXAUU1aZXN7gpXUA= +github.com/goccy/go-json v0.11.2/go.mod h1:3NdmfEkZlB7YI5UFw/qdFKq8XN1aiWR0YyRPWZNQltY= +github.com/goccy/go-yaml v1.19.2 h1:PmFC1S6h8ljIz6gMRBopkjP1TVT7xuwrButHID66PoM= +github.com/goccy/go-yaml v1.19.2/go.mod h1:XBurs7gK8ATbW4ZPGKgcbrY1Br56PdM69F7LkFRi1kA= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM= +github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHmT4TnhNGBo= +github.com/klauspost/cpuid/v2 v2.4.0 h1:S6Hrbc7+ywsr0r+RLapfGBHfyefhCTwEh3A0tV913Dw= +github.com/klauspost/cpuid/v2 v2.4.0/go.mod h1:19jmZ9mjzoF//ddRSUsv0zfBTJWh3QJh9FNxZTMrGxU= +github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= +github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= +github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= +github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= +github.com/leodido/go-urn v1.5.0 h1:pLqT2kq1zpHW/1D18QMjMpdtX7cekxqtJJjg5ANyWw0= +github.com/leodido/go-urn v1.5.0/go.mod h1:9BORnCDhdPBJNDEX+w1bJisa8yOKYi116VeO96s4ifE= +github.com/mattn/go-isatty v0.0.24 h1:tGZZoVgT/KiqK1c8ocVLeDS8BSWMRd47J3Lbz7vsReI= +github.com/mattn/go-isatty v0.0.24/go.mod h1:nMCL3Zebbrt45jsMDgnfIwz6ydEQApk5oEI3HqDio6A= +github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q= +github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd h1:TRLaZ9cD/w8PVh93nsPXa1VrQ6jlwL5oN8l14QlcNfg= +github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q= +github.com/modern-go/reflect2 v1.0.2 h1:xBagoLtFs94CBntxluKeaWgTMpvLxC4ur3nMaC9Gz0M= +github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk= +github.com/pelletier/go-toml/v2 v2.4.3 h1:GTRvJQutkOSftxIFD5xw9aepkYNuPWmVJpffdDPYVpY= +github.com/pelletier/go-toml/v2 v2.4.3/go.mod h1:2gIqNv+qfxSVS7cM2xJQKtLSTLUE9V8t9Stt+h56mCY= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/quic-go/go-ossfuzz-seeds v0.1.0 h1:APacT+iIaNF6fd8AGEiN3bT/Jtkd2jz4v4TzM7MFjy0= +github.com/quic-go/go-ossfuzz-seeds v0.1.0/go.mod h1:3IOHRbJIc+L6YKMwfDtJAM9Vj9k0YY4muhuyUYk5tbk= +github.com/quic-go/qpack v0.6.0 h1:g7W+BMYynC1LbYLSqRt8PBg5Tgwxn214ZZR34VIOjz8= +github.com/quic-go/qpack v0.6.0/go.mod h1:lUpLKChi8njB4ty2bFLX2x4gzDqXwUpaO1DP9qMDZII= +github.com/quic-go/quic-go v0.63.0 h1:LIFGHI4PFUhhw2dDD1ARHdCff143ffMHwZtbnbuJ78A= +github.com/quic-go/quic-go v0.63.0/go.mod h1:RAro2j2yN9a9EiPACLHT9IB2NXCvGQmmo/alT0yYI0w= +github.com/rogpeppe/go-internal v1.9.0 h1:73kH8U+JUqXU8lRuOHeVHaa/SZPifC7BkcraZVejAe8= +github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs= +github.com/sagikazarmark/locafero v0.11.0 h1:1iurJgmM9G3PA/I+wWYIOw/5SyBtxapeHDcg+AAIFXc= +github.com/sagikazarmark/locafero v0.11.0/go.mod h1:nVIGvgyzw595SUSUE6tvCp3YYTeHs15MvlmU87WwIik= +github.com/sourcegraph/conc v0.3.1-0.20240121214520-5f936abd7ae8 h1:+jumHNA0Wrelhe64i8F6HNlS8pkoyMv5sreGx2Ry5Rw= +github.com/sourcegraph/conc v0.3.1-0.20240121214520-5f936abd7ae8/go.mod h1:3n1Cwaq1E1/1lhQhtRK2ts/ZwZEhjcQeJQ1RuC6Q/8U= +github.com/spf13/afero v1.15.0 h1:b/YBCLWAJdFWJTN9cLhiXXcD7mzKn9Dm86dNnfyQw1I= +github.com/spf13/afero v1.15.0/go.mod h1:NC2ByUVxtQs4b3sIUphxK0NioZnmxgyCrfzeuq8lxMg= +github.com/spf13/cast v1.10.0 h1:h2x0u2shc1QuLHfxi+cTJvs30+ZAHOGRic8uyGTDWxY= +github.com/spf13/cast v1.10.0/go.mod h1:jNfB8QC9IA6ZuY2ZjDp0KtFO2LZZlg4S/7bzP6qqeHo= +github.com/spf13/pflag v1.0.10 h1:4EBh2KAYBwaONj6b2Ye1GiHfwjqyROoF4RwYO+vPwFk= +github.com/spf13/pflag v1.0.10/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= +github.com/spf13/viper v1.21.0 h1:x5S+0EU27Lbphp4UKm1C+1oQO+rKx36vfCoaVebLFSU= +github.com/spf13/viper v1.21.0/go.mod h1:P0lhsswPGWD/1lZJ9ny3fYnVqxiegrlNrEmgLjbTCAY= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= +github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= +github.com/stretchr/objx v0.5.2/go.mod h1:FRsXN1f5AsAjCGJKqEizvkpNtU+EGNCLh3NxZ/8L+MA= +github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= +github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= +github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo= +github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= +github.com/subosito/gotenv v1.6.0 h1:9NlTDc1FTs4qu0DDq7AEtTPNw6SVm7uBMsUCUjABIf8= +github.com/subosito/gotenv v1.6.0/go.mod h1:Dk4QP5c2W3ibzajGcXpNraDfq2IrhjMIvMSWPKKo0FU= +github.com/twitchyliquid64/golang-asm v0.15.1 h1:SU5vSMR7hnwNxj24w34ZyCi/FmDZTkS4MhqMhdFk5YI= +github.com/twitchyliquid64/golang-asm v0.15.1/go.mod h1:a1lVb/DtPvCB8fslRZhAngC2+aY1QWCk3Cedj/Gdt08= +github.com/ugorji/go/codec v1.3.2 h1:zkEASHHyEClGeURfgNT9PJZVfAbs9oEX9QXggwWNJbc= +github.com/ugorji/go/codec v1.3.2/go.mod h1:pRBVtBSKl77K30Bv8R2P+cLSGaTtex6fsA2Wjqmfxj4= +go.mongodb.org/mongo-driver/v2 v2.9.1 h1:jewiFs2m1/VOQp8qhFshX6hWZ+EAXDhZHXExAUMcOgQ= +go.mongodb.org/mongo-driver/v2 v2.9.1/go.mod h1:SHKN0IWkKmEVGHLjXnni6s4wPKX4v86FTgOeJJFuXcA= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.uber.org/mock v0.6.0 h1:hyF9dfmbgIX5EfOdasqLsWD6xqpNZlXblLB/Dbnwv3Y= +go.uber.org/mock v0.6.0/go.mod h1:KiVJ4BqZJaMj4svdfmHM0AUx4NJYO8ZNpPnZn1Z+BBU= +go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ= +go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= +go.uber.org/zap v1.28.0 h1:IZzaP1Fv73/T/pBMLk4VutPl36uNC+OSUh3JLG3FIjo= +go.uber.org/zap v1.28.0/go.mod h1:rDLpOi171uODNm/mxFcuYWxDsqWSAVkFdX4XojSKg/Q= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= +golang.org/x/arch v0.31.0 h1:22MlEb14/O/EPCYHFxsDdv5TuLD5dMjT5e2QeJw4ULk= +golang.org/x/arch v0.31.0/go.mod h1:KcJSod3cqT2dKcjBxqTyGfbumNikqU9p5tHJinPJnuY= +golang.org/x/crypto v0.57.0 h1:3ZVCjf8Ggz7zneR/EHRVx68Ctf+2pmIMP2UFhh9cC6M= +golang.org/x/crypto v0.57.0/go.mod h1:Fdz0i5U6CoizGwLda9DttjSk6qlZo25zYNtR+ycvuZA= +golang.org/x/net v0.60.0 h1:79p50tfZlm0J9YfoDsSi639qSXNGVwEzOPLCxM2FsYU= +golang.org/x/net v0.60.0/go.mod h1:2DA/G1UfVbCpQPeWTmMPGY7Cs2PkBkwu743bVX5PIVg= +golang.org/x/sync v0.23.0 h1:KameEIfc1IkluZyXWLn39Wd4tURc6GbCiISGiZm2bQk= +golang.org/x/sync v0.23.0/go.mod h1:sUUOizhqBxiL6pEWpqNLUiaJn1ShEbZ6BBqskPbjZm0= +golang.org/x/sys v0.48.0 h1:bbX/i/6MgT9BVLM9RT1thmxL04yeTAhbEz4SyadbXoo= +golang.org/x/sys v0.48.0/go.mod h1:hNLxWAXmnKAxqDtdwIYC4bM9oQPEecfsnNMuSxOs3og= +golang.org/x/text v0.42.0 h1:JbOZXgfeCPU9gacVtYliJqOhD+zhrEqK4LfdpmlUZqI= +golang.org/x/text v0.42.0/go.mod h1:ojzP1Z+2QtioaF8DTtO8K5q7JWVVYwZKenzujK0Zd0E= +google.golang.org/protobuf v1.36.12 h1:pJOKDDOyeXErUroCihFAd5LQuwXBSpVnKGrj5o/fwxc= +google.golang.org/protobuf v1.36.12/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/infra/terraform/service_api.tf b/infra/terraform/service_api.tf index 5214011..66cb768 100644 --- a/infra/terraform/service_api.tf +++ b/infra/terraform/service_api.tf @@ -74,6 +74,13 @@ resource "google_cloud_run_v2_service" "api" { name = "GOMEMLIMIT" value = "${floor(local.memory_mib * 9 / 10)}MiB" } + + # The service runs as the deployment it is. Without this it would take + # itself for a developer's machine and refuse to start on Cloud Run. + env { + name = "CANVAS_ENV" + value = "prod" + } } } diff --git a/infra/terraform/tests/configuration.tftest.hcl b/infra/terraform/tests/configuration.tftest.hcl index 31d9686..194b120 100644 --- a/infra/terraform/tests/configuration.tftest.hcl +++ b/infra/terraform/tests/configuration.tftest.hcl @@ -74,6 +74,11 @@ run "the_service_size_and_start_stay_as_chosen" { condition = one([for e in google_cloud_run_v2_service.api.template[0].containers[0].env : e.value if e.name == "GOMEMLIMIT"]) == "921MiB" error_message = "1Gi of memory tells the runtime 921MiB." } + + assert { + condition = one([for e in google_cloud_run_v2_service.api.template[0].containers[0].env : e.value if e.name == "CANVAS_ENV"]) == "prod" + error_message = "The service runs as prod: on Cloud Run any other environment refuses to start." + } } # The address a delivery checks and shows is the one made of the service's name, diff --git a/internal/apierror/apierror.go b/internal/apierror/apierror.go new file mode 100644 index 0000000..72b524d --- /dev/null +++ b/internal/apierror/apierror.go @@ -0,0 +1,31 @@ +// Package apierror defines the shape of an HTTP error response. +// +// One shape for every error the service answers with: a stable +// machine-readable code, a sentence meant to be relayed to a person, and, +// when a code needs them, details a client can act on. None of them ever +// carries an internal error message, a stack or anything a child wrote. The +// request's id travels in a header beside the body, not inside it. +package apierror + +// Response is a structured HTTP error. +type Response struct { + // Code is a stable identifier a client can branch on. + Code string `json:"code"` + // Message is a short sentence describing what happened. + Message string `json:"message"` + // Details are machine-readable facts about the error, for the codes that + // need any. Most do not, and then the field is left out of the body. + Details map[string]any `json:"details,omitempty"` +} + +// The codes the transport itself produces. A code joins this list with the +// first code that answers with it. +const ( + // CodeInternal answers a request the service failed on: a 500. + CodeInternal = "INTERNAL_ERROR" + // CodeNotFound answers a path the service does not serve: a 404. + CodeNotFound = "NOT_FOUND" + // CodeMethodNotAllowed answers a path asked with a method it does not + // take: a 405, with the methods it does take in its Allow header. + CodeMethodNotAllowed = "METHOD_NOT_ALLOWED" +) diff --git a/internal/apierror/apierror_test.go b/internal/apierror/apierror_test.go new file mode 100644 index 0000000..e74763c --- /dev/null +++ b/internal/apierror/apierror_test.go @@ -0,0 +1,80 @@ +package apierror_test + +import ( + "encoding/json" + "maps" + "testing" + + "github.com/MathTrail/canvas-api/internal/apierror" +) + +// The body is flat: a code and a message, and nothing else when there are no +// details, so that a client reading an error never meets a field it was not +// told about. +func TestAResponseWithoutDetailsHasTheCodeAndTheMessageOnly(t *testing.T) { + t.Parallel() + + data, err := json.Marshal(apierror.Response{Code: apierror.CodeNotFound, Message: "no such endpoint"}) + if err != nil { + t.Fatalf("Marshal() error = %v, want nil", err) + } + + var fields map[string]any + if err := json.Unmarshal(data, &fields); err != nil { + t.Fatalf("Unmarshal() error = %v, want nil", err) + } + want := map[string]any{"code": apierror.CodeNotFound, "message": "no such endpoint"} + if !maps.Equal(fields, want) { + t.Errorf("body = %s, want exactly the code and the message", data) + } +} + +// Details travel as an object beside the code and the message, keeping the +// type of every value. +func TestDetailsTravelBesideTheCode(t *testing.T) { + t.Parallel() + + data, err := json.Marshal(apierror.Response{ + Code: apierror.CodeNotFound, + Message: "no such endpoint", + Details: map[string]any{"expected": 3, "field": "task_id"}, + }) + if err != nil { + t.Fatalf("Marshal() error = %v, want nil", err) + } + + var body struct { + Code string `json:"code"` + Details map[string]any `json:"details"` + } + if err := json.Unmarshal(data, &body); err != nil { + t.Fatalf("Unmarshal() error = %v, want nil", err) + } + if body.Code != apierror.CodeNotFound { + t.Errorf("code = %q, want %q", body.Code, apierror.CodeNotFound) + } + want := map[string]any{"expected": float64(3), "field": "task_id"} + if !maps.Equal(body.Details, want) { + t.Errorf("details = %v, want %v; body = %s", body.Details, want, data) + } +} + +// A code is what a client branches on, so what it says on the wire is part of +// the contract: a code renamed in the source would break every client that +// knew the old one while the tests that compare with the constant stayed green. +func TestTheCodesSayWhatTheySaid(t *testing.T) { + t.Parallel() + + for code, want := range map[string]string{ + apierror.CodeInternal: "INTERNAL_ERROR", + apierror.CodeNotFound: "NOT_FOUND", + apierror.CodeMethodNotAllowed: "METHOD_NOT_ALLOWED", + } { + t.Run(want, func(t *testing.T) { + t.Parallel() + if code != want { + t.Errorf("code = %q, want %q", code, want) + } + }) + } +} diff --git a/internal/app/app_test.go b/internal/app/app_test.go new file mode 100644 index 0000000..0cfdd5e --- /dev/null +++ b/internal/app/app_test.go @@ -0,0 +1,302 @@ +package app_test + +import ( + "context" + "net" + "net/http" + "runtime" + "slices" + "strings" + "testing" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" + + "github.com/MathTrail/canvas-api/internal/app" + "github.com/MathTrail/canvas-api/internal/config" +) + +// The server must stop because its context was cancelled — the same way a +// signal reaches it — and it must stop without an error. +func TestServerStopsOnContextCancel(t *testing.T) { + t.Parallel() + + container := newTestContainer(t) + server := app.NewServer(container) + if err := server.Listen(t.Context()); err != nil { + t.Fatalf("Listen() error = %v, want nil", err) + } + + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- server.Run(ctx) }() + + // The server answers before the shutdown, so the test proves that it + // stopped rather than that it never started. + waitForHealthz(t, server.Addr()) + + cancel() + + select { + case err := <-stopped: + if err != nil { + t.Fatalf("Run() error = %v, want nil", err) + } + case <-time.After(5 * time.Second): + t.Fatal("Run() did not return within 5s of the context being cancelled") + } + + resp, err := http.Get("http://" + server.Addr() + "/health") //nolint:noctx // the request is expected to fail + if err == nil { + _ = resp.Body.Close() + t.Error("the server still answers after shutdown, want a refused connection") + } +} + +// Addr is read from one goroutine while Run binds the listener on another, +// which is how a caller learns the port the kernel picked. Run under the race +// detector, this is the test that says the field is guarded. +func TestAddrIsSafeWhileTheServerStarts(t *testing.T) { + t.Parallel() + + server := app.NewServer(newTestContainer(t)) + + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- server.Run(ctx) }() + + deadline := time.Now().Add(5 * time.Second) + addr := "" + for addr == "" && time.Now().Before(deadline) { + addr = server.Addr() + runtime.Gosched() + } + if addr == "" { + t.Fatal("Addr() stayed empty for 5s, want the bound address") + } + + cancel() + select { + case err := <-stopped: + if err != nil { + t.Fatalf("Run() error = %v, want nil", err) + } + case <-time.After(5 * time.Second): + t.Fatal("Run() did not return within 5s of the context being cancelled") + } +} + +// Run returns only once the goroutine it serves on has finished, with every line +// of its own log written: a line written after it returned would land in a +// test that has already ended, or in a process that is already on its way out. +func TestRunLogsEverythingBeforeItReturns(t *testing.T) { + t.Parallel() + + core, logs := observer.New(zapcore.InfoLevel) + container := newTestContainer(t) + container.Logger = zap.New(core) + server := app.NewServer(container) + if err := server.Listen(t.Context()); err != nil { + t.Fatalf("Listen() error = %v, want nil", err) + } + + // Cancelled before Run starts, so it turns to shutting down at once: the + // moment a goroutine of its own is most likely still to be on its way. + ctx, cancel := context.WithCancel(t.Context()) + cancel() + if err := server.Run(ctx); err != nil { + t.Fatalf("Run() error = %v, want nil", err) + } + + var logged []string + for _, entry := range logs.All() { + logged = append(logged, entry.Message) + } + if want := []string{"listening", "shutdown requested", "stopped"}; !slices.Equal(logged, want) { + t.Errorf("logged by the time Run returned: %q, want %q", logged, want) + } +} + +// A request that never finishes holds the server for the drain's share of the +// way out and no longer: the close that follows has to fit in the rest before +// the platform stops the process. +func TestTheDrainLeavesTheCloseItsShare(t *testing.T) { + t.Parallel() + + cfg := testConfig() + cfg.ShutdownTimeout = 4 * time.Second + container := containerFrom(t, cfg) + core, logs := observer.New(zapcore.InfoLevel) + container.Logger = zap.New(core) + + entered, released := make(chan struct{}), make(chan struct{}) + t.Cleanup(func() { close(released) }) + container.Router = http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + close(entered) + <-released + }) + server := app.NewServer(container) + if err := server.Listen(t.Context()); err != nil { + t.Fatalf("Listen() error = %v, want nil", err) + } + + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- server.Run(ctx) }() + go func() { + resp, err := http.Get("http://" + server.Addr() + "/stuck") //nolint:noctx // cut off by the shutdown + if err == nil { + _ = resp.Body.Close() + } + }() + <-entered + + started := time.Now() + cancel() + select { + case err := <-stopped: + // The stop was asked for and it happened: the request it cut off is a + // warning, not a failure of the process. + if err != nil { + t.Errorf("Run() error = %v, want nil", err) + } + if warned := logs.FilterMessage("stopped").FilterField(zap.Bool("cut_short", true)).All(); len(warned) != 1 || + warned[0].Level != zapcore.WarnLevel { + t.Errorf("stop lines = %v, want one warning that the drain was cut short", warned) + } + case <-time.After(2 * cfg.ShutdownTimeout): + t.Fatalf("Run() did not return within %v of the context being cancelled", 2*cfg.ShutdownTimeout) + } + + // Each line halfway to its neighbour, so that the drain is told apart from + // the close's quarter below it and from the whole way out above it, a + // second away and half a second away. + elapsed := time.Since(started) + if least := (cfg.CloseTimeout() + cfg.DrainTimeout()) / 2; elapsed < least { + t.Errorf("the drain took %v, want at least %v: it waits out its share of %v", + elapsed, least, cfg.DrainTimeout()) + } + if most := (cfg.DrainTimeout() + cfg.ShutdownTimeout) / 2; elapsed >= most { + t.Errorf("the drain took %v, want less than %v: it is done within its share of %v", + elapsed, most, cfg.DrainTimeout()) + } +} + +// A port that is already taken is reported when the server binds it, not +// swallowed by the goroutine that serves on it. +func TestListenReportsATakenPort(t *testing.T) { + t.Parallel() + + first := app.NewServer(newTestContainer(t)) + if err := first.Listen(t.Context()); err != nil { + t.Fatalf("Listen() error = %v, want nil", err) + } + // Nothing below reads the first server again, and the listener of a server + // nothing can reach is closed by the finalizer of its own descriptor as + // soon as a collection happens to run. That would hand the port back and + // leave the second server binding a free one. + defer runtime.KeepAlive(first) + + cfg := testConfig() + cfg.Port = portOf(t, first.Addr()) + if err := app.NewServer(containerFrom(t, cfg)).Listen(t.Context()); err == nil { + t.Error("Listen() error = nil, want a refusal on a port that is taken") + } +} + +// Run binds the port itself when nothing bound it first, and reports a port +// that is taken at once: the process stops at its start, rather than waiting +// for a stop that would never come. +func TestRunReportsATakenPort(t *testing.T) { + t.Parallel() + + first := app.NewServer(newTestContainer(t)) + if err := first.Listen(t.Context()); err != nil { + t.Fatalf("Listen() error = %v, want nil", err) + } + // Kept reachable to the end, so that no collection closes its listener + // and hands the port back before the second server tries it. + defer runtime.KeepAlive(first) + + cfg := testConfig() + cfg.Port = portOf(t, first.Addr()) + second := app.NewServer(containerFrom(t, cfg)) + ran := make(chan error, 1) + go func() { ran <- second.Run(t.Context()) }() + select { + case err := <-ran: + if err == nil || !strings.HasPrefix(err.Error(), "app: listen on ") { + t.Errorf("Run() error = %v, want a refusal to listen on the port that is taken", err) + } + case <-time.After(5 * time.Second): + t.Fatal("Run() on a port that is taken did not return within 5s, want the refusal at once") + } + if addr := second.Addr(); addr != "" { + t.Errorf("Addr() = %q after the refusal, want nothing bound", addr) + } +} + +// newTestContainer is a container built from the test configuration, closed +// when the case is over. +func newTestContainer(t *testing.T) *app.Container { + t.Helper() + + return containerFrom(t, testConfig()) +} + +// containerFrom builds a container from a configuration a case has changed, +// and closes it when the case is over. +func containerFrom(t *testing.T, cfg *config.Config) *app.Container { + t.Helper() + + container, err := app.NewContainer(t.Context(), cfg, zaptest.NewLogger(t)) + if err != nil { + t.Fatalf("NewContainer() error = %v, want nil", err) + } + t.Cleanup(func() { container.Close(context.Background()) }) + return container +} + +func testConfig() *config.Config { + return &config.Config{ + Port: "0", // the kernel picks a free one + Env: config.EnvLocal, + LogLevel: "debug", + LogFormat: "console", + ReadHeaderTimeout: config.DefaultReadHeaderTimeout, + ReadTimeout: config.DefaultReadTimeout, + WriteTimeout: config.DefaultWriteTimeout, + IdleTimeout: config.DefaultIdleTimeout, + ShutdownTimeout: config.DefaultShutdownTimeout, + } +} + +func portOf(t *testing.T, addr string) string { + t.Helper() + + _, port, err := net.SplitHostPort(addr) + if err != nil { + t.Fatalf("address %q has no port: %v", addr, err) + } + return port +} + +func waitForHealthz(t *testing.T, addr string) { + t.Helper() + + deadline := time.Now().Add(5 * time.Second) + for time.Now().Before(deadline) { + resp, err := http.Get("http://" + addr + "/health") //nolint:noctx // a probe with its own deadline loop + if err == nil { + _ = resp.Body.Close() + if resp.StatusCode == http.StatusOK { + return + } + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("no healthy answer from %s within 5s", addr) +} diff --git a/internal/app/container.go b/internal/app/container.go new file mode 100644 index 0000000..a431e3e --- /dev/null +++ b/internal/app/container.go @@ -0,0 +1,91 @@ +// Package app wires the service together and runs it. +// +// The container is hand-written on purpose: there is no DI framework, the +// order of construction is the order of the code, and the order of shutdown is +// its reverse. +package app + +import ( + "context" + "net/http" + + "go.uber.org/zap" + + "github.com/MathTrail/canvas-api/internal/config" + httpserver "github.com/MathTrail/canvas-api/internal/transport/http" +) + +// Container holds everything the process needs while it runs, and knows how to +// close it again. Every part is built in one place, NewContainer, and released +// in one, Close. +type Container struct { + Config *config.Config + Logger *zap.Logger + Router http.Handler + + // closers run in reverse order of registration, so that a resource is + // always closed before whatever it was built from. + closers []func(context.Context) error +} + +// part builds one piece of the container, and registers with onClose whatever +// that piece has to release. +type part func(ctx context.Context, c *Container) error + +// parts are the pieces of the service, in the order they are built: a piece +// may use any piece before it. +var parts = []part{ + routes, +} + +// NewContainer builds the service from its configuration. A piece that cannot +// be built stops the start, and whatever was built before it is closed again. +func NewContainer(ctx context.Context, cfg *config.Config, log *zap.Logger) (*Container, error) { + return build(ctx, cfg, log, parts) +} + +// build builds the container from the pieces given. It is NewContainer with the +// pieces as an argument, so that a test can make one of them fail. +func build(ctx context.Context, cfg *config.Config, log *zap.Logger, pieces []part) (_ *Container, err error) { + c := &Container{Config: cfg, Logger: log} + defer func() { + if err == nil { + return + } + // Detached, with the time a close is given: construction may have + // failed because its context ended, and a close handed that context + // would give up before it began. + closing, cancel := context.WithTimeout(context.WithoutCancel(ctx), cfg.CloseTimeout()) + defer cancel() + c.Close(closing) + }() + + for _, piece := range pieces { + if err := piece(ctx, c); err != nil { + return nil, err + } + } + return c, nil +} + +// routes builds the HTTP surface. It holds nothing to release. +func routes(_ context.Context, c *Container) error { + c.Router = httpserver.NewRouter(c.Logger) + return nil +} + +// onClose registers what Close has to release. +func (c *Container) onClose(closer func(context.Context) error) { + c.closers = append(c.closers, closer) +} + +// Close releases everything the container holds, the last built first. One +// that fails is logged, and the ones after it still run rather than being left +// open. +func (c *Container) Close(ctx context.Context) { + for i := len(c.closers) - 1; i >= 0; i-- { + if err := c.closers[i](ctx); err != nil { + c.Logger.Error("close failed", zap.Error(err)) + } + } +} diff --git a/internal/app/container_internal_test.go b/internal/app/container_internal_test.go new file mode 100644 index 0000000..01b00f2 --- /dev/null +++ b/internal/app/container_internal_test.go @@ -0,0 +1,111 @@ +package app + +import ( + "context" + "errors" + "slices" + "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" + + "github.com/MathTrail/canvas-api/internal/config" +) + +// Close runs every closer, the last registered first, so that a resource is +// closed before whatever it was built from. One that fails is logged as a +// failure, and the ones after it still run rather than being left open. +func TestCloseRunsEveryCloserLastFirstAndLogsTheOneThatFails(t *testing.T) { + t.Parallel() + + core, logs := observer.New(zapcore.InfoLevel) + stuck := errors.New("the client would not close") + var ran []string + c := &Container{Logger: zap.New(core)} + c.onClose(closing(&ran, "first", nil)) + c.onClose(closing(&ran, "second", stuck)) + c.onClose(closing(&ran, "third", nil)) + + c.Close(t.Context()) + if want := []string{"third", "second", "first"}; !slices.Equal(ran, want) { + t.Errorf("closed %q, want %q: every closer, the last registered first", ran, want) + } + failed := logs.FilterMessage("close failed").All() + if len(failed) != 1 || failed[0].Level != zapcore.ErrorLevel || failed[0].ContextMap()["error"] != stuck.Error() { + t.Errorf("close failed lines = %v, want one error naming %q", failed, stuck) + } +} + +// A start that fails halfway releases what it had built, the last built first, +// and builds nothing after the piece that failed. The close gets a context of +// its own: the start may have failed because its context ended. +func TestAStartThatFailsHalfwayClosesWhatItBuilt(t *testing.T) { + t.Parallel() + + refused := errors.New("the third piece could not be built") + var ran []string + var closedLive bool + built := func(name string) part { + return func(_ context.Context, c *Container) error { + c.onClose(func(ctx context.Context) error { + closedLive = closedLive || ctx.Err() == nil + ran = append(ran, name) + return nil + }) + return nil + } + } + never := func(context.Context, *Container) error { + t.Error("a piece after the one that failed was built") + return nil + } + failing := func(context.Context, *Container) error { return refused } + + ctx, cancel := context.WithCancel(t.Context()) + cancel() // the start was stopped, and its context is over + c, err := build(ctx, &config.Config{ShutdownTimeout: config.DefaultShutdownTimeout}, zaptest.NewLogger(t), + []part{built("first"), built("second"), failing, never}) + + if !errors.Is(err, refused) || c != nil { + t.Fatalf("build() = %v, %v, want no container and the piece's error", c, err) + } + if want := []string{"second", "first"}; !slices.Equal(ran, want) { + t.Errorf("closed %q, want %q: what was built, the last first", ran, want) + } + if !closedLive { + t.Error("the close got a context that had ended, want one of its own") + } +} + +// A start that succeeds closes nothing until it is asked to. +func TestAStartThatSucceedsClosesNothing(t *testing.T) { + t.Parallel() + + var ran []string + c, err := build(t.Context(), &config.Config{ShutdownTimeout: config.DefaultShutdownTimeout}, zaptest.NewLogger(t), + []part{func(_ context.Context, c *Container) error { + c.onClose(closing(&ran, "only", nil)) + return nil + }}) + if err != nil { + t.Fatalf("build() error = %v, want nil", err) + } + if len(ran) != 0 { + t.Errorf("closed %q before Close, want nothing", ran) + } + c.Close(t.Context()) + if want := []string{"only"}; !slices.Equal(ran, want) { + t.Errorf("closed %q, want %q", ran, want) + } +} + +// closing is a closer that writes its name down when it runs, and fails with +// err. +func closing(ran *[]string, name string, err error) func(context.Context) error { + return func(context.Context) error { + *ran = append(*ran, name) + return err + } +} diff --git a/internal/app/server.go b/internal/app/server.go new file mode 100644 index 0000000..b4228ad --- /dev/null +++ b/internal/app/server.go @@ -0,0 +1,139 @@ +package app + +import ( + "context" + "errors" + "fmt" + "net" + "net/http" + "sync" + "time" + + "go.uber.org/zap" +) + +// Server is the HTTP server and its graceful shutdown. +type Server struct { + http *http.Server + logger *zap.Logger + // drainTimeout is how long a shutdown waits for the requests in flight: + // the server's share of the way out, not the whole of it. + drainTimeout time.Duration + + // mu guards listener: Run binds it on one goroutine while Addr may be + // read from another, which is how a caller finds out which port the + // kernel picked. + mu sync.RWMutex + listener net.Listener +} + +// NewServer builds the server from a wired container. +func NewServer(c *Container) *Server { + return &Server{ + logger: c.Logger, + drainTimeout: c.Config.DrainTimeout(), + http: &http.Server{ + // Empty host, so the server listens on every interface. The + // configuration guarantees a bare port number, and JoinHostPort is + // what keeps the address well formed if that ever stops being true. + Addr: net.JoinHostPort("", c.Config.Port), + Handler: c.Router, + ReadHeaderTimeout: c.Config.ReadHeaderTimeout, + ReadTimeout: c.Config.ReadTimeout, + WriteTimeout: c.Config.WriteTimeout, + IdleTimeout: c.Config.IdleTimeout, + }, + } +} + +// Listen binds the port without serving on it yet. Run binds it itself when +// nothing did, but the process calls Listen first: binding early is how a port +// that is already taken is reported as a failed start, before the service says +// it has started, rather than swallowed by the goroutine inside Run. A test +// calls it too, when it needs the real address before the server starts. +func (s *Server) Listen(ctx context.Context) error { + s.mu.Lock() + defer s.mu.Unlock() + + if s.listener != nil { + return nil + } + var lc net.ListenConfig + listener, err := lc.Listen(ctx, "tcp", s.http.Addr) + if err != nil { + return fmt.Errorf("app: listen on %s: %w", s.http.Addr, err) + } + s.listener = listener + return nil +} + +// Addr is the address the server is bound to, empty before Listen. It is safe +// to call while the server is starting or serving. +func (s *Server) Addr() string { + s.mu.RLock() + defer s.mu.RUnlock() + + if s.listener == nil { + return "" + } + return s.listener.Addr().String() +} + +// Run serves until ctx is cancelled, then shuts down gracefully. Shutdown is +// driven by the context rather than by a signal handler of its own, so that +// every part of the process stops for the same reason at the same moment. +// +// It returns only once the goroutine it serves on has finished, so every line +// Run itself logs is written by then. A request still being handled when the +// drain's share of the way out is spent is cut off rather than waited for, and +// that is still the stop that was asked for: the line saying so is a warning, +// and Run returns no error. A failure is what nobody asked for — a server that +// stopped serving on its own. +func (s *Server) Run(ctx context.Context) error { + if err := s.Listen(ctx); err != nil { + return err + } + + s.mu.RLock() + listener := s.listener + s.mu.RUnlock() + + // The port is bound already, so this is true before serving starts, and + // written here it cannot land after Run has returned. + s.logger.Info("listening", zap.String("addr", listener.Addr().String())) + served := make(chan error, 1) + go func() { served <- s.http.Serve(listener) }() + + select { + case err := <-served: + // Nothing had asked it to stop, so whatever it returned is a failure. + return fmt.Errorf("app: serve: %w", err) + case <-ctx.Done(): + s.logger.Info("shutdown requested") + } + + // A fresh context, so the drain's deadline starts now rather than at the + // moment the signal arrived and cancelled the parent. It is the drain's + // share of the way out: whoever closes what the server ran on needs the + // rest before the platform stops the process. + shutdown, cancel := context.WithTimeout(context.WithoutCancel(ctx), s.drainTimeout) + defer cancel() + + drained := s.http.Shutdown(shutdown) + if drained != nil { + _ = s.http.Close() // the deadline passed: drop what is left rather than hang + } + // Shutdown and Close both make Serve return, even one that had not begun + // yet, so this wait is short. + <-served + + switch { + case errors.Is(drained, context.DeadlineExceeded): + s.logger.Warn("stopped", zap.Bool("cut_short", true)) + return nil + case drained != nil: + return fmt.Errorf("app: graceful shutdown: %w", drained) + } + s.logger.Info("stopped") + return nil +} diff --git a/internal/app/server_internal_test.go b/internal/app/server_internal_test.go new file mode 100644 index 0000000..c47214f --- /dev/null +++ b/internal/app/server_internal_test.go @@ -0,0 +1,122 @@ +package app + +import ( + "context" + "errors" + "net" + "net/http" + "strings" + "testing" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +// errStuckSocket is the fault of a listener that would not close. +var errStuckSocket = errors.New("the socket would not close") + +// stuckListener is a listener that closes and then says it could not. +type stuckListener struct{ net.Listener } + +func (l stuckListener) Close() error { + _ = l.Listener.Close() + return errStuckSocket +} + +// A way out that fails for a reason of its own — a listener that would not +// close — is a failure, and is returned as one. Only a drain that ran out of +// its time is the stop that was asked for, cut short. +func TestAShutdownThatFailsIsNotADrainCutShort(t *testing.T) { + t.Parallel() + + var lc net.ListenConfig + listener, err := lc.Listen(t.Context(), "tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen: %v", err) + } + core, logs := observer.New(zapcore.InfoLevel) + server := &Server{ + http: &http.Server{Handler: http.NotFoundHandler(), ReadHeaderTimeout: time.Second}, + logger: zap.New(core), + drainTimeout: time.Second, + listener: stuckListener{listener}, + } + + ctx, cancel := context.WithCancel(t.Context()) + stopped := make(chan error, 1) + go func() { stopped <- server.Run(ctx) }() + + // Stopped only once it is serving: a server stopped before it began + // never gets to close its listener, and so never finds it stuck. + answered(t, listener.Addr().String()) + cancel() + + select { + case err := <-stopped: + if !errors.Is(err, errStuckSocket) { + t.Errorf("Run() error = %v, want the socket that would not close", err) + } + case <-time.After(5 * time.Second): + t.Fatal("Run() did not return within 5s of the context being cancelled") + } + if stopped := logs.FilterMessage("stopped").All(); len(stopped) != 0 { + t.Errorf("stop lines = %v, want none for a way out that failed", stopped) + } +} + +// A server whose listener is gone stops serving on its own, which nobody asked +// for: Run returns that as a failure of serving, and no line says the server +// was asked to stop or stopped as asked. +func TestAServerThatStopsServingOnItsOwnFails(t *testing.T) { + t.Parallel() + + var lc net.ListenConfig + listener, err := lc.Listen(t.Context(), "tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen: %v", err) + } + if err = listener.Close(); err != nil { + t.Fatalf("close the listener: %v", err) + } + core, logs := observer.New(zapcore.InfoLevel) + server := &Server{ + http: &http.Server{Handler: http.NotFoundHandler(), ReadHeaderTimeout: time.Second}, + logger: zap.New(core), + drainTimeout: time.Second, + listener: listener, + } + + err = server.Run(t.Context()) + if err == nil || !strings.HasPrefix(err.Error(), "app: serve: ") || !errors.Is(err, net.ErrClosed) { + t.Errorf("Run() error = %v, want a failure of serving on the closed listener", err) + } + for _, message := range []string{"shutdown requested", "stopped"} { + if lines := logs.FilterMessage(message).All(); len(lines) != 0 { + t.Errorf("%q lines = %v, want none for a server nobody asked to stop", message, lines) + } + } +} + +// answered waits until the server at addr answers a request, whatever it +// answers. +func answered(t *testing.T, addr string) { + t.Helper() + + client := &http.Client{Timeout: time.Second} + deadline := time.Now().Add(5 * time.Second) + for time.Now().Before(deadline) { + request, err := http.NewRequestWithContext(t.Context(), http.MethodGet, "http://"+addr+"/", http.NoBody) + if err != nil { + t.Fatalf("build a request: %v", err) + } + if response, err := client.Do(request); err == nil { + _ = response.Body.Close() + client.CloseIdleConnections() + return + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("no answer from %s within 5s", addr) +} diff --git a/internal/config/config.go b/internal/config/config.go new file mode 100644 index 0000000..220ae43 --- /dev/null +++ b/internal/config/config.go @@ -0,0 +1,270 @@ +// Package config reads the service's configuration from the environment. +// +// Environment variables are the only source: there is no file, no flag and no +// remote source. They are read here and nowhere else, so that every value has +// one origin and one validation. Viper does the reading — as it does in the +// platform's other services — which keeps the names, the defaults and the +// types of a growing table in one declaration. +// +// Only the variables the service actually uses are here. A variable arrives +// with the code that consumes it, because a required variable with no reader +// is a deployment that fails for no reason. +package config + +import ( + "errors" + "fmt" + "os" + "strconv" + "strings" + "time" + + "github.com/spf13/viper" +) + +// The two environments the service knows. Local is a developer's machine, +// where the conveniences of development may be switched on; prod is the one +// deployment, where none of them may. +const ( + EnvLocal = "local" + EnvProd = "prod" +) + +// Defaults for every optional variable. They are named constants rather than +// literals in LoadFrom so that the documentation and the code cannot drift. +const ( + DefaultPort = "8080" + DefaultEnv = EnvLocal + DefaultLogLevel = "info" + DefaultLogFormat = "json" + DefaultReadHeaderTimeout = 5 * time.Second + DefaultReadTimeout = 30 * time.Second + DefaultWriteTimeout = 60 * time.Second + DefaultIdleTimeout = 120 * time.Second + DefaultShutdownTimeout = 9 * time.Second +) + +// MinShutdownTimeout is the shortest way out a service may be given: the close +// after the drain has a quarter of it, and a quarter of less is no time to +// close anything in. +const MinShutdownTimeout = time.Second + +// CloudRunStopGrace is how long Cloud Run waits after it asks an instance to +// stop before it kills it. A deployed way out has to end before then, or the +// close it keeps time for never runs. +const CloudRunStopGrace = 10 * time.Second + +// ErrInvalid is returned by LoadFrom and Validate; callers branch on it with +// errors.Is. +var ErrInvalid = errors.New("config: invalid") + +// Config is the whole configuration of the process. Every field names the +// variable it comes from, so that a refusal and the deployment that caused it +// use the same word. +type Config struct { + // Port is the TCP port to listen on. + Port string `mapstructure:"PORT"` + // Env is the environment the service runs in: local or prod. + Env string `mapstructure:"CANVAS_ENV"` + // LogLevel is a zap level name: debug, info, warn or error. + LogLevel string `mapstructure:"CANVAS_LOG_LEVEL"` + // LogFormat is "json" for a log collector and "console" to read by eye. + LogFormat string `mapstructure:"CANVAS_LOG_FORMAT"` + + // ReadHeaderTimeout is how long a client may take to send its headers. + ReadHeaderTimeout time.Duration `mapstructure:"CANVAS_HTTP_READ_HEADER_TIMEOUT"` + // ReadTimeout is how long a client may take to send its whole request. + ReadTimeout time.Duration `mapstructure:"CANVAS_HTTP_READ_TIMEOUT"` + // WriteTimeout is how long the server may take to send its answer. + WriteTimeout time.Duration `mapstructure:"CANVAS_HTTP_WRITE_TIMEOUT"` + // IdleTimeout is how long a connection is kept open between requests. + IdleTimeout time.Duration `mapstructure:"CANVAS_HTTP_IDLE_TIMEOUT"` + // ShutdownTimeout is the whole way out once a stop is asked for: the + // server's drain and the close after it together. The platform stops the + // process ten seconds after asking it to, and time spent past that is not + // spent at all, so the default stops a second short of it: the signal takes + // a moment to arrive, and the last lines are written after the close. + ShutdownTimeout time.Duration `mapstructure:"CANVAS_SHUTDOWN_TIMEOUT"` + + // Service is the name K_SERVICE carries. Cloud Run sets it on every + // service and a developer's machine does not, which is what makes it the + // gate for everything meant for development only: no value of ours can + // open that gate in a deployment. + Service string `mapstructure:"K_SERVICE"` +} + +// Deployed reports whether the process is running as a deployed service. +func (c *Config) Deployed() bool { return c.Service != "" } + +// Local reports whether the service runs on a developer's machine, where the +// conveniences of development may be switched on. +func (c *Config) Local() bool { return c.Env == EnvLocal } + +// DrainTimeout is the part of the way out the server waits for the requests +// still in flight: three quarters of it. +// +// The drain and the close after it share one budget rather than take one +// each, in fixed shares, so that a slow request cannot eat the time the close +// needs. +func (c *Config) DrainTimeout() time.Duration { return c.ShutdownTimeout - c.CloseTimeout() } + +// CloseTimeout is the part of the way out kept for closing what the service ran +// on, once the server has drained or a start has failed halfway: a quarter of +// it. +func (c *Config) CloseTimeout() time.Duration { return c.ShutdownTimeout / 4 } + +// Load reads the process environment. +func Load() (*Config, error) { return LoadFrom(os.Environ()) } + +// LoadFrom reads the configuration from a set of KEY=VALUE strings, in the +// shape os.Environ returns them, applies the defaults and validates the +// result. The source is an argument so that a test can hand over an +// environment instead of changing the one the process runs in. +// +// A variable set to an empty string counts as unset: an empty value is what a +// deployment leaves behind when it stops setting something, and it should not +// silently override a default with nothing. +func LoadFrom(environ []string) (*Config, error) { + v := viper.New() + + // Every key is declared, including the ones whose default is empty, so + // that the names, the defaults and the types sit in one place. + v.SetDefault("PORT", DefaultPort) + v.SetDefault("CANVAS_ENV", DefaultEnv) + v.SetDefault("CANVAS_LOG_LEVEL", DefaultLogLevel) + v.SetDefault("CANVAS_LOG_FORMAT", DefaultLogFormat) + v.SetDefault("CANVAS_HTTP_READ_HEADER_TIMEOUT", DefaultReadHeaderTimeout) + v.SetDefault("CANVAS_HTTP_READ_TIMEOUT", DefaultReadTimeout) + v.SetDefault("CANVAS_HTTP_WRITE_TIMEOUT", DefaultWriteTimeout) + v.SetDefault("CANVAS_HTTP_IDLE_TIMEOUT", DefaultIdleTimeout) + v.SetDefault("CANVAS_SHUTDOWN_TIMEOUT", DefaultShutdownTimeout) + v.SetDefault("K_SERVICE", "") + + // Only the declared keys are taken from the environment. Everything else a + // process carries — credentials of other systems, tokens, the shell's own + // variables — has no business inside this reader, where a future dump of + // its contents would carry them straight into a log. A name is matched as + // it is written: the environment tells PORT from port, and so does this. + // Viper keeps its keys in lower case, so they are matched in upper case. + declared := make(map[string]struct{}, len(v.AllKeys())) + for _, key := range v.AllKeys() { + declared[strings.ToUpper(key)] = struct{}{} + } + for _, entry := range environ { + name, value, found := strings.Cut(entry, "=") + if !found || value == "" { + continue + } + if _, ours := declared[name]; !ours { + continue + } + v.Set(name, value) + } + + cfg := &Config{} + if err := v.Unmarshal(cfg); err != nil { + // The decoder names every variable it could not read, and it names all + // of them rather than the first, so its message is passed through as + // it is. A test holds it to that. + return nil, fmt.Errorf("%w: %w", ErrInvalid, err) + } + + if err := cfg.Validate(); err != nil { + return nil, err + } + return cfg, nil +} + +// Validate reports the first problem it finds, naming the variable behind it. +func (c *Config) Validate() error { + for _, check := range []func() error{ + c.validatePort, + c.validateEnv, + c.validateLogging, + c.validateTimeouts, + } { + if err := check(); err != nil { + return err + } + } + return nil +} + +// validatePort refuses a port the server could not listen on, and one written +// in any other way than plain digits: a sign or a leading zero would be read +// as the same port and logged as something else. +func (c *Config) validatePort() error { + port, err := strconv.Atoi(c.Port) + if err != nil || port < 1 || port > 65535 || strconv.Itoa(port) != c.Port { + return fmt.Errorf("%w: PORT must be a number from 1 to 65535, got %q", ErrInvalid, c.Port) + } + return nil +} + +// validateEnv refuses an environment the service does not know, and the local +// one in a deployment. Local is what switches development's conveniences on, +// so a deployment that says it is local is refused outright rather than +// warned about: whatever its variables say, a service on Cloud Run is prod. +func (c *Config) validateEnv() error { + switch c.Env { + case EnvLocal, EnvProd: + default: + return fmt.Errorf("%w: CANVAS_ENV must be %s or %s, got %q", ErrInvalid, EnvLocal, EnvProd, c.Env) + } + if c.Local() && c.Deployed() { + return fmt.Errorf("%w: CANVAS_ENV must be %s when K_SERVICE is set", ErrInvalid, EnvProd) + } + return nil +} + +// validateLogging refuses a level or a format the logger does not know, and +// the console format in a deployment. +func (c *Config) validateLogging() error { + switch c.LogLevel { + case "debug", "info", "warn", "error": + default: + return fmt.Errorf("%w: CANVAS_LOG_LEVEL must be debug, info, warn or error, got %q", ErrInvalid, c.LogLevel) + } + + switch c.LogFormat { + case "json", "console": + default: + return fmt.Errorf("%w: CANVAS_LOG_FORMAT must be json or console, got %q", ErrInvalid, c.LogFormat) + } + // The console format is for a person at a terminal. It escapes nothing, so a + // newline a request carries would start a line of its own, and a collector + // reads no severity out of it: a deployment writes JSON. + if c.LogFormat == "console" && c.Deployed() { + return fmt.Errorf("%w: CANVAS_LOG_FORMAT must be json when K_SERVICE is set", ErrInvalid) + } + return nil +} + +// validateTimeouts refuses a duration nothing could run under, naming its +// variable: every one has to be positive, and the way out long enough to be +// shared. +func (c *Config) validateTimeouts() error { + for _, timeout := range []struct { + name string + value time.Duration + }{ + {"CANVAS_HTTP_READ_HEADER_TIMEOUT", c.ReadHeaderTimeout}, + {"CANVAS_HTTP_READ_TIMEOUT", c.ReadTimeout}, + {"CANVAS_HTTP_WRITE_TIMEOUT", c.WriteTimeout}, + {"CANVAS_HTTP_IDLE_TIMEOUT", c.IdleTimeout}, + {"CANVAS_SHUTDOWN_TIMEOUT", c.ShutdownTimeout}, + } { + if timeout.value <= 0 { + return fmt.Errorf("%w: %s must be a positive duration, got %v", ErrInvalid, timeout.name, timeout.value) + } + } + if c.ShutdownTimeout < MinShutdownTimeout { + return fmt.Errorf("%w: CANVAS_SHUTDOWN_TIMEOUT must be at least %v, got %v", + ErrInvalid, MinShutdownTimeout, c.ShutdownTimeout) + } + if c.Deployed() && c.ShutdownTimeout >= CloudRunStopGrace { + return fmt.Errorf("%w: CANVAS_SHUTDOWN_TIMEOUT must be under %v when K_SERVICE is set, got %v", + ErrInvalid, CloudRunStopGrace, c.ShutdownTimeout) + } + return nil +} diff --git a/internal/config/config_test.go b/internal/config/config_test.go new file mode 100644 index 0000000..7241bb4 --- /dev/null +++ b/internal/config/config_test.go @@ -0,0 +1,246 @@ +package config_test + +import ( + "errors" + "strings" + "testing" + "time" + + "github.com/MathTrail/canvas-api/internal/config" +) + +// deployed is what Cloud Run and the deployment's configuration set together: +// the name of the service, and the environment it says it is. +var deployed = []string{"K_SERVICE=canvas-api", "CANVAS_ENV=prod"} + +func TestDefaults(t *testing.T) { + t.Parallel() + + cfg, err := config.LoadFrom(nil) + if err != nil { + t.Fatalf("LoadFrom() error = %v, want nil", err) + } + + for _, field := range []struct { + name string + got, want any + }{ + {"Port", cfg.Port, config.DefaultPort}, + {"Env", cfg.Env, config.EnvLocal}, + {"LogLevel", cfg.LogLevel, config.DefaultLogLevel}, + {"LogFormat", cfg.LogFormat, config.DefaultLogFormat}, + {"ReadHeaderTimeout", cfg.ReadHeaderTimeout, config.DefaultReadHeaderTimeout}, + {"ReadTimeout", cfg.ReadTimeout, config.DefaultReadTimeout}, + {"WriteTimeout", cfg.WriteTimeout, config.DefaultWriteTimeout}, + {"IdleTimeout", cfg.IdleTimeout, config.DefaultIdleTimeout}, + {"ShutdownTimeout", cfg.ShutdownTimeout, config.DefaultShutdownTimeout}, + } { + if field.got != field.want { + t.Errorf("%s = %v, want %v", field.name, field.got, field.want) + } + } + if cfg.Deployed() { + t.Error("Deployed() = true, want false when K_SERVICE is unset") + } + if !cfg.Local() { + t.Error("Local() = false, want true by default") + } +} + +func TestValuesAreRead(t *testing.T) { + t.Parallel() + + cfg, err := config.LoadFrom([]string{ + "PORT=9090", + "CANVAS_ENV=prod", + "CANVAS_LOG_LEVEL=debug", + "CANVAS_LOG_FORMAT=console", + "CANVAS_HTTP_READ_HEADER_TIMEOUT=2s", + "CANVAS_HTTP_READ_TIMEOUT=3s", + "CANVAS_HTTP_WRITE_TIMEOUT=4s", + "CANVAS_HTTP_IDLE_TIMEOUT=5s", + "CANVAS_SHUTDOWN_TIMEOUT=6s", + }) + if err != nil { + t.Fatalf("LoadFrom() error = %v, want nil", err) + } + + for _, field := range []struct { + name string + got, want any + }{ + {"Port", cfg.Port, "9090"}, + {"Env", cfg.Env, config.EnvProd}, + {"LogLevel", cfg.LogLevel, "debug"}, + {"LogFormat", cfg.LogFormat, "console"}, + {"ReadHeaderTimeout", cfg.ReadHeaderTimeout, 2 * time.Second}, + {"ReadTimeout", cfg.ReadTimeout, 3 * time.Second}, + {"WriteTimeout", cfg.WriteTimeout, 4 * time.Second}, + {"IdleTimeout", cfg.IdleTimeout, 5 * time.Second}, + {"ShutdownTimeout", cfg.ShutdownTimeout, 6 * time.Second}, + } { + if field.got != field.want { + t.Errorf("%s = %v, want %v", field.name, field.got, field.want) + } + } + if cfg.Local() { + t.Error("Local() = true, want false for prod") + } +} + +func TestEmptyValueCountsAsUnset(t *testing.T) { + t.Parallel() + + cfg, err := config.LoadFrom([]string{"CANVAS_LOG_LEVEL=", "PORT=", "CANVAS_ENV="}) + if err != nil { + t.Fatalf("LoadFrom() error = %v, want nil", err) + } + if cfg.LogLevel != config.DefaultLogLevel { + t.Errorf("LogLevel = %q, want the default %q", cfg.LogLevel, config.DefaultLogLevel) + } + if cfg.Port != config.DefaultPort { + t.Errorf("Port = %q, want the default %q", cfg.Port, config.DefaultPort) + } + if cfg.Env != config.DefaultEnv { + t.Errorf("Env = %q, want the default %q", cfg.Env, config.DefaultEnv) + } +} + +// Nothing but the declared variables enters the reader, so a dump of it can +// never carry a credential of something else. +func TestOnlyDeclaredVariablesAreRead(t *testing.T) { + t.Parallel() + + cfg, err := config.LoadFrom([]string{ + "DB_PASSWORD=hunter2", + "AWS_SECRET_ACCESS_KEY=secret", + "PATH=/usr/bin", + "PORT=9200", + "port=9300", + "canvas_env=prod", + "k_service=canvas-api", + }) + if err != nil { + t.Fatalf("LoadFrom() error = %v, want nil", err) + } + if cfg.Port != "9200" { + t.Errorf("Port = %q, want the declared variable, as it is written, to be read", cfg.Port) + } + if cfg.Env != config.DefaultEnv || cfg.Deployed() { + t.Errorf("Env = %q, Deployed() = %v, want names in another case left unread", cfg.Env, cfg.Deployed()) + } +} + +// The decoder names the variables it could not read, all of them at once. +// This is the test that notices if it ever stops. +func TestDecodeFailuresNameEveryBadVariable(t *testing.T) { + t.Parallel() + + _, err := config.LoadFrom([]string{ + "CANVAS_HTTP_READ_TIMEOUT=half a minute", + "CANVAS_SHUTDOWN_TIMEOUT=soon", + }) + if !errors.Is(err, config.ErrInvalid) { + t.Fatalf("LoadFrom() error = %v, want ErrInvalid", err) + } + for _, name := range []string{"CANVAS_HTTP_READ_TIMEOUT", "CANVAS_SHUTDOWN_TIMEOUT"} { + if !strings.Contains(err.Error(), name) { + t.Errorf("error = %q, want it to name %s", err, name) + } + } +} + +// A deployment is the service Cloud Run runs, said in prod and in JSON, with a +// way out that ends before the platform's grace does. +func TestADeploymentStarts(t *testing.T) { + t.Parallel() + + cfg, err := config.LoadFrom(append([]string{"CANVAS_SHUTDOWN_TIMEOUT=9999ms"}, deployed...)) + if err != nil { + t.Fatalf("LoadFrom() error = %v, want nil", err) + } + if !cfg.Deployed() { + t.Error("Deployed() = false, want true when K_SERVICE is set") + } +} + +// Every refusal has to name the variable behind it: a message that says only +// "invalid configuration" makes somebody read the code to deploy a service. +// What development alone may do is refused wherever K_SERVICE is set, however +// the rest of the configuration reads. +func TestRefusals(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + environ []string + wantVar string + }{ + {name: "the port is not a number", environ: []string{"PORT=eighty"}, wantVar: "PORT"}, + {name: "the port is zero", environ: []string{"PORT=0"}, wantVar: "PORT"}, + {name: "the port is out of range", environ: []string{"PORT=65536"}, wantVar: "PORT"}, + {name: "the port has a sign", environ: []string{"PORT=+8080"}, wantVar: "PORT"}, + {name: "the port has a leading zero", environ: []string{"PORT=08080"}, wantVar: "PORT"}, + {name: "an environment nobody knows", environ: []string{"CANVAS_ENV=dev"}, wantVar: "CANVAS_ENV"}, + {name: "a deployment that says it is local", environ: []string{"K_SERVICE=canvas-api", "CANVAS_ENV=local"}, wantVar: "CANVAS_ENV"}, + {name: "a deployment that says nothing is local by default", environ: []string{"K_SERVICE=canvas-api"}, wantVar: "CANVAS_ENV"}, + {name: "a level nobody knows", environ: []string{"CANVAS_LOG_LEVEL=loud"}, wantVar: "CANVAS_LOG_LEVEL"}, + {name: "a format nobody knows", environ: []string{"CANVAS_LOG_FORMAT=xml"}, wantVar: "CANVAS_LOG_FORMAT"}, + {name: "the console format in a deployment", environ: append([]string{"CANVAS_LOG_FORMAT=console"}, deployed...), wantVar: "CANVAS_LOG_FORMAT"}, + {name: "a read header timeout of nothing", environ: []string{"CANVAS_HTTP_READ_HEADER_TIMEOUT=0s"}, wantVar: "CANVAS_HTTP_READ_HEADER_TIMEOUT"}, + {name: "a negative read timeout", environ: []string{"CANVAS_HTTP_READ_TIMEOUT=-1s"}, wantVar: "CANVAS_HTTP_READ_TIMEOUT"}, + {name: "a write timeout of nothing", environ: []string{"CANVAS_HTTP_WRITE_TIMEOUT=0s"}, wantVar: "CANVAS_HTTP_WRITE_TIMEOUT"}, + {name: "an idle timeout of nothing", environ: []string{"CANVAS_HTTP_IDLE_TIMEOUT=0s"}, wantVar: "CANVAS_HTTP_IDLE_TIMEOUT"}, + {name: "a way out of nothing", environ: []string{"CANVAS_SHUTDOWN_TIMEOUT=0s"}, wantVar: "CANVAS_SHUTDOWN_TIMEOUT"}, + {name: "a way out too short to share", environ: []string{"CANVAS_SHUTDOWN_TIMEOUT=900ms"}, wantVar: "CANVAS_SHUTDOWN_TIMEOUT"}, + {name: "a deployed way out the platform cuts off", environ: append([]string{"CANVAS_SHUTDOWN_TIMEOUT=10s"}, deployed...), wantVar: "CANVAS_SHUTDOWN_TIMEOUT"}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + _, err := config.LoadFrom(tc.environ) + if !errors.Is(err, config.ErrInvalid) { + t.Fatalf("LoadFrom() error = %v, want ErrInvalid", err) + } + if !strings.Contains(err.Error(), tc.wantVar) { + t.Errorf("error = %q, want it to name %s", err, tc.wantVar) + } + }) + } +} + +func TestLoadReadsTheProcessEnvironment(t *testing.T) { + t.Setenv("PORT", "9100") + t.Setenv("CANVAS_LOG_LEVEL", "warn") + + cfg, err := config.Load() + if err != nil { + t.Fatalf("Load() error = %v, want nil", err) + } + if cfg.Port != "9100" { + t.Errorf("Port = %q, want %q", cfg.Port, "9100") + } + if cfg.LogLevel != "warn" { + t.Errorf("LogLevel = %q, want %q", cfg.LogLevel, "warn") + } +} + +// The drain and the close share one budget: together they are the whole way +// out, and the close keeps its quarter however long the drain could take. +func TestTheWayOutIsSharedRatherThanTakenTwice(t *testing.T) { + t.Parallel() + + for _, budget := range []time.Duration{time.Second, config.DefaultShutdownTimeout, 7 * time.Second} { + t.Run(budget.String(), func(t *testing.T) { + t.Parallel() + + cfg := &config.Config{ShutdownTimeout: budget} + if got := cfg.DrainTimeout() + cfg.CloseTimeout(); got != budget { + t.Errorf("drain + close = %v, want the whole way out, %v", got, budget) + } + if cfg.CloseTimeout() != budget/4 { + t.Errorf("close = %v, want the quarter of %v the drain leaves it", cfg.CloseTimeout(), budget) + } + }) + } +} diff --git a/internal/logger/logger.go b/internal/logger/logger.go new file mode 100644 index 0000000..a491c13 --- /dev/null +++ b/internal/logger/logger.go @@ -0,0 +1,120 @@ +// Package logger builds the one logger the service uses, and holds the rules +// for two things a line carries wherever it is written: the id of the request +// it belongs to, and what a panic was. +// +// The JSON encoder writes severity, message and time, which is what a log +// collector reads without being configured for us. It is the only reason this +// package differs from the platform's other services, which log ts in ISO +// 8601: a different collector reads their logs. +// +// The logger is injected into constructors and never kept in a package-level +// variable, so that a test can hand a component a logger it can read back. +package logger + +import ( + "fmt" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// New builds a logger for the given level and format: "json" for a deployed +// service, "console" for a terminal. A level or a format it does not know is +// refused, and so is a logger that cannot be built: a service whose log goes +// nowhere, or somewhere other than it was asked to, is one nobody can see. +func New(level, format string) (*zap.Logger, error) { + cfg, err := newConfig(level, format) + if err != nil { + return nil, err + } + built, err := cfg.Build() + if err != nil { + return nil, fmt.Errorf("logger: build: %w", err) + } + return built, nil +} + +// newConfig assembles what New builds from. It is its own function because +// several of its settings are decisions rather than defaults, and a test reads +// them here rather than inferring them from output. +func newConfig(level, format string) (zap.Config, error) { + parsed, err := zapcore.ParseLevel(level) + if err != nil { + return zap.Config{}, fmt.Errorf("logger: level: %w", err) + } + + var cfg zap.Config + switch format { + case "json": + cfg = zap.NewProductionConfig() + cfg.EncoderConfig = cloudRunEncoderConfig() + case "console": + cfg = zap.NewDevelopmentConfig() + cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder + default: + return zap.Config{}, fmt.Errorf("logger: format %q, want json or console", format) + } + cfg.Level = zap.NewAtomicLevelAt(parsed) + + // The format decides how a line looks and nothing else. zap's own + // development mode would make a terminal behave differently too — a + // DPanic that panics, stacks from warnings on. + cfg.Development = false + + // No stack of zap's own. It would be the stack of whoever wrote the line + // — for a request that failed, the middleware that logs it — beside a + // panic's own stack of the code that panicked, and on every line of an + // error that is described by its fields. + cfg.DisableStacktrace = true + + // No sampling. By default zap keeps the first hundred repeats of a message + // each second and drops most of the rest, and our messages are on purpose + // a small set of event names with the detail in the fields — so a burst of + // refusals is exactly the shape it would throw away. Everything we count + // is counted from these lines, and a number taken from a sample is wrong + // precisely when something is going wrong. + cfg.Sampling = nil + + // The log goes to stdout and the logger's own failures to stderr. A + // collector that labels a whole stream by the descriptor it came from + // would otherwise read every line as an error. + cfg.OutputPaths = []string{"stdout"} + cfg.ErrorOutputPaths = []string{"stderr"} + + return cfg, nil +} + +// cloudRunEncoderConfig renames zap's keys to the ones a log collector picks +// up: severity for the level, message for the text and time for the timestamp. +// Everything else stays as zap's production defaults. +func cloudRunEncoderConfig() zapcore.EncoderConfig { + cfg := zap.NewProductionEncoderConfig() + cfg.LevelKey = "severity" + cfg.MessageKey = "message" + cfg.TimeKey = "time" + cfg.EncodeTime = zapcore.RFC3339NanoTimeEncoder + cfg.EncodeLevel = cloudRunLevelEncoder + return cfg +} + +// cloudRunLevelEncoder writes zap's levels as the severity names a collector +// understands: its scale is ERROR, WARNING, INFO, DEBUG rather than zap's +// lowercase warn and dpanic. +func cloudRunLevelEncoder(level zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { + switch level { + case zapcore.DebugLevel: + enc.AppendString("DEBUG") + case zapcore.InfoLevel: + enc.AppendString("INFO") + case zapcore.WarnLevel: + enc.AppendString("WARNING") + case zapcore.ErrorLevel: + enc.AppendString("ERROR") + case zapcore.DPanicLevel, zapcore.PanicLevel: + enc.AppendString("CRITICAL") + case zapcore.FatalLevel: + enc.AppendString("EMERGENCY") + default: + enc.AppendString("DEFAULT") + } +} diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go new file mode 100644 index 0000000..1abf612 --- /dev/null +++ b/internal/logger/logger_test.go @@ -0,0 +1,212 @@ +package logger + +import ( + "bytes" + "encoding/json" + "fmt" + "strings" + "testing" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// The JSON encoder exists to be read by Cloud Logging without any further +// configuration, and that means three key names and one severity scale. A test +// that only checked "it logs something" would not notice the day one of them +// is renamed back to zap's default. +func TestJSONEncoderUsesCloudRunKeys(t *testing.T) { + t.Parallel() + + encoder := zapcore.NewJSONEncoder(cloudRunEncoderConfig()) + entry := zapcore.Entry{ + Level: zapcore.WarnLevel, + Time: time.Date(2026, 9, 21, 10, 30, 0, 0, time.UTC), + Message: "http_request", + } + + buf, err := encoder.EncodeEntry(entry, []zapcore.Field{{ + Key: "route", + Type: zapcore.StringType, + String: "/health", + }}) + if err != nil { + t.Fatalf("EncodeEntry() error = %v, want nil", err) + } + + var line map[string]any + if err := json.Unmarshal(buf.Bytes(), &line); err != nil { + t.Fatalf("the line is not JSON: %v; line = %s", err, buf.String()) + } + + for key, want := range map[string]string{ + "severity": "WARNING", + "message": "http_request", + "time": "2026-09-21T10:30:00Z", + "route": "/health", + } { + got, ok := line[key].(string) + if !ok { + t.Errorf("line[%q] is missing; line = %s", key, buf.String()) + continue + } + if got != want { + t.Errorf("line[%q] = %q, want %q", key, got, want) + } + } + + for _, absent := range []string{"level", "msg", "ts"} { + if _, found := line[absent]; found { + t.Errorf("line still has zap's default key %q; line = %s", absent, buf.String()) + } + } +} + +func TestSeverityNames(t *testing.T) { + t.Parallel() + + cases := map[zapcore.Level]string{ + zapcore.DebugLevel: "DEBUG", + zapcore.InfoLevel: "INFO", + zapcore.WarnLevel: "WARNING", + zapcore.ErrorLevel: "ERROR", + zapcore.DPanicLevel: "CRITICAL", + zapcore.PanicLevel: "CRITICAL", + zapcore.FatalLevel: "EMERGENCY", + // A level the scale has no name for is written as the collector's own + // word for "not said", rather than as nothing. + zapcore.Level(42): "DEFAULT", + } + + for level, want := range cases { + t.Run(level.String(), func(t *testing.T) { + t.Parallel() + encoder := zapcore.NewJSONEncoder(cloudRunEncoderConfig()) + buf, err := encoder.EncodeEntry(zapcore.Entry{Level: level, Message: "x"}, nil) + if err != nil { + t.Fatalf("EncodeEntry() error = %v, want nil", err) + } + var line map[string]any + if err := json.Unmarshal(buf.Bytes(), &line); err != nil { + t.Fatalf("the line is not JSON: %v", err) + } + if got := line["severity"]; got != want { + t.Errorf("severity = %v, want %q", got, want) + } + }) + } +} + +// A level or a format the logger does not know is refused rather than guessed +// at: a service whose log goes somewhere other than it was asked to is one +// nobody can see. +func TestNewRefusesWhatItDoesNotKnow(t *testing.T) { + t.Parallel() + + for _, c := range []struct{ level, format string }{ + {level: "loud", format: "json"}, + {level: "info", format: "yaml"}, + {level: "info", format: ""}, + } { + if log, err := New(c.level, c.format); err == nil { + t.Errorf("New(%q, %q) = %v, want a refusal", c.level, c.format, log) + } + } +} + +// The level asked for is the level written: info and nothing below it. +func TestNewWritesTheLevelAskedFor(t *testing.T) { + t.Parallel() + + log, err := New("info", "json") + if err != nil { + t.Fatalf("New() error = %v, want nil", err) + } + if !log.Core().Enabled(zapcore.InfoLevel) { + t.Error("info is disabled, want it enabled") + } + if log.Core().Enabled(zapcore.DebugLevel) { + t.Error("debug is enabled, want nothing below info") + } +} + +// Several settings of the configuration are decisions, not defaults, and all are +// easy to lose to a future refactor that starts from zap's own constructors. +func TestConfigurationDecisions(t *testing.T) { + t.Parallel() + + for _, format := range []string{"json", "console"} { + t.Run(format, func(t *testing.T) { + t.Parallel() + + cfg, err := newConfig("info", format) + if err != nil { + t.Fatalf("newConfig() error = %v, want nil", err) + } + + for _, decision := range []struct { + name string + got any + want any + }{ + // The counts are taken from these lines. + {name: "sampling off", got: cfg.Sampling == nil, want: true}, + // The only stacks are the ones the service writes. + {name: "zap's own stacks switched off", got: cfg.DisableStacktrace, want: true}, + // The format changes nothing but the format. + {name: "development mode", got: cfg.Development, want: false}, + {name: "output", got: fmt.Sprint(cfg.OutputPaths), want: "[stdout]"}, + {name: "the logger's own failures", got: fmt.Sprint(cfg.ErrorOutputPaths), want: "[stderr]"}, + } { + if decision.got != decision.want { + t.Errorf("%s = %v, want %v", decision.name, decision.got, decision.want) + } + } + }) + } +} + +// A field can never end the line it is in, whatever it carries. The code that +// writes each field keeps a caller's words out of it as far as it knows how, +// and the encoder is what keeps anything that still gets through harmless. +// +// The attack is a caller ending the line they are in and starting one of their +// own — a path of "/x\n{severity: ERROR, …}" becoming a second entry that +// nobody wrote. A JSON encoder escapes the newline, so the forgery stays inside +// the string it arrived in, and the fields it tried to forge keep the values +// this service gave them. +// +// This is the test that holds the encoder to that: swap it for one that does +// not escape and it goes red. +func TestAFieldCannotForgeASecondLine(t *testing.T) { + t.Parallel() + + var written bytes.Buffer + log := zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(cloudRunEncoderConfig()), + zapcore.AddSync(&written), + zapcore.DebugLevel, + )) + + forged := "/x\n{\"severity\":\"ERROR\",\"message\":\"a line nobody wrote\"}" + log.Info("http_request", zap.String("path", forged)) + + if extra := strings.Count(strings.TrimRight(written.String(), "\n"), "\n"); extra != 0 { + t.Errorf("the log holds %d lines, want exactly one", extra+1) + } + + var entry map[string]any + if err := json.Unmarshal(written.Bytes(), &entry); err != nil { + t.Fatalf("what was written is not one JSON object: %v", err) + } + if entry["path"] != forged { + t.Errorf("path = %q, want it kept whole and escaped", entry["path"]) + } + if entry["message"] != "http_request" { + t.Errorf("message = %q, want the forgery unable to replace it", entry["message"]) + } + if entry["severity"] != "INFO" { + t.Errorf("severity = %q, want the forgery unable to raise it", entry["severity"]) + } +} diff --git a/internal/logger/panic.go b/internal/logger/panic.go new file mode 100644 index 0000000..741480f --- /dev/null +++ b/internal/logger/panic.go @@ -0,0 +1,70 @@ +package logger + +import ( + "errors" + "fmt" + "reflect" + "runtime" + "strings" + + "go.uber.org/zap" +) + +// maxStackDepth is how many frames of a panicking goroutine's stack are read. +const maxStackDepth = 64 + +// PanicValue names what a panic was raised with, and none of what the code +// that raised it carried. A fault of the runtime is put in the runtime's own +// words, found inside whatever wrapped it, because those words hold types and +// numbers and no data. Anything else is a value of ours or a library's, which +// may hold a task, an answer or an image, so only its type is written: the +// stack beside it shows where it came from. +func PanicValue(recovered any) zap.Field { + var fault runtime.Error + if err, isError := recovered.(error); isError && errors.As(err, &fault) && ofTheRuntime(fault) { + return zap.String("panic", fault.Error()) + } + return zap.String("panic", fmt.Sprintf("a value of type %T", recovered)) +} + +// ofTheRuntime says whether a fault was made by the Go runtime itself. Any type +// can call itself a runtime error by having the method, and one that is not +// the runtime's may say anything at all. +func ofTheRuntime(fault runtime.Error) bool { + kind := reflect.TypeOf(fault) + for kind.Kind() == reflect.Pointer { + kind = kind.Elem() + } + return kind.PkgPath() == "runtime" +} + +// PanicStack is the stack of the goroutine that is panicking, from the code +// that panicked down. It is read from inside the deferred function that +// recovered, while the panic is still on the stack. What stands above the +// panicking code is left off: the recovery that caught the panic, and the +// runtime's own frames — one for a panic called by name, a few more for a +// fault the runtime raised itself — so that the first line a reader sees is +// the line that failed. +func PanicStack() zap.Field { + callers := make([]uintptr, maxStackDepth) + frames := runtime.CallersFrames(callers[:runtime.Callers(1, callers)]) + + var stack strings.Builder + panicking, reached := false, false + for { + frame, more := frames.Next() + switch { + case reached: + case frame.Function == "runtime.gopanic": + panicking = true + case panicking && !strings.HasPrefix(frame.Function, "runtime."): + reached = true + } + if reached { + fmt.Fprintf(&stack, "%s\n\t%s:%d\n", frame.Function, frame.File, frame.Line) + } + if !more { + return zap.String("stack", stack.String()) + } + } +} diff --git a/internal/logger/panic_test.go b/internal/logger/panic_test.go new file mode 100644 index 0000000..f55d34c --- /dev/null +++ b/internal/logger/panic_test.go @@ -0,0 +1,82 @@ +package logger + +import ( + "errors" + "fmt" + "strings" + "testing" + + "go.uber.org/zap" +) + +// impostor calls itself a fault of the runtime, and is not one. +type impostor struct{} + +func (impostor) Error() string { return "the answer is 36" } +func (impostor) RuntimeError() {} + +// outOfRange is a fault the runtime raises itself, caught as a value. +func outOfRange() (fault error) { + defer func() { + fault, _ = recover().(error) + }() + fill(nil, 1) + return nil +} + +// fill writes into a list of jugs, past its end when the list is too short. +func fill(jugs []int, at int) { jugs[at] = 1 } + +// A panic is named in words that hold no data: the runtime's own for a fault it +// raised, wherever that fault was wrapped, and the type alone for anything +// else — which may hold a task, an answer or an image. +func TestAPanicIsNamedByWhatItIs(t *testing.T) { + t.Parallel() + + fault := outOfRange() + cases := []struct { + name string + recovered any + want string + }{ + {name: "a fault of the runtime", recovered: fault, want: fault.Error()}, + {name: "a fault of the runtime, wrapped", recovered: fmt.Errorf("filling the jug of masha: %w", fault), want: fault.Error()}, + {name: "an error of ours", recovered: errors.New("the answer is C"), want: "a value of type *errors.errorString"}, + {name: "a text", recovered: "the answer is C", want: "a value of type string"}, + {name: "a value that calls itself a fault of the runtime", recovered: impostor{}, want: "a value of type logger.impostor"}, + {name: "the same behind a pointer", recovered: &impostor{}, want: "a value of type *logger.impostor"}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if got := PanicValue(tc.recovered).String; got != tc.want { + t.Errorf("panic = %q, want %q", got, tc.want) + } + }) + } +} + +// The stack of a panic begins at the code that panicked, not at the recovery +// that caught it or in the runtime between the two. +func TestAPanicsStackBeginsWhereItPanicked(t *testing.T) { + t.Parallel() + + var stack zap.Field + func() { + defer func() { + if recover() != nil { + stack = PanicStack() + } + }() + panickingCode() + }() + + first, _, _ := strings.Cut(stack.String, "\n") + if !strings.HasSuffix(first, ".panickingCode") { + t.Errorf("the stack begins at %q, want the code that panicked", first) + } +} + +// panickingCode is the code a stack is expected to begin at. +func panickingCode() { panic("the answer is C") } diff --git a/internal/logger/request.go b/internal/logger/request.go new file mode 100644 index 0000000..65fc981 --- /dev/null +++ b/internal/logger/request.go @@ -0,0 +1,22 @@ +package logger + +import "context" + +// requestIDKey holds the id of the request a context belongs to. It is a type +// of its own, so that nothing else a context carries can be taken for it. +type requestIDKey struct{} + +// WithRequestID returns a copy of ctx that carries the id every line of one +// request shares. The id travels in the context rather than beside it because +// a line is often written far from the code that received the request — inside +// a handler another library calls — and the context is the one thing that +// reaches that far. +func WithRequestID(ctx context.Context, id string) context.Context { + return context.WithValue(ctx, requestIDKey{}, id) +} + +// RequestID returns the id WithRequestID put in ctx, or an empty string. +func RequestID(ctx context.Context) string { + id, _ := ctx.Value(requestIDKey{}).(string) + return id +} diff --git a/internal/logger/request_test.go b/internal/logger/request_test.go new file mode 100644 index 0000000..39972ea --- /dev/null +++ b/internal/logger/request_test.go @@ -0,0 +1,20 @@ +package logger + +import ( + "context" + "testing" +) + +// The id a request is correlated by travels in its context, and a context +// that never received one says so with an empty id rather than a made-up one. +func TestARequestIDTravelsInTheContext(t *testing.T) { + t.Parallel() + + if got := RequestID(context.Background()); got != "" { + t.Errorf("RequestID() of a context without one = %q, want empty", got) + } + ctx := WithRequestID(context.Background(), "01a0dd9a") + if got := RequestID(ctx); got != "01a0dd9a" { + t.Errorf("RequestID() = %q, want %q", got, "01a0dd9a") + } +} diff --git a/internal/transport/http/health.go b/internal/transport/http/health.go new file mode 100644 index 0000000..0e75105 --- /dev/null +++ b/internal/transport/http/health.go @@ -0,0 +1,32 @@ +package httpserver + +import ( + "net/http" + + "github.com/gin-gonic/gin" + + "github.com/MathTrail/canvas-api/internal/version" +) + +// healthResponse is the body of the probe. It is a type rather than a map so +// that the shape of the answer is stated once, in one place, and a mistyped +// key is a compile error instead of a field nobody notices is missing. +type healthResponse struct { + Status string `json:"status"` + Version string `json:"version"` + Commit string `json:"commit"` +} + +// health says the process is up and serving, and which build it is: the +// delivery reads the commit here to know that the revision it rolled out is +// the one that answers, so no cache on the way may answer for it. It checks +// nothing else on purpose: a probe that reached for a dependency would turn +// that dependency's outage into restarts of this service. +func health(c *gin.Context) { + c.Header("Cache-Control", "no-store") + c.JSON(http.StatusOK, healthResponse{ + Status: "ok", + Version: version.Version, + Commit: version.Commit, + }) +} diff --git a/internal/transport/http/middleware/logger.go b/internal/transport/http/middleware/logger.go new file mode 100644 index 0000000..cb475bc --- /dev/null +++ b/internal/transport/http/middleware/logger.go @@ -0,0 +1,98 @@ +package middleware + +import ( + "errors" + "fmt" + "syscall" + "time" + + "github.com/gin-gonic/gin" + "go.uber.org/zap" +) + +// ZapLogger logs one line per request: what was asked, what was answered and +// how long it took. Successful probes are skipped; anything that failed is +// always logged. +// +// What was asked is the route the request matched and its method, each from a +// set this service wrote down, and never the path, the query or the verb as a +// caller wrote them: those are the caller's own words, and a log line carries +// none. +func ZapLogger(logger *zap.Logger) gin.HandlerFunc { + return func(c *gin.Context) { + start := time.Now() + // Read before the handlers run, both together: what was asked is a + // fact about the request, and by the time the answer exists the + // request may have been replaced by something downstream. The route + // is the framework's, and known before the first handler runs. + verb := method(c) + matched := route(c) + + c.Next() + + // A panic is always written, and as an error, whatever status the answer + // had got to: a handler can panic after it began a 200, and a probe can + // panic too. + status := c.Writer.Status() + panicFields, panicked := panicOf(c) + if isProbe(c) && status < 400 && !panicked { + return + } + + // A handler that wrote no body leaves the size at -1, which reads as + // nonsense in a log line; an answer with no body has a body of zero. + bodySize := max(c.Writer.Size(), 0) + + fields := []zap.Field{ + zap.Int("status", status), + zap.String("method", verb), + zap.String("route", matched), + zap.Duration("duration", time.Since(start)), + zap.Int("body_size", bodySize), + zap.String("request_id", RequestIDFrom(c)), + } + if errs := c.Errors.ByType(gin.ErrorTypePrivate); len(errs) > 0 { + fields = append(fields, errorsField(errs)) + } + fields = append(fields, panicFields...) + + switch { + case panicked || status >= 500: + logger.Error("http_request", fields...) + case status >= 400: + logger.Warn("http_request", fields...) + default: + logger.Info("http_request", fields...) + } + } +} + +// errorsField says what the errors a request collected were, and not what they +// said. The text of an error is whatever the code that made it had in hand: a +// write that failed names both ends of the connection, the address of whoever +// was at the other end among them. A fault of the system is given in the +// system's own words, which name the fault and nothing else, and anything else +// by its type — the same rule a panic is written by. +func errorsField(errs []*gin.Error) zap.Field { + kinds := make([]string, len(errs)) + for i, collected := range errs { + var fault syscall.Errno + if errors.As(collected.Err, &fault) { + kinds[i] = fault.Error() + } else { + kinds[i] = fmt.Sprintf("an error of type %T", collected.Err) + } + } + return zap.Strings("errors", kinds) +} + +// panicOf is what the request panicked with, as the recovery wrote it down, +// and whether it panicked at all. +func panicOf(c *gin.Context) ([]zap.Field, bool) { + recorded, found := c.Get(panicKey{}) + if !found { + return nil, false + } + fields, isFields := recorded.([]zap.Field) + return fields, isFields +} diff --git a/internal/transport/http/middleware/middleware_test.go b/internal/transport/http/middleware/middleware_test.go new file mode 100644 index 0000000..2ec2e06 --- /dev/null +++ b/internal/transport/http/middleware/middleware_test.go @@ -0,0 +1,673 @@ +package middleware_test + +import ( + "errors" + "fmt" + "net" + "net/http" + "net/http/httptest" + "net/url" + "os" + "strings" + "syscall" + "testing" + + "github.com/gin-gonic/gin" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/MathTrail/canvas-api/internal/transport/http/middleware" +) + +// A probe that answers normally is not worth a line; a probe that fails is. +func TestSuccessfulProbesAreNotLogged(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/health", func(c *gin.Context) { c.Status(http.StatusOK) }) + + serve(t, router, http.MethodGet, "/health") + + if logs.Len() != 0 { + t.Errorf("a successful probe wrote %d lines, want none", logs.Len()) + } +} + +func TestFailuresAreLoggedWithTheirRequestID(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/health", func(c *gin.Context) { c.Status(http.StatusServiceUnavailable) }) + + serve(t, router, http.MethodGet, "/health") + + line := onlyLine(t, logs) + if line.Level != zapcore.ErrorLevel { + t.Errorf("level = %v, want %v for a 5xx", line.Level, zapcore.ErrorLevel) + } + if field(t, line, "request_id") == "" { + t.Error("request_id is empty, want the id the request carried") + } +} + +// One request must not take the process down: another child is in the middle +// of a task on the same instance. +func TestAPanicBecomesAnAnswer(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/boom", func(_ *gin.Context) { panic("boom") }) + + rec := serve(t, router, http.MethodGet, "/boom") + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusInternalServerError) + } + if !strings.Contains(rec.Body.String(), "INTERNAL_ERROR") { + t.Errorf("body = %s, want a structured error", rec.Body.String()) + } + if rec.Body.String() != "" && strings.Contains(rec.Body.String(), "boom") { + t.Errorf("body = %s, want the panic's text kept out of the answer", rec.Body.String()) + } + if line := panickedLine(t, logs); line.Level != zapcore.ErrorLevel { + t.Errorf("level = %v, want %v for a panic", line.Level, zapcore.ErrorLevel) + } +} + +// Whatever a handler panicked with, the line says what kind of fault it was, as +// text in a field of a known type, and none of what the value carried: a value +// a handler panics with may hold a task or an answer. A fault of the runtime +// is told in the runtime's own words, which hold no data. +func TestAPanicIsLoggedAsText(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + panic func() + want string + }{ + {name: "an error", panic: func() { panic(errors.New("the jug is empty")) }, + want: "a value of type *errors.errorString"}, + {name: "anything else", panic: func() { panic(42) }, want: "a value of type int"}, + {name: "a fault of the runtime", panic: func() { fill(nil, 1) }, + want: "runtime error: index out of range [1] with length 0"}, + {name: "a fault of the runtime, wrapped", panic: func() { + panic(fmt.Errorf("while filling %q: %w", "the jug of the task", runtimeFault())) + }, want: "runtime error: index out of range [1] with length 0"}, + {name: "a value that calls itself a fault of the runtime", panic: func() { panic(impostor{}) }, + want: "a value of type middleware_test.impostor"}, + {name: "a fault of the runtime behind a pointer", panic: func() { countOf("six") }, + want: "interface conversion: interface {} is string, not int"}, + {name: "a value behind a pointer that calls itself a fault of the runtime", panic: func() { panic(&impostor{}) }, + want: "a value of type *middleware_test.impostor"}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/boom", func(_ *gin.Context) { tc.panic() }) + + serve(t, router, http.MethodGet, "/boom") + + // field fails the test unless the value is a string, which is the + // half of this that matters: a log field has a type on purpose. + if got := field(t, panickedLine(t, logs), "panic"); got != tc.want { + t.Errorf("panic = %q, want %q", got, tc.want) + } + }) + } +} + +func TestMain(m *testing.M) { + gin.SetMode(gin.TestMode) + os.Exit(m.Run()) +} + +func routerWithObservedLogs(t *testing.T) (*observer.ObservedLogs, *gin.Engine) { + t.Helper() + + core, logs := observer.New(zapcore.DebugLevel) + logger := zap.New(core) + + router := gin.New() + router.Use(middleware.LastResort(logger)) + router.Use(middleware.RequestID()) + router.Use(middleware.ZapLogger(logger)) + router.Use(middleware.ZapRecovery()) + return logs, router +} + +// panickedLine is the one line a panicked request is logged in: its request +// line, carrying what it panicked with, and no second line beside it. +func panickedLine(t *testing.T, logs *observer.ObservedLogs) *observer.LoggedEntry { + t.Helper() + + if others := logs.FilterMessage("panic").Len(); others != 0 { + t.Errorf("panic lines = %d beside the request line, want none", others) + } + line := onlyLine(t, logs) + if _, found := line.ContextMap()["panic"]; !found { + t.Fatalf("the request line says nothing of the panic: %v", line.ContextMap()) + } + return line +} + +// fill writes into a list of jugs, and indexes past the end of one too short: +// a fault of the runtime that no analysis of the code can see coming. +func fill(jugs []int, at int) { jugs[at] = 1 } + +// keep puts a value in a set by the value itself, which the runtime refuses from +// inside its own map code when the value cannot be hashed. +func keep(set map[any]bool, value any) { set[value] = true } + +// countOf reads an answer as a count, which the runtime refuses when it is not +// one — with the one fault it raises behind a pointer. +func countOf(answer any) int { + return answer.(int) //nolint:errcheck // the refusal is the fault under test +} + +// runtimeFault is the fault fill makes of a list too short, caught as a value. +func runtimeFault() error { + var fault error + func() { + defer func() { + if recovered, isError := recover().(error); isError { + fault = recovered + } + }() + fill(nil, 1) + }() + return fault +} + +// impostor is a value that calls itself a fault of the runtime, and is not one. +type impostor struct{} + +func (impostor) Error() string { return "the answer is 36" } +func (impostor) RuntimeError() {} + +func serve(t *testing.T, router *gin.Engine, method, target string) *httptest.ResponseRecorder { + t.Helper() + + req := httptest.NewRequestWithContext(t.Context(), method, target, http.NoBody) + rec := httptest.NewRecorder() + router.ServeHTTP(rec, req) + return rec +} + +func onlyLine(t *testing.T, logs *observer.ObservedLogs) *observer.LoggedEntry { + t.Helper() + + entries := logs.FilterMessage("http_request").All() + if len(entries) != 1 { + t.Fatalf("http_request lines = %d, want exactly 1", len(entries)) + } + return &entries[0] +} + +func field(t *testing.T, line *observer.LoggedEntry, key string) string { + t.Helper() + + value, found := line.ContextMap()[key] + if !found { + t.Fatalf("the line has no %q field: %v", key, line.ContextMap()) + } + text, ok := value.(string) + if !ok { + t.Fatalf("%q = %T, want a string", key, value) + } + return text +} + +// The errors a request collected are written by what they were, not by what +// they said: a write that failed names both ends of the connection, and an +// error of the service's own can carry whatever its code had in hand. +func TestACollectedErrorIsLoggedByItsKind(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/written", func(c *gin.Context) { + _ = c.Error(&net.OpError{ + Op: "write", + Net: "tcp", + Source: &net.TCPAddr{IP: net.IPv4(10, 0, 0, 2), Port: 8080}, + Addr: &net.TCPAddr{IP: net.IPv4(203, 0, 113, 9), Port: 51234}, + Err: os.NewSyscallError("write", syscall.EPIPE), + }) + _ = c.Error(errors.New("gemini: read the sheet of Otter")) + c.Status(http.StatusOK) + }) + + serve(t, router, http.MethodGet, "/written") + + line := onlyLine(t, logs).ContextMap() + want := []any{"broken pipe", "an error of type *errors.errorString"} + if got, isList := line["errors"].([]any); !isList || fmt.Sprint(got) != fmt.Sprint(want) { + t.Errorf("errors = %v, want %v", line["errors"], want) + } + for _, kept := range []string{"203.0.113.9", "Otter"} { + if strings.Contains(fmt.Sprint(line), kept) { + t.Errorf("the line carries %q, want the errors by their kind alone: %v", kept, line) + } + } +} + +// A panic in the middleware itself, above the recovery next to the handlers, +// is caught by the last resort: logged once, by its kind alone, and answered. +func TestAPanicAboveTheRecoveryIsCaughtByTheLastResort(t *testing.T) { + t.Parallel() + + core, logs := observer.New(zapcore.DebugLevel) + router := gin.New() + router.Use(middleware.LastResort(zap.New(core))) + router.Use(middleware.RequestID()) + router.Use(func(c *gin.Context) { + c.Next() + panic(errors.New("the answer is 36")) + }) + router.Use(middleware.ZapRecovery()) + router.GET("/fine", func(c *gin.Context) { c.Status(http.StatusNoContent) }) + + serve(t, router, http.MethodGet, "/fine") + + entries := logs.FilterMessage("panic").All() + if len(entries) != 1 { + t.Fatalf("panic lines = %d, want exactly 1", len(entries)) + } + if got := field(t, &entries[0], "panic"); got != "a value of type *errors.errorString" { + t.Errorf("panic = %q, want its type alone", got) + } + if field(t, &entries[0], "request_id") == "" { + t.Error("request_id is empty, want the id the request carried") + } +} + +// Both lines that name a request — its own line, and the last resort's when +// the middleware above the recovery panicked — name it by the route it matched +// and by a method from the known ones, never by what the caller wrote: a path +// carries identifiers, a path nothing matched is text the caller chose, and a +// verb can be any word at all. +func TestALineNamesTheRouteAndNotThePath(t *testing.T) { + t.Parallel() + + for _, kind := range []struct { + name string + line func(t *testing.T, method, target string) *observer.LoggedEntry + }{ + {name: "the request's own line", line: requestLine}, + {name: "the last resort's line", line: lastResortLine}, + } { + for _, tc := range []struct { + name, method, target, route, verb string + }{ + {"a route with a name in it", http.MethodGet, "/tasks/masha-ivanova", "/tasks/:id", http.MethodGet}, + {"a path nothing matched", http.MethodPost, + (&url.URL{Path: "/x\n{\"severity\":\"ERROR\",\"message\":\"masha ivanova\"}"}).EscapedPath(), + "other", http.MethodPost}, + {"a verb nobody defined", "MASHA", "/tasks/42", "other", "other"}, + } { + t.Run(kind.name+", "+tc.name, func(t *testing.T) { + t.Parallel() + + line := kind.line(t, tc.method, tc.target) + if got := field(t, line, "route"); got != tc.route { + t.Errorf("route = %q, want %q", got, tc.route) + } + if got := field(t, line, "method"); got != tc.verb { + t.Errorf("method = %q, want %q", got, tc.verb) + } + if written := strings.ToLower(fmt.Sprint(line.ContextMap())); strings.Contains(written, "masha") { + t.Errorf("the line carries what the caller wrote: %v", line.ContextMap()) + } + }) + } + } +} + +// requestLine serves one request through the request log and gives back its +// line. +func requestLine(t *testing.T, method, target string) *observer.LoggedEntry { + t.Helper() + + logs, router := routerWithObservedLogs(t) + router.GET("/tasks/:id", func(c *gin.Context) { c.Status(http.StatusNoContent) }) + serve(t, router, method, target) + return onlyLine(t, logs) +} + +// lastResortLine serves one request through middleware that panics above the +// recovery, and gives back the line the last resort wrote. +func lastResortLine(t *testing.T, method, target string) *observer.LoggedEntry { + t.Helper() + + core, logs := observer.New(zapcore.DebugLevel) + router := gin.New() + router.Use(middleware.LastResort(zap.New(core))) + router.Use(func(*gin.Context) { panic("the middleware is on fire") }) + router.GET("/tasks/:id", func(c *gin.Context) { c.Status(http.StatusNoContent) }) + serve(t, router, method, target) + + entries := logs.FilterMessage("panic").All() + if len(entries) != 1 { + t.Fatalf("panic lines = %d, want exactly 1", len(entries)) + } + return &entries[0] +} + +// An answer with no body has a body of zero, not the -1 the writer starts at. +func TestAnEmptyBodyIsLoggedAsZero(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/gone", func(c *gin.Context) { c.Status(http.StatusNotFound) }) + + serve(t, router, http.MethodGet, "/gone") + + size, found := onlyLine(t, logs).ContextMap()["body_size"] + if !found { + t.Fatal("the line has no body_size field") + } + if size != int64(0) { + t.Errorf("body_size = %v, want 0", size) + } +} + +// A handler that panicked halfway through its answer has already sent a status +// and headers, and a second one would corrupt what the client is reading. +func TestAPanicAfterTheAnswerHasStartedDoesNotWriteTwice(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/half", func(c *gin.Context) { + c.JSON(http.StatusOK, gin.H{"first": "part"}) + panic("boom") + }) + + rec := serve(t, router, http.MethodGet, "/half") + + if rec.Code != http.StatusOK { + t.Errorf("status = %d, want the %d the handler already sent", rec.Code, http.StatusOK) + } + if strings.Contains(rec.Body.String(), "INTERNAL_ERROR") { + t.Errorf("body = %s, want no second answer appended to the first", rec.Body.String()) + } + if line := panickedLine(t, logs); line.Level != zapcore.ErrorLevel { + t.Errorf("level = %v, want %v for a panic, whatever the answer had got to", line.Level, zapcore.ErrorLevel) + } +} + +// A probe that answers is not worth a line, and a probe that panicked is. +func TestAPanickedProbeIsLogged(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/health", func(c *gin.Context) { + c.Status(http.StatusOK) + c.Writer.WriteHeaderNow() + panic("boom") + }) + + serve(t, router, http.MethodGet, "/health") + + if line := panickedLine(t, logs); line.Level != zapcore.ErrorLevel { + t.Errorf("level = %v, want %v", line.Level, zapcore.ErrorLevel) + } +} + +// net/http documents ErrAbortHandler as the way to drop a request silently. +// It is passed on to the server bare, however it was wrapped, past everything +// that counts and logs: a request that asked for no answer is neither a panic +// nor an answer of 200. +func TestASilentAbortIsPassedOnToTheServer(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + abort error + }{ + {"an abort", http.ErrAbortHandler}, + {"an abort wrapped on the way", fmt.Errorf("proxy: %w", http.ErrAbortHandler)}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/abort", func(_ *gin.Context) { panic(tc.abort) }) + + if passed := servedPanic(t, router, "/abort"); passed != http.ErrAbortHandler { //nolint:errorlint // the server compares it by identity + t.Errorf("the server was handed %v, want %v", passed, http.ErrAbortHandler) + } + if lines := logs.Len(); lines != 0 { + t.Errorf("log lines = %d: %v, want none for a request that asked for no answer", lines, logs.All()) + } + }) + } +} + +// servedPanic serves one request, and returns what panicked out of the router +// to the server, if anything did. +func servedPanic(t *testing.T, router *gin.Engine, target string) (passed any) { + t.Helper() + + defer func() { passed = recover() }() + serve(t, router, http.MethodGet, target) + return nil +} + +// A connection that died under the service's own call — to Gemini, say — is +// a fault of the request, not the client hanging up: the client is still +// there, and it is answered and the fault written down. +func TestAConnectionOfOurOwnGoneIsAFault(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/check", func(_ *gin.Context) { + panic(&net.OpError{Op: "read", Err: os.NewSyscallError("read", syscall.ECONNRESET)}) + }) + + if rec := serve(t, router, http.MethodGet, "/check"); rec.Code != http.StatusInternalServerError { + t.Errorf("status = %d, want %d", rec.Code, http.StatusInternalServerError) + } + panickedLine(t, logs) +} + +// An id the client dictates is echoed back and written into every line about +// the request, so what a client may dictate is kept to what an id can be. +func TestOnlyAUsableRequestIDIsKept(t *testing.T) { + t.Parallel() + + kept := []struct { + name string + id string + }{ + {"a uuid", "01a0c467-8008-75c3-825b-37f804bf11bb"}, + {"a hex trace id", "4bf92f3577b34da6a3ce929d0e0e4736"}, + {"a traceparent", "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01"}, + } + for _, tc := range kept { + t.Run("kept: "+tc.name, func(t *testing.T) { + t.Parallel() + + if got := echoedRequestID(t, tc.id); got != tc.id { + t.Errorf("X-Request-Id = %q, want the id the client sent", got) + } + }) + } + + replaced := []struct { + name string + id string + }{ + {"a newline", "abc\r\nX-Injected: yes"}, + {"a control byte", "abc\x00def"}, + {"a quote", `abc"def`}, + {"a space", "two words"}, + {"letters outside ASCII", "идентификатор"}, + {"longer than the limit", strings.Repeat("a", 65)}, + } + for _, tc := range replaced { + t.Run("replaced: "+tc.name, func(t *testing.T) { + t.Parallel() + + got := echoedRequestID(t, tc.id) + if got == tc.id { + t.Errorf("X-Request-Id = %q, want it replaced", got) + } + if !usableLooking(got) { + t.Errorf("X-Request-Id = %q, want a plain identifier", got) + } + }) + } +} + +// A request the id middleware never saw has no id, and neither has a context +// with no request at all. +func TestNoIDIsReadWhereNoneWasSet(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + request *http.Request + }{ + {name: "no request", request: nil}, + {name: "a request the middleware never saw", + request: httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/x", http.NoBody)}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + c, _ := gin.CreateTestContext(httptest.NewRecorder()) + c.Request = tc.request + if id := middleware.RequestIDFrom(c); id != "" { + t.Errorf("RequestIDFrom() = %q, want no id", id) + } + }) + } +} + +func echoedRequestID(t *testing.T, sent string) string { + t.Helper() + + router := gin.New() + router.Use(middleware.RequestID()) + router.GET("/x", func(c *gin.Context) { c.Status(http.StatusOK) }) + + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/x", http.NoBody) + req.Header.Set(middleware.RequestIDHeader, sent) + rec := httptest.NewRecorder() + router.ServeHTTP(rec, req) + + return rec.Header().Get(middleware.RequestIDHeader) +} + +// usableLooking mirrors the rule the middleware applies, by bytes as it does: +// the package keeps that rule unexported, and a test that walked the string +// differently would agree with it only by accident. +func usableLooking(id string) bool { + if id == "" { + return false + } + for i := range len(id) { + r := id[i] + switch { + case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': + case r == '-', r == '_', r == '.', r == ':': + default: + return false + } + } + return true +} + +// panickingFunction is named so that the stack the recovery logs can be held +// to starting at the code that panicked rather than at the machinery that +// caught it. +func panickingFunction() { panic("boom") } + +// The stack starts at the code that panicked, whether it panicked by name or +// the runtime raised the fault, with neither the recovery nor the runtime's +// own frames above it: the first line a reader sees is the line that failed. +func TestThePanicStackStartsAtTheCodeThatPanicked(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name, want string + panic func() + }{ + {"a panic by name", "panickingFunction", panickingFunction}, + {"a fault of the runtime", "middleware_test.fill", func() { fill(nil, 1) }}, + {"a fault inside the runtime's own packages", "middleware_test.keep", func() { keep(map[any]bool{}, []int{1}) }}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + logs, router := routerWithObservedLogs(t) + router.GET("/boom", func(_ *gin.Context) { tc.panic() }) + + serve(t, router, http.MethodGet, "/boom") + + stack := field(t, panickedLine(t, logs), "stack") + first, _, _ := strings.Cut(stack, "\n") + if !strings.Contains(first, tc.want) { + t.Errorf("the stack starts at %q, want %s; whole stack:\n%s", first, tc.want, stack) + } + }) + } +} + +// Every answer carries what tells a browser how to treat it, a panic's answer +// included: the headers are set before anything below them runs. +func TestEveryAnswerCarriesTheSecurityHeaders(t *testing.T) { + t.Parallel() + + _, router := routerWithObservedLogs(t) + router.Use(middleware.SecurityHeaders()) + router.GET("/ok", func(c *gin.Context) { c.Status(http.StatusOK) }) + router.GET("/panics", func(*gin.Context) { panic("boom") }) + + for _, target := range []string{"/ok", "/panics"} { + rec := serve(t, router, http.MethodGet, target) + for header, want := range map[string]string{ + "Strict-Transport-Security": "max-age=31536000", + "X-Content-Type-Options": "nosniff", + "Referrer-Policy": "no-referrer", + } { + if got := rec.Header().Get(header); got != want { + t.Errorf("GET %s: %s = %q, want %q", target, header, got, want) + } + } + } +} + +// A handler that panics after it set headers for the answer it meant to give +// gets the error answered as JSON all the same: its type and its length are +// dropped, and what the chain put on every answer stays. +func TestAPanicDropsTheHeadersTheHandlerSet(t *testing.T) { + t.Parallel() + + _, router := routerWithObservedLogs(t) + router.GET("/image", func(c *gin.Context) { + c.Header("Content-Type", "image/png") + c.Header("Content-Length", "1234") + c.Header("Cache-Control", "public, max-age=31536000") + panic("boom") + }) + + rec := serve(t, router, http.MethodGet, "/image") + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusInternalServerError) + } + if got := rec.Header().Get("Content-Type"); !strings.HasPrefix(got, "application/json") { + t.Errorf("Content-Type = %q, want the error's own application/json", got) + } + for _, dropped := range []string{"Content-Length", "Cache-Control"} { + if got := rec.Header().Get(dropped); got != "" { + t.Errorf("%s = %q, want the handler's value dropped", dropped, got) + } + } + if rec.Header().Get(middleware.RequestIDHeader) == "" { + t.Errorf("%s is empty, want the request's id kept", middleware.RequestIDHeader) + } +} diff --git a/internal/transport/http/middleware/probe.go b/internal/transport/http/middleware/probe.go new file mode 100644 index 0000000..1610906 --- /dev/null +++ b/internal/transport/http/middleware/probe.go @@ -0,0 +1,22 @@ +package middleware + +import "github.com/gin-gonic/gin" + +// probeRoutes answer a machine rather than a person. The platform asks for them +// constantly and the answer is the same every time. +var probeRoutes = map[string]struct{}{ + "/health": {}, +} + +// isProbe reports whether a request matched one of those. +// +// The request log asks, and leaves a probe out: there are far more of them than +// there are checks, so a probe in the log buries the lines that mean +// something. +// +// It asks by the route, as everything else here names a request, so that the +// path a caller wrote is never read at all. +func isProbe(c *gin.Context) bool { + _, probe := probeRoutes[route(c)] + return probe +} diff --git a/internal/transport/http/middleware/recovery.go b/internal/transport/http/middleware/recovery.go new file mode 100644 index 0000000..870f7d7 --- /dev/null +++ b/internal/transport/http/middleware/recovery.go @@ -0,0 +1,116 @@ +package middleware + +import ( + "errors" + "net/http" + + "github.com/gin-gonic/gin" + "go.uber.org/zap" + + "github.com/MathTrail/canvas-api/internal/apierror" + "github.com/MathTrail/canvas-api/internal/logger" +) + +// panicKey holds, for the length of one request, what the request panicked +// with and where, so that the request's own line in the log says it. It is a +// type of its own, so that nothing else a request carries can be taken for it. +type panicKey struct{} + +// ZapRecovery turns a panic of a handler into a plain JSON answer. One request +// must not take the process down: another child is in the middle of a task on +// the same instance. +// +// It stands next to the handlers and writes no line of its own. What the +// request panicked with, and where, goes into the request's line, which the +// request log writes when it sees the answer: one fault, one line, and the +// panicked request logged like any other. +// +// A handler that panics with http.ErrAbortHandler, which is how net/http is +// told to end a response unfinished, is passed on as it asked: the server +// then drops the request silently, and nothing above takes it for an answer. +func ZapRecovery() gin.HandlerFunc { + return func(c *gin.Context) { + recovering(c, func(recovered any) { + c.Set(panicKey{}, []zap.Field{logger.PanicValue(recovered), logger.PanicStack()}) + }) + } +} + +// LastResort catches what ZapRecovery cannot: a panic in the middleware above +// it, whose request never reaches the request log. It writes the line itself, +// naming the request as the request log does, and answers and passes an abort +// on as ZapRecovery does. +func LastResort(log *zap.Logger) gin.HandlerFunc { + return func(c *gin.Context) { + recovering(c, func(recovered any) { + log.Error("panic", + logger.PanicValue(recovered), + logger.PanicStack(), + zap.String("method", method(c)), + zap.String("route", route(c)), + zap.String("request_id", RequestIDFrom(c)), + ) + }) + } +} + +// recovering runs the handlers after it and catches a panic of theirs: an +// abort is passed on to the server, and anything else is written down by +// record and answered. +func recovering(c *gin.Context, record func(recovered any)) { + defer func() { + recovered := recover() + switch { + case recovered == nil: + return + case aborted(recovered): + panic(http.ErrAbortHandler) + } + record(recovered) + answerPanic(c) + }() + c.Next() +} + +// aborted says whether a panic is a handler asking net/http to end its +// response unfinished, however it was wrapped on the way. It is passed on bare, +// because that is the one value the server knows to drop without a word. +func aborted(recovered any) bool { + err, isError := recovered.(error) + return isError && errors.Is(err, http.ErrAbortHandler) +} + +// everyAnswerCarries are the headers the middleware above the handlers puts on +// every answer, an answer to a panic included. +var everyAnswerCarries = map[string]struct{}{ + "Strict-Transport-Security": {}, + "X-Content-Type-Options": {}, + "Referrer-Policy": {}, + RequestIDHeader: {}, +} + +// answerPanic answers a request that panicked. A handler that panicked halfway +// through its answer has already sent a status and headers, and writing a +// second one corrupts what the client is reading: all that is left then is to +// stop. +// +// What the handler had already put in the headers is dropped first: a type, a +// length or a caching rule it set for the answer it meant to give would +// otherwise go out with the error in its place. What the chain above put there +// for every answer stays. +func answerPanic(c *gin.Context) { + if c.Writer.Written() { + c.Abort() + return + } + header := c.Writer.Header() + for name := range header { + if _, kept := everyAnswerCarries[name]; !kept { + header.Del(name) + } + } + c.AbortWithStatusJSON(http.StatusInternalServerError, apierror.Response{ + Code: apierror.CodeInternal, + Message: "an unexpected error occurred", + }) +} diff --git a/internal/transport/http/middleware/requestid.go b/internal/transport/http/middleware/requestid.go new file mode 100644 index 0000000..8c3a2e8 --- /dev/null +++ b/internal/transport/http/middleware/requestid.go @@ -0,0 +1,98 @@ +// Package middleware holds the gin middleware every request passes through. +package middleware + +import ( + "strconv" + "sync/atomic" + "time" + + "github.com/gin-gonic/gin" + "github.com/google/uuid" + + "github.com/MathTrail/canvas-api/internal/logger" +) + +// RequestIDHeader is the header a request is correlated by. +const RequestIDHeader = "X-Request-Id" + +// requestsSeen is what keeps two fallback identifiers apart when the source +// of randomness has stopped answering. +var requestsSeen atomic.Uint64 + +// maxRequestIDLength bounds what a client may dictate: an id is a correlation +// handle, and an unbounded one is a way to write anything into a log line. +const maxRequestIDLength = 64 + +// RequestID gives every request an id and echoes it back. A client that sends +// a usable one keeps it, so that a trace through somebody else's logs and a +// trace through ours use the same word; anything else is replaced. +// +// The id is kept in the request's context, the one place both the handlers of +// this framework and code that knows nothing of it can read it from, so that +// every line of the request carries one id. +func RequestID() gin.HandlerFunc { + return func(c *gin.Context) { + id := c.GetHeader(RequestIDHeader) + if !usableRequestID(id) { + id = newRequestID() + } + c.Request = c.Request.WithContext(logger.WithRequestID(c.Request.Context(), id)) + c.Header(RequestIDHeader, id) + c.Next() + } +} + +// usableRequestID reports whether a client's id can be carried as it stands. +// +// The alphabet is deliberately narrow: letters, digits and the four separators +// every correlation format in the wild is built from — a UUID, a hex trace id +// and a W3C traceparent all fit, and nothing else needs to. What it keeps out +// is a value that means something to a reader rather than to a machine: a +// newline, a control byte, a quote. Neither our JSON log nor the header writer +// would be fooled by one today, but the id also travels into whatever we +// correlate with next, and this is the one place that can be said once. +func usableRequestID(id string) bool { + if id == "" || len(id) > maxRequestIDLength { + return false + } + for _, b := range []byte(id) { + switch { + case b >= 'a' && b <= 'z', b >= 'A' && b <= 'Z', b >= '0' && b <= '9': + case b == '-', b == '_', b == '.', b == ':': + default: + return false + } + } + return true +} + +// newRequestID prefers a version 7 identifier, whose leading bits are a +// timestamp, so that ids sort by the order the requests arrived. +// +// A second kind of identifier would be no use as a fallback: every version +// asks the same source of randomness, so they fail together, and the one that +// takes no error panics instead of saying so. What follows a failure is the +// clock and a counter — a correlation handle is not a secret, and two lines +// only have to be told apart. +func newRequestID() string { + if v7, err := uuid.NewV7(); err == nil { + return v7.String() + } + return fallbackRequestID() +} + +// fallbackRequestID is what a request is correlated by when there is no +// randomness to be had. The clock puts ids in the order they were handed out, +// and the counter keeps two within the same nanosecond apart. +func fallbackRequestID() string { + return strconv.FormatInt(time.Now().UnixNano(), 36) + "-" + + strconv.FormatUint(requestsSeen.Add(1), 36) +} + +// RequestIDFrom returns the request id set by RequestID, or an empty string. +func RequestIDFrom(c *gin.Context) string { + if c.Request == nil { + return "" + } + return logger.RequestID(c.Request.Context()) +} diff --git a/internal/transport/http/middleware/requestid_internal_test.go b/internal/transport/http/middleware/requestid_internal_test.go new file mode 100644 index 0000000..ea7823e --- /dev/null +++ b/internal/transport/http/middleware/requestid_internal_test.go @@ -0,0 +1,115 @@ +package middleware + +import ( + "errors" + "net/http" + "net/http/httptest" + "strings" + "testing" + "testing/iotest" + + "github.com/gin-gonic/gin" + "github.com/google/uuid" + + "github.com/MathTrail/canvas-api/internal/logger" +) + +// When the source of randomness stops answering there is still a request to +// correlate. The identifier that follows has to pass the same rule as any +// other, and two of them have to be different. +func TestTheFallbackIdentifierIsUsableAndUnique(t *testing.T) { + t.Parallel() + + first := fallbackRequestID() + second := fallbackRequestID() + + for _, id := range []string{first, second} { + if !usableRequestID(id) { + t.Errorf("fallbackRequestID() = %q, want an id the middleware would keep", id) + } + } + if first == second { + t.Errorf("two identifiers came back the same: %q", first) + } +} + +// A request that arrives once the source of randomness has stopped answering +// is still given an identifier: the fallback, under the same rule and just as +// different from the one before it. +func TestAnIdentifierIsMadeWithoutRandomness(t *testing.T) { + // Not parallel: the source of randomness belongs to the whole process, and + // it is put back before any test that runs in parallel starts. + uuid.SetRand(iotest.ErrReader(errors.New("no randomness left"))) + t.Cleanup(func() { uuid.SetRand(nil) }) + + first, second := newRequestID(), newRequestID() + for _, id := range []string{first, second} { + if !usableRequestID(id) { + t.Errorf("newRequestID() = %q, want an id the middleware would keep", id) + } + } + if first == second { + t.Errorf("two requests were given the same id %q, want them told apart", first) + } +} + +// Whatever a client sends as its request id, the id the request is known by +// is one the rule keeps — short, and made only of the bytes a correlation +// format is built from — and a client's id is kept exactly when the rule keeps +// it. The header is the one part of a request the skeleton reads as it was +// written, so this is what a log line and an answer can never be made to carry. +func FuzzRequestID(f *testing.F) { + for _, seed := range []string{ + "", + "from-the-caller", + "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01", + "line\nbreak", + `"quoted"`, + strings.Repeat("a", 64), + strings.Repeat("a", 65), + "\x00", + "ünïcödé", + } { + f.Add(seed) + } + + gin.SetMode(gin.TestMode) + router := gin.New() + router.Use(RequestID()) + router.GET("/", func(c *gin.Context) { + c.String(http.StatusOK, logger.RequestID(c.Request.Context())) + }) + + f.Fuzz(func(t *testing.T, sent string) { + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody) + req.Header[RequestIDHeader] = []string{sent} + rec := httptest.NewRecorder() + router.ServeHTTP(rec, req) + + echoed := rec.Header().Get(RequestIDHeader) + if !plainIdentifier(echoed) { + t.Fatalf("echoed id %q for %q, want 1 to 64 letters, digits, '-', '_', '.' or ':'", echoed, sent) + } + if logged := rec.Body.String(); logged != echoed { + t.Fatalf("the context carries %q, the header %q, want one id", logged, echoed) + } + if plainIdentifier(sent) != (echoed == sent) { + t.Fatalf("sent %q, echoed %q: a client's id is kept exactly when the rule keeps it", sent, echoed) + } + }) +} + +// plainIdentifier is the rule a request id is held to, written out here apart +// from the code it checks, so that a rule loosened there is caught rather than +// agreed with. +func plainIdentifier(id string) bool { + if id == "" || len(id) > 64 { + return false + } + for _, r := range id { + if !strings.ContainsRune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789-_.:", r) { + return false + } + } + return true +} diff --git a/internal/transport/http/middleware/route.go b/internal/transport/http/middleware/route.go new file mode 100644 index 0000000..df7ceb6 --- /dev/null +++ b/internal/transport/http/middleware/route.go @@ -0,0 +1,49 @@ +package middleware + +import ( + "net/http" + + "github.com/gin-gonic/gin" +) + +// otherLabel stands for anything outside the closed sets this service wrote +// down, the ones below, which a request is called by in a line of the log. It +// says that something was there, and nothing of what it was: a log line that +// carries what a caller wrote carries whatever they chose to write there. +const otherLabel = "other" + +// knownMethods is the closed set a request's method is reported as. Anything +// else is a caller inventing a verb, and it is reported as one kind. +var knownMethods = map[string]struct{}{ + http.MethodGet: {}, + http.MethodHead: {}, + http.MethodPost: {}, + http.MethodPut: {}, + http.MethodPatch: {}, + http.MethodDelete: {}, + http.MethodOptions: {}, + http.MethodConnect: {}, + http.MethodTrace: {}, +} + +// route is the pattern the request matched, never the path it asked for. A +// path carries identifiers, one per sheet or task a log line would then +// spread; and a path nothing matched is text a caller wrote, as able to carry +// a name as anything else they write. +// +// The framework knows the pattern before the first handler runs, so every +// middleware can ask, a panicking one included. +func route(c *gin.Context) string { + if matched := c.FullPath(); matched != "" { + return matched + } + return otherLabel +} + +// method is the request's verb when it is one of the known ones. +func method(c *gin.Context) string { + if _, known := knownMethods[c.Request.Method]; known { + return c.Request.Method + } + return otherLabel +} diff --git a/internal/transport/http/middleware/security.go b/internal/transport/http/middleware/security.go new file mode 100644 index 0000000..1423695 --- /dev/null +++ b/internal/transport/http/middleware/security.go @@ -0,0 +1,20 @@ +package middleware + +import "github.com/gin-gonic/gin" + +// SecurityHeaders puts on every answer what tells a browser how to treat it: +// reach this host over HTTPS only, for a year; believe the type an answer +// declares rather than guess another; and send no address of ours onward in a +// referrer. +// +// They are set before anything else runs, so that every answer carries them — +// a refusal and an answer to a panic included. +func SecurityHeaders() gin.HandlerFunc { + return func(c *gin.Context) { + header := c.Writer.Header() + header.Set("Strict-Transport-Security", "max-age=31536000") + header.Set("X-Content-Type-Options", "nosniff") + header.Set("Referrer-Policy", "no-referrer") + c.Next() + } +} diff --git a/internal/transport/http/router.go b/internal/transport/http/router.go new file mode 100644 index 0000000..8378fff --- /dev/null +++ b/internal/transport/http/router.go @@ -0,0 +1,69 @@ +// Package httpserver builds the HTTP surface of the service. +package httpserver + +import ( + "net/http" + + "github.com/gin-gonic/gin" + "go.uber.org/zap" + + "github.com/MathTrail/canvas-api/internal/apierror" + "github.com/MathTrail/canvas-api/internal/transport/http/middleware" +) + +// NewRouter builds the service's router: the middleware every request passes +// through, in the order each one needs the others, and the routes it serves. +// +// The order is the point. The last resort comes first, so that a panic in any +// middleware below it is still answered and written down. The security headers +// come next, so that every answer carries them, a refusal and the answer to a +// panic included. The request id comes before the log, so that the request's +// line carries it, and the recovery comes last, next to the handlers, so that +// the request's own line says what it panicked with. What decides who may ask +// at all — the origins a browser may call from, then the access key — joins +// the chain after the recovery, with the first routes that need it. +func NewRouter(log *zap.Logger) *gin.Engine { + router := gin.New() + + // A path asked with a method it does not take is told so, with the methods + // it does take, rather than that it does not exist. + router.HandleMethodNotAllowed = true + + // A path with a slash too many is a path nobody declared. A redirect would + // answer it with a second request the client never meant to make. + router.RedirectTrailingSlash = false + + router.Use(middleware.LastResort(log)) + router.Use(middleware.SecurityHeaders()) + router.Use(middleware.RequestID()) + router.Use(middleware.ZapLogger(log)) + router.Use(middleware.ZapRecovery()) + + router.NoRoute(notFound) + router.NoMethod(methodNotAllowed) + + // /health rather than /healthz: Cloud Run's front end intercepts paths + // that end in z. HEAD is answered wherever GET is, since a probe may ask + // either way. + router.GET("/health", health) + router.HEAD("/health", health) + + return router +} + +// notFound answers a path the service does not serve. +func notFound(c *gin.Context) { + c.JSON(http.StatusNotFound, apierror.Response{ + Code: apierror.CodeNotFound, + Message: "no such endpoint", + }) +} + +// methodNotAllowed answers a path asked with a method it does not take. The +// framework has already put the methods it does take in the Allow header. +func methodNotAllowed(c *gin.Context) { + c.JSON(http.StatusMethodNotAllowed, apierror.Response{ + Code: apierror.CodeMethodNotAllowed, + Message: "this endpoint does not accept that method", + }) +} diff --git a/internal/transport/http/router_test.go b/internal/transport/http/router_test.go new file mode 100644 index 0000000..771807a --- /dev/null +++ b/internal/transport/http/router_test.go @@ -0,0 +1,202 @@ +package httpserver_test + +import ( + "encoding/json" + "maps" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + + "github.com/gin-gonic/gin" + "go.uber.org/zap/zaptest" + + "github.com/MathTrail/canvas-api/internal/apierror" + httpserver "github.com/MathTrail/canvas-api/internal/transport/http" + "github.com/MathTrail/canvas-api/internal/transport/http/middleware" + "github.com/MathTrail/canvas-api/internal/version" +) + +// The framework keeps its mode in a package variable. A test binary sets it +// once, here, rather than letting a constructor decide it for every other test +// running beside it. +func TestMain(m *testing.M) { + gin.SetMode(gin.TestMode) + os.Exit(m.Run()) +} + +// The probe names the build that answers it, and nothing on the way may keep +// the answer: the delivery reads the commit to know which revision serves, in +// exactly the shape it checks. +func TestHealthNamesTheBuild(t *testing.T) { + stamp(t) + + rec := call(t, http.MethodGet, "/health") + + if rec.Code != http.StatusOK { + t.Fatalf("GET /health status = %d, want %d", rec.Code, http.StatusOK) + } + if got := rec.Header().Get("Cache-Control"); got != "no-store" { + t.Errorf("Cache-Control = %q, want %q", got, "no-store") + } + if got := rec.Header().Get("Content-Type"); !strings.HasPrefix(got, "application/json") { + t.Errorf("Content-Type = %q, want application/json", got) + } + var body map[string]string + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatalf("the body is not a JSON object of strings: %v; body = %s", err, rec.Body.String()) + } + want := map[string]string{"status": "ok", "version": "v1.2.3", "commit": "abc1234"} + if !maps.Equal(body, want) { + t.Errorf("body = %v, want %v", body, want) + } +} + +// The service answers its health probe and nothing else. HEAD is answered +// wherever GET is, since a probe may ask either way; /healthz is not the +// probe, because Cloud Run's front end keeps that path for itself. +func TestRoutes(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + method string + path string + want int + }{ + {name: "the health probe", method: http.MethodGet, path: "/health", want: http.StatusOK}, + {name: "the health probe asked with HEAD", method: http.MethodHead, path: "/health", want: http.StatusOK}, + {name: "the path Cloud Run intercepts", method: http.MethodGet, path: "/healthz", want: http.StatusNotFound}, + {name: "a slash too many", method: http.MethodGet, path: "/health/", want: http.StatusNotFound}, + {name: "an unknown path", method: http.MethodGet, path: "/unknown", want: http.StatusNotFound}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if rec := call(t, tc.method, tc.path); rec.Code != tc.want { + t.Errorf("%s %s status = %d, want %d", tc.method, tc.path, rec.Code, tc.want) + } + }) + } +} + +// A refusal is the flat error body, with a code a client can branch on and a +// sentence it can relay. +func TestRefusals(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + name string + method string + path string + wantStatus int + wantCode string + }{ + {name: "an unknown path", method: http.MethodGet, path: "/nope", wantStatus: http.StatusNotFound, wantCode: apierror.CodeNotFound}, + {name: "a method the path does not take", method: http.MethodPost, path: "/health", wantStatus: http.StatusMethodNotAllowed, wantCode: apierror.CodeMethodNotAllowed}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + rec := call(t, tc.method, tc.path) + + if rec.Code != tc.wantStatus { + t.Fatalf("status = %d, want %d", rec.Code, tc.wantStatus) + } + var body apierror.Response + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatalf("body is not an apierror.Response: %v; body = %s", err, rec.Body.String()) + } + if body.Code != tc.wantCode { + t.Errorf("code = %q, want %q", body.Code, tc.wantCode) + } + if body.Message == "" { + t.Error("message is empty, want a sentence that can be relayed") + } + }) + } +} + +// A 405 says which methods the path does take. +func TestA405SaysWhichMethodsWork(t *testing.T) { + t.Parallel() + + rec := call(t, http.MethodPost, "/health") + + if rec.Code != http.StatusMethodNotAllowed { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusMethodNotAllowed) + } + if got, want := rec.Header().Get("Allow"), "GET, HEAD"; got != want { + t.Errorf("Allow = %q, want %q", got, want) + } +} + +// Every answer carries a request id and the security headers, a refusal +// included: the chain runs before the router decides there is nothing to +// serve. +func TestEveryAnswerCarriesItsIDAndTheSecurityHeaders(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + method string + path string + }{ + {method: http.MethodGet, path: "/health"}, + {method: http.MethodGet, path: "/nope"}, + {method: http.MethodPost, path: "/health"}, + } { + t.Run(tc.method+" "+tc.path, func(t *testing.T) { + t.Parallel() + + rec := call(t, tc.method, tc.path) + + if rec.Header().Get(middleware.RequestIDHeader) == "" { + t.Errorf("%s is empty, want an id on every answer", middleware.RequestIDHeader) + } + for header, want := range map[string]string{ + "Strict-Transport-Security": "max-age=31536000", + "X-Content-Type-Options": "nosniff", + "Referrer-Policy": "no-referrer", + } { + if got := rec.Header().Get(header); got != want { + t.Errorf("%s = %q, want %q", header, got, want) + } + } + }) + } +} + +func TestAClientsRequestIDIsKept(t *testing.T) { + t.Parallel() + + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/health", http.NoBody) + req.Header.Set(middleware.RequestIDHeader, "from-the-caller") + rec := httptest.NewRecorder() + httpserver.NewRouter(zaptest.NewLogger(t)).ServeHTTP(rec, req) + + if got := rec.Header().Get(middleware.RequestIDHeader); got != "from-the-caller" { + t.Errorf("%s = %q, want the id the client sent", middleware.RequestIDHeader, got) + } +} + +// call asks a fresh router for method and path. +func call(t *testing.T, method, path string) *httptest.ResponseRecorder { + t.Helper() + + req := httptest.NewRequestWithContext(t.Context(), method, path, http.NoBody) + rec := httptest.NewRecorder() + httpserver.NewRouter(zaptest.NewLogger(t)).ServeHTTP(rec, req) + return rec +} + +// stamp sets the build identity as the linker would, and puts the placeholders +// back when the test ends. The identity is the whole process's, so a test that +// stamps it does not run in parallel: the parallel tests wait until it is over. +func stamp(t *testing.T) { + t.Helper() + + was := [3]string{version.Version, version.Commit, version.Date} + version.Version, version.Commit, version.Date = "v1.2.3", "abc1234", "2026-10-12T00:00:00Z" + t.Cleanup(func() { version.Version, version.Commit, version.Date = was[0], was[1], was[2] }) +} From d9574eba1793fcf599564d2903157dff14324d93 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 16 Oct 2026 18:05:39 +0000 Subject: [PATCH 2/3] Give every request an id of the service's own and log the method from a closed set (T16, PR review) CodeQL flagged the request log and the last-resort line as carrying user input: the client's X-Request-Id and the request's method. No client of the service needs its id kept, so the header is no longer read; the method is written as one of the service's own words. Recorded as R68. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01U1MCDC5QUpgX5xmPSJYn5W --- RUN.md | 9 +- docs/decisions.md | 16 +++- .../http/middleware/middleware_test.go | 95 ++++++------------- .../transport/http/middleware/requestid.go | 40 +------- .../middleware/requestid_internal_test.go | 86 +++-------------- internal/transport/http/middleware/route.go | 43 +++++---- .../http/middleware/route_internal_test.go | 40 ++++++++ internal/transport/http/router_test.go | 9 +- 8 files changed, 135 insertions(+), 203 deletions(-) create mode 100644 internal/transport/http/middleware/route_internal_test.go diff --git a/RUN.md b/RUN.md index 3fbc383..790dd8c 100644 --- a/RUN.md +++ b/RUN.md @@ -555,12 +555,13 @@ - `internal/logger` — без изменений, кроме модуля и примеров в тестах; - `internal/apierror` — `{code, message}` и `details` с `omitempty`; коды `NOT_FOUND`, `METHOD_NOT_ALLOWED`, `INTERNAL_ERROR`. Остальные коды E2 придут с T18, T65 и T70; - `internal/transport/http` на gin — роутер, `/health` на GET и HEAD, 404 и 405 телом `apierror`; middleware в порядке образца: `LastResort`, `SecurityHeaders`, `RequestID`, `ZapLogger`, `ZapRecovery`. - - **Отличия от образца:** нет телеметрии, метрик, лимитов, проверки `Host` и `Origin`, полей query в логе и продуктовых маршрутов; заголовок — `X-Request-Id`, как в spec 8.1; `CANVAS_ENV` и его защита при `K_SERVICE` — своё; при `K_SERVICE` `CANVAS_SHUTDOWN_TIMEOUT` меньше 10 с — Cloud Run убивает экземпляр через 10 с после SIGTERM. Косвенные модули подняты до версий образца. + - **Отличия от образца:** нет телеметрии, метрик, лимитов, проверки `Host` и `Origin`, полей query в логе и продуктовых маршрутов; заголовок — `X-Request-Id`, как в spec 8.1, и id всегда свой: сервер не читает id клиента, а метод пишет одним из слов закрытого набора (R68); `CANVAS_ENV` и его защита при `K_SERVICE` — своё; при `K_SERVICE` `CANVAS_SHUTDOWN_TIMEOUT` меньше 10 с — Cloud Run убивает экземпляр через 10 с после SIGTERM. Косвенные модули подняты до версий образца. - **Облако:** `CANVAS_ENV=prod` в `service_api.tf` и тест `terraform test` на него. - **Ещё:** `.env.example`, `.vscode/launch.json` — локальный запуск и «как видит Cloud Run», `THIRD_PARTY_LICENSES`, spec 8.3 и 15.4. - - **Проверки** (облачная сессия; `just`, golangci-lint 2.14.0 и Terraform 1.16.3 скачаны по закреплённым версиям): зелёные `ci-lint`, `ci-test` (покрытие 97,6 %), `ci-mocks-check`, `ci-secrets`, `release-version`, `release-artifacts`, `terraform fmt -check`. Вживую: `/health` отвечает версией и коммитом, 404 и 405 — телом `apierror`, каждый ответ несёт `X-Request-Id`, строки лога — JSON с `severity`; с `K_SERVICE` и без `CANVAS_ENV=prod` сервис не стартует. - - **Выключены, чтобы доказать тесты, — 16 проверок, каждая краснила свой тест:** `local` и `console` при `K_SERVICE`, неизвестный `CANVAS_ENV`, предел `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании, имя переменной в точном регистре, `PORT` только цифрами, закрытие при сбое сборки, отдельный контекст закрытия, обратный порядок, `RequestID` в цепочке, `HEAD /health`, 405, порт до строки `startup`, сброс заголовков обработчика при панике, алфавит и длина `X-Request-Id` под fuzz. - - **Fuzz:** `FuzzRequestID` — заголовок `X-Request-Id`, единственный внешний ввод каркаса, — 60 с, без находок. Правило id в нём записано отдельно от кода: первая версия сверяла id тем же `usableRequestID` и пропустила ослабленное правило. + - **Проверки** (облачная сессия; `just`, golangci-lint 2.14.0 и Terraform 1.16.3 скачаны по закреплённым версиям): зелёные — и повторно после R68 — `ci-lint`, `ci-test` (покрытие 97,6 %; после R68 тест метода обходит весь закрытый набор), `ci-mocks-check`, `ci-secrets`, `release-version`, `release-artifacts`, `terraform fmt -check`. Вживую: `/health` отвечает версией и коммитом, 404 и 405 — телом `apierror`, каждый ответ несёт `X-Request-Id`, строки лога — JSON с `severity`; с `K_SERVICE` и без `CANVAS_ENV=prod` сервис не стартует. + - **Выключены, чтобы доказать тесты, — 17 проверок, каждая краснила свой тест:** `local` и `console` при `K_SERVICE`, неизвестный `CANVAS_ENV`, предел `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании, имя переменной в точном регистре, `PORT` только цифрами, закрытие при сбое сборки, отдельный контекст закрытия, обратный порядок, `RequestID` в цепочке, `HEAD /health`, 405, порт до строки `startup`, сброс заголовков обработчика при панике, id клиента не читается, метод только из закрытого набора, форма запасного id. + - **Fuzz:** нет. Был `FuzzRequestID` на заголовок `X-Request-Id` — 60 с без находок; он ушёл вместе с чтением заголовка (R68), и внешнего ввода каркас больше не разбирает. + - **PR #20, находки CodeQL `go/log-injection`** — четыре, на строке лога запроса и в `LastResort`: в них шли метод и id клиента. Id клиента не читается, метод пишется `switch` по закрытому набору (R68). Ревью правки — 8 находок: исправлено 7 — таблица-тождество методов заменена `switch`, а R68 говорит, что это не защита, а запись закрытого набора; общая проверка формы id получила предел длины; убраны тест-дубль уникальности id, случай «длиннее id» и неиспользуемый помощник; в RUN.md обновлены проверки; дата R68 названа явно. Отброшено 1: форму id в тесте роутера проверяет тест middleware. Второй круг — 6 находок: исправлено 5 — тесты сверяют id как UUID v7, а запасной — по своему узору, вместо общего широкого правила в двух копиях; таблица случаев сокращена до двух; тест роутера тоже требует UUID v7; `switch` метода и форма запасного id доказаны выключением. Отброшено 1: тест метода нарочно перечисляет набор отдельно от кода — так он и ловит расхождение. - **Ревью `/code-review high`, два круга.** - Первый — 9 находок. Исправлено 6: `.env.example` обещал, что `.env` прочтут, — теперь сказано, как его загрузить; занятый порт писался как сбой `shutdown` после строки `startup` — порт теперь занимается до неё; тесты `run()` зависели от переменных оболочки — они их обнуляют; `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании ограничен 10 с; повтор перехвата stdout в тесте заменён помощником; нет fuzz на `X-Request-Id` — добавлен. Отброшено 3: верхняя граница теста drain — тест о самих часах ставит свои сроки, как и в образце; 5-секундные сторожа ожиданий — предел для событий, которые занимают миллисекунды, а не мера скорости кода; список шагов контейнера — его требует задача (закрытие при сбое посередине), следующий ресурс принесёт T35. - Второй — 8 находок. Исправлено 5: ответ на панику нёс заголовки обработчика; имена переменных сравнивались без учёта регистра; `PORT` принимал `+8080` и `08080`; комментарий `Listen` называл вызов только тестовым; у четырёх полей тайм-аутов не было doc-комментариев. Отброшено 1: список шагов контейнера — повтор находки первого круга. В «Открыто» — 2, ниже. diff --git a/docs/decisions.md b/docs/decisions.md index 95f8687..ecfb6c7 100644 --- a/docs/decisions.md +++ b/docs/decisions.md @@ -8,7 +8,7 @@ > > Записи R37–R43 внесены 2026-10-11 при повороте к LLM-first. Записи, которые они заменили, остались на месте с пометкой «Заменено»: их текст не правится, а их «Отвергнуто» больше не действует. Записи, которые поворот только задел, поправлены на месте, и в конце каждой стоит «Поправка 2026-10-11». Запись R44 о плане эпиками внесена тогда же, по решению автора. Запись R45 о выкладке после релиза — тоже, при сверке с mathtrail-standalone. Запись R46 о намеренных отличиях devcontainer от образца внесена 2026-10-12 при сверке с ним (T60). Записи R47 о тулчейне SPA и R48 о лицензиях npm внесены тогда же, в T05. Запись R49 о CI и его отличиях от образца внесена 2026-10-13 в T06. Записи R50 о том, что держит мерж, и R51 о находках, которые остаются открытыми, внесены тогда же, в T07. > -> Записи R60–R67 внесены 2026-10-16 (T61) по решениям автора 2026-10-15, когда E2 стал минимальным срезом с замером Gemini, а закрытая бета — эпиком E15. Запись R40 они заменили, и она осталась на месте с пометкой «Заменено». Записи R22–R24, R35, R38, R39, R42, R44, R56 и R59 поправлены на месте, и в конце каждой стоит «Поправка 2026-10-15». +> Записи R60–R67 внесены 2026-10-16 (T61) по решениям автора 2026-10-15, когда E2 стал минимальным срезом с замером Gemini, а закрытая бета — эпиком E15. Запись R40 они заменили, и она осталась на месте с пометкой «Заменено». Записи R22–R24, R35, R38, R39, R42, R44, R56 и R59 поправлены на месте, и в конце каждой стоит «Поправка 2026-10-15». Запись R68 внесена 2026-10-16, в T16, по решению автора того же дня. ## Рамки и продукт @@ -644,6 +644,20 @@ Centrifugo сохраняет роль из R23. Событие `verdict` ухо — spec 3.2, 8.1, 20 (Т-1); RUN.md (T16, T18); R11, R12. +**R68. `X-Request-Id` всегда свой: сервер не читает id клиента, а в лог идут только его собственные слова о запросе.** Решение автора 2026-10-16, по находкам CodeQL `go/log-injection` в PR T16. +- Каждый запрос получает id сервера — UUID v7, а без источника случайности — время и счётчик. Id, присланный клиентом, не читается и не возвращается. +- Метод запроса пишется в лог одним из слов закрытого набора — `switch` по известным методам возвращает константу, неизвестный — `other`; путь пишется шаблоном маршрута. Набор был закрытым и в образце, и защиты это не прибавляет: `switch` — простейшая запись закрытого набора, а сканер видит в ней сравнение с константами. Это не экранирование чужого текста, которое отвергнуто ниже: в лог идёт слово сервиса. + +— *Почему:* образец сохраняет id клиента, если тот проходит белый список, чтобы след через чужие журналы и через наши шёл под одним словом. Здесь такого клиента нет: SPA id не шлёт, и CORS T65 его не пропустит — разрешены только `Authorization` и `Content-Type`. Сохранённый id клиента был бы единственной строкой лога, которую написал не сервер, — CodeQL указал на неё четырьмя находками. Правка убирает сам источник, а не прячет его от сканера. + +— *Отвергнуто:* +- сохранять id клиента по белому списку и закрыть находки как ложные, со ссылкой на fuzz-тест, как R111 standalone: держать чужой ввод в каждой строке лога ради возможности, которой никто не пользуется; +- `strings.ReplaceAll` перевода строки или `%q` в полях лога ради сканера — R111 standalone отверг это как защиту от того, что код и так не пропускает. + +— *Следствие:* `usableRequestID` и `FuzzRequestID` ушли вместе с чтением заголовка; внешнего ввода каркас больше не разбирает. Если клиент, которому нужен общий id, появится — это новое решение. + +— `internal/transport/http/middleware/requestid.go`, `route.go`; spec 8.1; R67; standalone: R111. + ## Идентификация и доступ **R14. Для Firebase используем Admin SDK (`firebase.google.com/go/v4`).** Через него проверяем ID token и App Check и удаляем пользователей. `golang-jwt/jwt/v5` нужен только для подписи токенов Centrifugo. `keyfunc` не используется. diff --git a/internal/transport/http/middleware/middleware_test.go b/internal/transport/http/middleware/middleware_test.go index 2ec2e06..7f897fe 100644 --- a/internal/transport/http/middleware/middleware_test.go +++ b/internal/transport/http/middleware/middleware_test.go @@ -13,6 +13,7 @@ import ( "testing" "github.com/gin-gonic/gin" + "github.com/google/uuid" "go.uber.org/zap" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest/observer" @@ -472,50 +473,35 @@ func TestAConnectionOfOurOwnGoneIsAFault(t *testing.T) { panickedLine(t, logs) } -// An id the client dictates is echoed back and written into every line about -// the request, so what a client may dictate is kept to what an id can be. -func TestOnlyAUsableRequestIDIsKept(t *testing.T) { +// An id a client sends is never kept, however well it is formed: the answer +// and the request's line in the log carry an id of the service's own, so that +// nothing a caller wrote reaches a log line by way of its id. +func TestAClientsIDIsNeverKept(t *testing.T) { t.Parallel() - kept := []struct { - name string - id string - }{ - {"a uuid", "01a0c467-8008-75c3-825b-37f804bf11bb"}, - {"a hex trace id", "4bf92f3577b34da6a3ce929d0e0e4736"}, - {"a traceparent", "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01"}, - } - for _, tc := range kept { - t.Run("kept: "+tc.name, func(t *testing.T) { - t.Parallel() - - if got := echoedRequestID(t, tc.id); got != tc.id { - t.Errorf("X-Request-Id = %q, want the id the client sent", got) - } - }) - } - - replaced := []struct { + for _, tc := range []struct { name string id string }{ - {"a newline", "abc\r\nX-Injected: yes"}, - {"a control byte", "abc\x00def"}, - {"a quote", `abc"def`}, - {"a space", "two words"}, - {"letters outside ASCII", "идентификатор"}, - {"longer than the limit", strings.Repeat("a", 65)}, - } - for _, tc := range replaced { - t.Run("replaced: "+tc.name, func(t *testing.T) { + {"a well-formed id", "01a0c467-8008-75c3-825b-37f804bf11bb"}, + {"a line break", "abc\r\nX-Injected: yes"}, + } { + t.Run(tc.name, func(t *testing.T) { t.Parallel() - got := echoedRequestID(t, tc.id) - if got == tc.id { - t.Errorf("X-Request-Id = %q, want it replaced", got) + logs, router := routerWithObservedLogs(t) + router.GET("/x", func(c *gin.Context) { c.Status(http.StatusBadRequest) }) + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/x", http.NoBody) + req.Header[middleware.RequestIDHeader] = []string{tc.id} + rec := httptest.NewRecorder() + router.ServeHTTP(rec, req) + + echoed := rec.Header().Get(middleware.RequestIDHeader) + if echoed == tc.id || !serviceID(echoed) { + t.Errorf("X-Request-Id = %q, want an id of the service's own, a UUID v7, not %q", echoed, tc.id) } - if !usableLooking(got) { - t.Errorf("X-Request-Id = %q, want a plain identifier", got) + if logged := field(t, onlyLine(t, logs), "request_id"); logged != echoed { + t.Errorf("request_id = %q, want the id the answer carries, %q", logged, echoed) } }) } @@ -546,38 +532,11 @@ func TestNoIDIsReadWhereNoneWasSet(t *testing.T) { } } -func echoedRequestID(t *testing.T, sent string) string { - t.Helper() - - router := gin.New() - router.Use(middleware.RequestID()) - router.GET("/x", func(c *gin.Context) { c.Status(http.StatusOK) }) - - req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/x", http.NoBody) - req.Header.Set(middleware.RequestIDHeader, sent) - rec := httptest.NewRecorder() - router.ServeHTTP(rec, req) - - return rec.Header().Get(middleware.RequestIDHeader) -} - -// usableLooking mirrors the rule the middleware applies, by bytes as it does: -// the package keeps that rule unexported, and a test that walked the string -// differently would agree with it only by accident. -func usableLooking(id string) bool { - if id == "" { - return false - } - for i := range len(id) { - r := id[i] - switch { - case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': - case r == '-', r == '_', r == '.', r == ':': - default: - return false - } - } - return true +// serviceID says whether id is one the service hands out while it has +// randomness: a version 7 UUID. +func serviceID(id string) bool { + parsed, err := uuid.Parse(id) + return err == nil && parsed.Version() == 7 && parsed.String() == id } // panickingFunction is named so that the stack the recovery logs can be held diff --git a/internal/transport/http/middleware/requestid.go b/internal/transport/http/middleware/requestid.go index 8c3a2e8..9ed0d90 100644 --- a/internal/transport/http/middleware/requestid.go +++ b/internal/transport/http/middleware/requestid.go @@ -19,53 +19,23 @@ const RequestIDHeader = "X-Request-Id" // of randomness has stopped answering. var requestsSeen atomic.Uint64 -// maxRequestIDLength bounds what a client may dictate: an id is a correlation -// handle, and an unbounded one is a way to write anything into a log line. -const maxRequestIDLength = 64 - -// RequestID gives every request an id and echoes it back. A client that sends -// a usable one keeps it, so that a trace through somebody else's logs and a -// trace through ours use the same word; anything else is replaced. +// RequestID gives every request an id of the service's own and sends it back +// in the answer. An id a client sends is not read: no client of this service +// needs one kept, and an id taken from a request would put a caller's words +// into every line of the log. // // The id is kept in the request's context, the one place both the handlers of // this framework and code that knows nothing of it can read it from, so that // every line of the request carries one id. func RequestID() gin.HandlerFunc { return func(c *gin.Context) { - id := c.GetHeader(RequestIDHeader) - if !usableRequestID(id) { - id = newRequestID() - } + id := newRequestID() c.Request = c.Request.WithContext(logger.WithRequestID(c.Request.Context(), id)) c.Header(RequestIDHeader, id) c.Next() } } -// usableRequestID reports whether a client's id can be carried as it stands. -// -// The alphabet is deliberately narrow: letters, digits and the four separators -// every correlation format in the wild is built from — a UUID, a hex trace id -// and a W3C traceparent all fit, and nothing else needs to. What it keeps out -// is a value that means something to a reader rather than to a machine: a -// newline, a control byte, a quote. Neither our JSON log nor the header writer -// would be fooled by one today, but the id also travels into whatever we -// correlate with next, and this is the one place that can be said once. -func usableRequestID(id string) bool { - if id == "" || len(id) > maxRequestIDLength { - return false - } - for _, b := range []byte(id) { - switch { - case b >= 'a' && b <= 'z', b >= 'A' && b <= 'Z', b >= '0' && b <= '9': - case b == '-', b == '_', b == '.', b == ':': - default: - return false - } - } - return true -} - // newRequestID prefers a version 7 identifier, whose leading bits are a // timestamp, so that ids sort by the order the requests arrived. // diff --git a/internal/transport/http/middleware/requestid_internal_test.go b/internal/transport/http/middleware/requestid_internal_test.go index ea7823e..6e78d99 100644 --- a/internal/transport/http/middleware/requestid_internal_test.go +++ b/internal/transport/http/middleware/requestid_internal_test.go @@ -2,21 +2,16 @@ package middleware import ( "errors" - "net/http" - "net/http/httptest" - "strings" + "regexp" "testing" "testing/iotest" - "github.com/gin-gonic/gin" "github.com/google/uuid" - - "github.com/MathTrail/canvas-api/internal/logger" ) // When the source of randomness stops answering there is still a request to -// correlate. The identifier that follows has to pass the same rule as any -// other, and two of them have to be different. +// correlate. The identifier that follows is the clock and a counter, in base +// 36, and two of them have to be different. func TestTheFallbackIdentifierIsUsableAndUnique(t *testing.T) { t.Parallel() @@ -24,8 +19,8 @@ func TestTheFallbackIdentifierIsUsableAndUnique(t *testing.T) { second := fallbackRequestID() for _, id := range []string{first, second} { - if !usableRequestID(id) { - t.Errorf("fallbackRequestID() = %q, want an id the middleware would keep", id) + if !fallbackShape.MatchString(id) { + t.Errorf("fallbackRequestID() = %q, want the clock and a counter in base 36", id) } } if first == second { @@ -34,8 +29,8 @@ func TestTheFallbackIdentifierIsUsableAndUnique(t *testing.T) { } // A request that arrives once the source of randomness has stopped answering -// is still given an identifier: the fallback, under the same rule and just as -// different from the one before it. +// is still given an identifier: the fallback, just as different from the one +// before it. func TestAnIdentifierIsMadeWithoutRandomness(t *testing.T) { // Not parallel: the source of randomness belongs to the whole process, and // it is put back before any test that runs in parallel starts. @@ -44,8 +39,8 @@ func TestAnIdentifierIsMadeWithoutRandomness(t *testing.T) { first, second := newRequestID(), newRequestID() for _, id := range []string{first, second} { - if !usableRequestID(id) { - t.Errorf("newRequestID() = %q, want an id the middleware would keep", id) + if !fallbackShape.MatchString(id) { + t.Errorf("newRequestID() = %q, want the fallback, the clock and a counter in base 36", id) } } if first == second { @@ -53,63 +48,6 @@ func TestAnIdentifierIsMadeWithoutRandomness(t *testing.T) { } } -// Whatever a client sends as its request id, the id the request is known by -// is one the rule keeps — short, and made only of the bytes a correlation -// format is built from — and a client's id is kept exactly when the rule keeps -// it. The header is the one part of a request the skeleton reads as it was -// written, so this is what a log line and an answer can never be made to carry. -func FuzzRequestID(f *testing.F) { - for _, seed := range []string{ - "", - "from-the-caller", - "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01", - "line\nbreak", - `"quoted"`, - strings.Repeat("a", 64), - strings.Repeat("a", 65), - "\x00", - "ünïcödé", - } { - f.Add(seed) - } - - gin.SetMode(gin.TestMode) - router := gin.New() - router.Use(RequestID()) - router.GET("/", func(c *gin.Context) { - c.String(http.StatusOK, logger.RequestID(c.Request.Context())) - }) - - f.Fuzz(func(t *testing.T, sent string) { - req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody) - req.Header[RequestIDHeader] = []string{sent} - rec := httptest.NewRecorder() - router.ServeHTTP(rec, req) - - echoed := rec.Header().Get(RequestIDHeader) - if !plainIdentifier(echoed) { - t.Fatalf("echoed id %q for %q, want 1 to 64 letters, digits, '-', '_', '.' or ':'", echoed, sent) - } - if logged := rec.Body.String(); logged != echoed { - t.Fatalf("the context carries %q, the header %q, want one id", logged, echoed) - } - if plainIdentifier(sent) != (echoed == sent) { - t.Fatalf("sent %q, echoed %q: a client's id is kept exactly when the rule keeps it", sent, echoed) - } - }) -} - -// plainIdentifier is the rule a request id is held to, written out here apart -// from the code it checks, so that a rule loosened there is caught rather than -// agreed with. -func plainIdentifier(id string) bool { - if id == "" || len(id) > 64 { - return false - } - for _, r := range id { - if !strings.ContainsRune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789-_.:", r) { - return false - } - } - return true -} +// fallbackShape is the id made without randomness: the clock and a counter, +// each in lower-case base 36. +var fallbackShape = regexp.MustCompile(`^[0-9a-z]+-[0-9a-z]+$`) diff --git a/internal/transport/http/middleware/route.go b/internal/transport/http/middleware/route.go index df7ceb6..bc68000 100644 --- a/internal/transport/http/middleware/route.go +++ b/internal/transport/http/middleware/route.go @@ -12,20 +12,6 @@ import ( // carries what a caller wrote carries whatever they chose to write there. const otherLabel = "other" -// knownMethods is the closed set a request's method is reported as. Anything -// else is a caller inventing a verb, and it is reported as one kind. -var knownMethods = map[string]struct{}{ - http.MethodGet: {}, - http.MethodHead: {}, - http.MethodPost: {}, - http.MethodPut: {}, - http.MethodPatch: {}, - http.MethodDelete: {}, - http.MethodOptions: {}, - http.MethodConnect: {}, - http.MethodTrace: {}, -} - // route is the pattern the request matched, never the path it asked for. A // path carries identifiers, one per sheet or task a log line would then // spread; and a path nothing matched is text a caller wrote, as able to carry @@ -40,10 +26,31 @@ func route(c *gin.Context) string { return otherLabel } -// method is the request's verb when it is one of the known ones. +// method is the request's verb when it is one of the known ones, and other +// otherwise: anything else is a caller inventing a verb, and it is reported as +// one kind. The set is closed, so the word written is always one of the +// service's own, spelled here. func method(c *gin.Context) string { - if _, known := knownMethods[c.Request.Method]; known { - return c.Request.Method + switch c.Request.Method { + case http.MethodGet: + return http.MethodGet + case http.MethodHead: + return http.MethodHead + case http.MethodPost: + return http.MethodPost + case http.MethodPut: + return http.MethodPut + case http.MethodPatch: + return http.MethodPatch + case http.MethodDelete: + return http.MethodDelete + case http.MethodOptions: + return http.MethodOptions + case http.MethodConnect: + return http.MethodConnect + case http.MethodTrace: + return http.MethodTrace + default: + return otherLabel } - return otherLabel } diff --git a/internal/transport/http/middleware/route_internal_test.go b/internal/transport/http/middleware/route_internal_test.go new file mode 100644 index 0000000..eada52a --- /dev/null +++ b/internal/transport/http/middleware/route_internal_test.go @@ -0,0 +1,40 @@ +package middleware + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/gin-gonic/gin" +) + +// Every known method is reported as itself, and anything else as other, in any +// case a caller chose to spell it. +func TestAMethodIsReportedFromTheClosedSet(t *testing.T) { + t.Parallel() + + for sent, want := range map[string]string{ + http.MethodGet: http.MethodGet, + http.MethodHead: http.MethodHead, + http.MethodPost: http.MethodPost, + http.MethodPut: http.MethodPut, + http.MethodPatch: http.MethodPatch, + http.MethodDelete: http.MethodDelete, + http.MethodOptions: http.MethodOptions, + http.MethodConnect: http.MethodConnect, + http.MethodTrace: http.MethodTrace, + "get": otherLabel, + "MASHA": otherLabel, + } { + t.Run(sent, func(t *testing.T) { + t.Parallel() + + c, _ := gin.CreateTestContext(httptest.NewRecorder()) + c.Request = httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody) + c.Request.Method = sent + if got := method(c); got != want { + t.Errorf("method() = %q, want %q", got, want) + } + }) + } +} diff --git a/internal/transport/http/router_test.go b/internal/transport/http/router_test.go index 771807a..079470e 100644 --- a/internal/transport/http/router_test.go +++ b/internal/transport/http/router_test.go @@ -10,6 +10,7 @@ import ( "testing" "github.com/gin-gonic/gin" + "github.com/google/uuid" "go.uber.org/zap/zaptest" "github.com/MathTrail/canvas-api/internal/apierror" @@ -167,7 +168,8 @@ func TestEveryAnswerCarriesItsIDAndTheSecurityHeaders(t *testing.T) { } } -func TestAClientsRequestIDIsKept(t *testing.T) { +// The id the service answers with is its own, whatever the client sent. +func TestAClientsRequestIDIsReplaced(t *testing.T) { t.Parallel() req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/health", http.NoBody) @@ -175,8 +177,9 @@ func TestAClientsRequestIDIsKept(t *testing.T) { rec := httptest.NewRecorder() httpserver.NewRouter(zaptest.NewLogger(t)).ServeHTTP(rec, req) - if got := rec.Header().Get(middleware.RequestIDHeader); got != "from-the-caller" { - t.Errorf("%s = %q, want the id the client sent", middleware.RequestIDHeader, got) + got := rec.Header().Get(middleware.RequestIDHeader) + if parsed, err := uuid.Parse(got); err != nil || parsed.Version() != 7 { + t.Errorf("%s = %q, want an id of the service's own, a UUID v7", middleware.RequestIDHeader, got) } } From 7771e4a6837e07c383413c292426ce4aaea86cdc Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 16 Oct 2026 18:19:32 +0000 Subject: [PATCH 3/3] Name a request's route from the router's own table (T16, PR review) CodeQL's gin model treats Context.FullPath as user input, so the four go/log-injection alerts stayed after the id and the method were fixed. The route is now written as a pattern from the table of routes the router registered, read once at the first request; the probe filter uses the same name. R68 and RUN.md say so. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01U1MCDC5QUpgX5xmPSJYn5W --- RUN.md | 6 ++-- docs/decisions.md | 6 ++-- internal/transport/http/middleware/logger.go | 9 ++--- .../http/middleware/middleware_test.go | 9 ++--- internal/transport/http/middleware/probe.go | 11 +++--- .../transport/http/middleware/recovery.go | 4 +-- internal/transport/http/middleware/route.go | 36 ++++++++++++++++--- .../http/middleware/route_internal_test.go | 34 ++++++++++++++++++ internal/transport/http/router.go | 8 +++-- 9 files changed, 95 insertions(+), 28 deletions(-) diff --git a/RUN.md b/RUN.md index 790dd8c..df481c2 100644 --- a/RUN.md +++ b/RUN.md @@ -555,13 +555,13 @@ - `internal/logger` — без изменений, кроме модуля и примеров в тестах; - `internal/apierror` — `{code, message}` и `details` с `omitempty`; коды `NOT_FOUND`, `METHOD_NOT_ALLOWED`, `INTERNAL_ERROR`. Остальные коды E2 придут с T18, T65 и T70; - `internal/transport/http` на gin — роутер, `/health` на GET и HEAD, 404 и 405 телом `apierror`; middleware в порядке образца: `LastResort`, `SecurityHeaders`, `RequestID`, `ZapLogger`, `ZapRecovery`. - - **Отличия от образца:** нет телеметрии, метрик, лимитов, проверки `Host` и `Origin`, полей query в логе и продуктовых маршрутов; заголовок — `X-Request-Id`, как в spec 8.1, и id всегда свой: сервер не читает id клиента, а метод пишет одним из слов закрытого набора (R68); `CANVAS_ENV` и его защита при `K_SERVICE` — своё; при `K_SERVICE` `CANVAS_SHUTDOWN_TIMEOUT` меньше 10 с — Cloud Run убивает экземпляр через 10 с после SIGTERM. Косвенные модули подняты до версий образца. + - **Отличия от образца:** нет телеметрии, метрик, лимитов, проверки `Host` и `Origin`, полей query в логе и продуктовых маршрутов; заголовок — `X-Request-Id`, как в spec 8.1, и id всегда свой: сервер не читает id клиента, метод пишет одним из слов закрытого набора, а маршрут — шаблоном из таблицы самого роутера (R68); `CANVAS_ENV` и его защита при `K_SERVICE` — своё; при `K_SERVICE` `CANVAS_SHUTDOWN_TIMEOUT` меньше 10 с — Cloud Run убивает экземпляр через 10 с после SIGTERM. Косвенные модули подняты до версий образца. - **Облако:** `CANVAS_ENV=prod` в `service_api.tf` и тест `terraform test` на него. - **Ещё:** `.env.example`, `.vscode/launch.json` — локальный запуск и «как видит Cloud Run», `THIRD_PARTY_LICENSES`, spec 8.3 и 15.4. - **Проверки** (облачная сессия; `just`, golangci-lint 2.14.0 и Terraform 1.16.3 скачаны по закреплённым версиям): зелёные — и повторно после R68 — `ci-lint`, `ci-test` (покрытие 97,6 %; после R68 тест метода обходит весь закрытый набор), `ci-mocks-check`, `ci-secrets`, `release-version`, `release-artifacts`, `terraform fmt -check`. Вживую: `/health` отвечает версией и коммитом, 404 и 405 — телом `apierror`, каждый ответ несёт `X-Request-Id`, строки лога — JSON с `severity`; с `K_SERVICE` и без `CANVAS_ENV=prod` сервис не стартует. - - **Выключены, чтобы доказать тесты, — 17 проверок, каждая краснила свой тест:** `local` и `console` при `K_SERVICE`, неизвестный `CANVAS_ENV`, предел `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании, имя переменной в точном регистре, `PORT` только цифрами, закрытие при сбое сборки, отдельный контекст закрытия, обратный порядок, `RequestID` в цепочке, `HEAD /health`, 405, порт до строки `startup`, сброс заголовков обработчика при панике, id клиента не читается, метод только из закрытого набора, форма запасного id. + - **Выключены, чтобы доказать тесты, — 19 проверок, каждая краснила свой тест:** `local` и `console` при `K_SERVICE`, неизвестный `CANVAS_ENV`, предел `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании, имя переменной в точном регистре, `PORT` только цифрами, закрытие при сбое сборки, отдельный контекст закрытия, обратный порядок, `RequestID` в цепочке, `HEAD /health`, 405, порт до строки `startup`, сброс заголовков обработчика при панике, id клиента не читается, метод только из закрытого набора, форма запасного id, маршрут из таблицы роутера, пропуск проб в логе. - **Fuzz:** нет. Был `FuzzRequestID` на заголовок `X-Request-Id` — 60 с без находок; он ушёл вместе с чтением заголовка (R68), и внешнего ввода каркас больше не разбирает. - - **PR #20, находки CodeQL `go/log-injection`** — четыре, на строке лога запроса и в `LastResort`: в них шли метод и id клиента. Id клиента не читается, метод пишется `switch` по закрытому набору (R68). Ревью правки — 8 находок: исправлено 7 — таблица-тождество методов заменена `switch`, а R68 говорит, что это не защита, а запись закрытого набора; общая проверка формы id получила предел длины; убраны тест-дубль уникальности id, случай «длиннее id» и неиспользуемый помощник; в RUN.md обновлены проверки; дата R68 названа явно. Отброшено 1: форму id в тесте роутера проверяет тест middleware. Второй круг — 6 находок: исправлено 5 — тесты сверяют id как UUID v7, а запасной — по своему узору, вместо общего широкого правила в двух копиях; таблица случаев сокращена до двух; тест роутера тоже требует UUID v7; `switch` метода и форма запасного id доказаны выключением. Отброшено 1: тест метода нарочно перечисляет набор отдельно от кода — так он и ловит расхождение. + - **PR #20, находки CodeQL `go/log-injection`** — четыре, на строке лога запроса и в `LastResort`: в них шли метод и id клиента. Id клиента не читается, метод пишется `switch` по закрытому набору (R68). Ревью правки — 8 находок: исправлено 7 — таблица-тождество методов заменена `switch`, а R68 говорит, что это не защита, а запись закрытого набора; общая проверка формы id получила предел длины; убраны тест-дубль уникальности id, случай «длиннее id» и неиспользуемый помощник; в RUN.md обновлены проверки; дата R68 названа явно. Отброшено 1: форму id в тесте роутера проверяет тест middleware. Второй круг — 6 находок: исправлено 5 — тесты сверяют id как UUID v7, а запасной — по своему узору, вместо общего широкого правила в двух копиях; таблица случаев сокращена до двух; тест роутера тоже требует UUID v7; `switch` метода и форма запасного id доказаны выключением. Отброшено 1: тест метода нарочно перечисляет набор отдельно от кода — так он и ловит расхождение. После этого CodeQL на коммите d9574eb оставил те же 4 находки: в модели gin у CodeQL источником помечен и `Context.FullPath`, из которого шёл маршрут. По решению автора маршрут пишется шаблоном из таблицы роутера (`middleware.Routes`). Ревью этой правки, два круга. Первый — 6 находок: исправлено 2 — фильтр проб берёт маршрут из той же таблицы, устаревший комментарий поправлен; отброшено 3 — таблица чужого роутера (ошибка вызова, видная в коде), таблица-тождество (решение автора), ссылка на роутер; 1 — поздняя регистрация маршрута — сначала исправлено перечитыванием таблицы, но второй круг напомнил, что gin не берёт маршруты, пока обслуживает, и перечитывание убрано: таблица читается один раз, при первом запросе. Второй — 6 находок: исправлено 4 этим возвратом; отброшено 2 — у `NewRoutes` нет интерфейса, который он вернул бы, а закрывает ли таблица находки CodeQL, показывает CI на PR. - **Ревью `/code-review high`, два круга.** - Первый — 9 находок. Исправлено 6: `.env.example` обещал, что `.env` прочтут, — теперь сказано, как его загрузить; занятый порт писался как сбой `shutdown` после строки `startup` — порт теперь занимается до неё; тесты `run()` зависели от переменных оболочки — они их обнуляют; `CANVAS_SHUTDOWN_TIMEOUT` в развёртывании ограничен 10 с; повтор перехвата stdout в тесте заменён помощником; нет fuzz на `X-Request-Id` — добавлен. Отброшено 3: верхняя граница теста drain — тест о самих часах ставит свои сроки, как и в образце; 5-секундные сторожа ожиданий — предел для событий, которые занимают миллисекунды, а не мера скорости кода; список шагов контейнера — его требует задача (закрытие при сбое посередине), следующий ресурс принесёт T35. - Второй — 8 находок. Исправлено 5: ответ на панику нёс заголовки обработчика; имена переменных сравнивались без учёта регистра; `PORT` принимал `+8080` и `08080`; комментарий `Listen` называл вызов только тестовым; у четырёх полей тайм-аутов не было doc-комментариев. Отброшено 1: список шагов контейнера — повтор находки первого круга. В «Открыто» — 2, ниже. diff --git a/docs/decisions.md b/docs/decisions.md index ecfb6c7..991049a 100644 --- a/docs/decisions.md +++ b/docs/decisions.md @@ -646,7 +646,9 @@ Centrifugo сохраняет роль из R23. Событие `verdict` ухо **R68. `X-Request-Id` всегда свой: сервер не читает id клиента, а в лог идут только его собственные слова о запросе.** Решение автора 2026-10-16, по находкам CodeQL `go/log-injection` в PR T16. - Каждый запрос получает id сервера — UUID v7, а без источника случайности — время и счётчик. Id, присланный клиентом, не читается и не возвращается. -- Метод запроса пишется в лог одним из слов закрытого набора — `switch` по известным методам возвращает константу, неизвестный — `other`; путь пишется шаблоном маршрута. Набор был закрытым и в образце, и защиты это не прибавляет: `switch` — простейшая запись закрытого набора, а сканер видит в ней сравнение с константами. Это не экранирование чужого текста, которое отвергнуто ниже: в лог идёт слово сервиса. +- Метод запроса пишется в лог одним из слов закрытого набора — `switch` по известным методам возвращает константу, неизвестный — `other`. Маршрут пишется шаблоном из таблицы маршрутов самого роутера (`middleware.Routes`, читается из `router.Routes()` при первом запросе); не найденный в ней — `other`. Оба набора были закрытыми и в образце, и защиты это не прибавляет: CodeQL считает вводом клиента и метод, и `gin.Context.FullPath` — хотя тот возвращает зарегистрированный шаблон, — а слово из своей таблицы он видит как слово сервиса. Это не экранирование чужого текста, которое отвергнуто ниже: в лог идёт слово сервиса. + +— *Выяснилось:* модель gin у CodeQL (`go/ql/lib/ext/github.com.gin-gonic.gin.model.yml`, прочитана 2026-10-16) помечает источником ввода `Context.FullPath` и `GetHeader`; первые две правки — id и метод — оставили находки на месте, пока маршрут шёл из `FullPath`. Решение автора 2026-10-16: закрыть и это кодом, таблицей маршрутов, а не пометкой «ложное». — *Почему:* образец сохраняет id клиента, если тот проходит белый список, чтобы след через чужие журналы и через наши шёл под одним словом. Здесь такого клиента нет: SPA id не шлёт, и CORS T65 его не пропустит — разрешены только `Authorization` и `Content-Type`. Сохранённый id клиента был бы единственной строкой лога, которую написал не сервер, — CodeQL указал на неё четырьмя находками. Правка убирает сам источник, а не прячет его от сканера. @@ -656,7 +658,7 @@ Centrifugo сохраняет роль из R23. Событие `verdict` ухо — *Следствие:* `usableRequestID` и `FuzzRequestID` ушли вместе с чтением заголовка; внешнего ввода каркас больше не разбирает. Если клиент, которому нужен общий id, появится — это новое решение. -— `internal/transport/http/middleware/requestid.go`, `route.go`; spec 8.1; R67; standalone: R111. +— `internal/transport/http/middleware/requestid.go`, `route.go`, `router.go`; spec 8.1; R67; standalone: R111. ## Идентификация и доступ diff --git a/internal/transport/http/middleware/logger.go b/internal/transport/http/middleware/logger.go index cb475bc..e69f3ae 100644 --- a/internal/transport/http/middleware/logger.go +++ b/internal/transport/http/middleware/logger.go @@ -18,15 +18,16 @@ import ( // set this service wrote down, and never the path, the query or the verb as a // caller wrote them: those are the caller's own words, and a log line carries // none. -func ZapLogger(logger *zap.Logger) gin.HandlerFunc { +func ZapLogger(logger *zap.Logger, routes *Routes) gin.HandlerFunc { return func(c *gin.Context) { start := time.Now() // Read before the handlers run, both together: what was asked is a // fact about the request, and by the time the answer exists the // request may have been replaced by something downstream. The route - // is the framework's, and known before the first handler runs. + // is the pattern the framework matched before the first handler ran, + // named from the router's own table. verb := method(c) - matched := route(c) + matched := routes.of(c) c.Next() @@ -35,7 +36,7 @@ func ZapLogger(logger *zap.Logger) gin.HandlerFunc { // panic too. status := c.Writer.Status() panicFields, panicked := panicOf(c) - if isProbe(c) && status < 400 && !panicked { + if isProbe(matched) && status < 400 && !panicked { return } diff --git a/internal/transport/http/middleware/middleware_test.go b/internal/transport/http/middleware/middleware_test.go index 7f897fe..a5b3eb6 100644 --- a/internal/transport/http/middleware/middleware_test.go +++ b/internal/transport/http/middleware/middleware_test.go @@ -132,9 +132,10 @@ func routerWithObservedLogs(t *testing.T) (*observer.ObservedLogs, *gin.Engine) logger := zap.New(core) router := gin.New() - router.Use(middleware.LastResort(logger)) + routes := middleware.NewRoutes(router) + router.Use(middleware.LastResort(logger, routes)) router.Use(middleware.RequestID()) - router.Use(middleware.ZapLogger(logger)) + router.Use(middleware.ZapLogger(logger, routes)) router.Use(middleware.ZapRecovery()) return logs, router } @@ -261,7 +262,7 @@ func TestAPanicAboveTheRecoveryIsCaughtByTheLastResort(t *testing.T) { core, logs := observer.New(zapcore.DebugLevel) router := gin.New() - router.Use(middleware.LastResort(zap.New(core))) + router.Use(middleware.LastResort(zap.New(core), middleware.NewRoutes(router))) router.Use(middleware.RequestID()) router.Use(func(c *gin.Context) { c.Next() @@ -344,7 +345,7 @@ func lastResortLine(t *testing.T, method, target string) *observer.LoggedEntry { core, logs := observer.New(zapcore.DebugLevel) router := gin.New() - router.Use(middleware.LastResort(zap.New(core))) + router.Use(middleware.LastResort(zap.New(core), middleware.NewRoutes(router))) router.Use(func(*gin.Context) { panic("the middleware is on fire") }) router.GET("/tasks/:id", func(c *gin.Context) { c.Status(http.StatusNoContent) }) serve(t, router, method, target) diff --git a/internal/transport/http/middleware/probe.go b/internal/transport/http/middleware/probe.go index 1610906..527fb96 100644 --- a/internal/transport/http/middleware/probe.go +++ b/internal/transport/http/middleware/probe.go @@ -1,7 +1,5 @@ package middleware -import "github.com/gin-gonic/gin" - // probeRoutes answer a machine rather than a person. The platform asks for them // constantly and the answer is the same every time. var probeRoutes = map[string]struct{}{ @@ -14,9 +12,10 @@ var probeRoutes = map[string]struct{}{ // there are checks, so a probe in the log buries the lines that mean // something. // -// It asks by the route, as everything else here names a request, so that the -// path a caller wrote is never read at all. -func isProbe(c *gin.Context) bool { - _, probe := probeRoutes[route(c)] +// It asks by the route the request is named by in the log, so that the path a +// caller wrote is never read at all, and a line skipped as a probe is one that +// would have named the probe. +func isProbe(route string) bool { + _, probe := probeRoutes[route] return probe } diff --git a/internal/transport/http/middleware/recovery.go b/internal/transport/http/middleware/recovery.go index 870f7d7..b001c3f 100644 --- a/internal/transport/http/middleware/recovery.go +++ b/internal/transport/http/middleware/recovery.go @@ -40,14 +40,14 @@ func ZapRecovery() gin.HandlerFunc { // it, whose request never reaches the request log. It writes the line itself, // naming the request as the request log does, and answers and passes an abort // on as ZapRecovery does. -func LastResort(log *zap.Logger) gin.HandlerFunc { +func LastResort(log *zap.Logger, routes *Routes) gin.HandlerFunc { return func(c *gin.Context) { recovering(c, func(recovered any) { log.Error("panic", logger.PanicValue(recovered), logger.PanicStack(), zap.String("method", method(c)), - zap.String("route", route(c)), + zap.String("route", routes.of(c)), zap.String("request_id", RequestIDFrom(c)), ) }) diff --git a/internal/transport/http/middleware/route.go b/internal/transport/http/middleware/route.go index bc68000..0dc900f 100644 --- a/internal/transport/http/middleware/route.go +++ b/internal/transport/http/middleware/route.go @@ -2,6 +2,7 @@ package middleware import ( "net/http" + "sync" "github.com/gin-gonic/gin" ) @@ -12,16 +13,41 @@ import ( // carries what a caller wrote carries whatever they chose to write there. const otherLabel = "other" -// route is the pattern the request matched, never the path it asked for. A -// path carries identifiers, one per sheet or task a log line would then +// Routes names a request by the pattern it matched, never by the path it asked +// for. A path carries identifiers, one per sheet or task a log line would then // spread; and a path nothing matched is text a caller wrote, as able to carry // a name as anything else they write. // +// The name is looked up in the table of the patterns the router serves, so +// what a line says is always one of the service's own words — the same rule +// the method is held to. +type Routes struct { + router *gin.Engine + + learned sync.Once + known map[string]string +} + +// NewRoutes names the requests the router serves. It is given the router the +// middleware is mounted on, and reads its patterns at the first request: the +// framework takes no routes once it serves, so by then every one is there. +func NewRoutes(router *gin.Engine) *Routes { + return &Routes{router: router} +} + +// of is the pattern the request matched, or other when it matched none. +// // The framework knows the pattern before the first handler runs, so every // middleware can ask, a panicking one included. -func route(c *gin.Context) string { - if matched := c.FullPath(); matched != "" { - return matched +func (r *Routes) of(c *gin.Context) string { + r.learned.Do(func() { + r.known = make(map[string]string) + for _, served := range r.router.Routes() { + r.known[served.Path] = served.Path + } + }) + if pattern, served := r.known[c.FullPath()]; served { + return pattern } return otherLabel } diff --git a/internal/transport/http/middleware/route_internal_test.go b/internal/transport/http/middleware/route_internal_test.go index eada52a..8fec550 100644 --- a/internal/transport/http/middleware/route_internal_test.go +++ b/internal/transport/http/middleware/route_internal_test.go @@ -38,3 +38,37 @@ func TestAMethodIsReportedFromTheClosedSet(t *testing.T) { }) } } + +// A request is named by a pattern from the table of the router the names were +// made for: a pattern it serves is written as itself, and a pattern no route of +// it serves — even one another router matched — is written as other. +func TestARouteIsNamedFromTheRoutersOwnTable(t *testing.T) { + t.Parallel() + + gin.SetMode(gin.TestMode) + served := gin.New() + served.GET("/tasks/:id", func(*gin.Context) {}) + stranger := gin.New() + + for _, tc := range []struct { + name string + routes *Routes + want string + }{ + {name: "the router's own pattern", routes: NewRoutes(served), want: "/tasks/:id"}, + {name: "a pattern the table does not hold", routes: NewRoutes(stranger), want: otherLabel}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + var named string + engine := gin.New() + engine.GET("/tasks/:id", func(c *gin.Context) { named = tc.routes.of(c) }) + engine.ServeHTTP(httptest.NewRecorder(), + httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/tasks/42", http.NoBody)) + if named != tc.want { + t.Errorf("routes.of() = %q, want %q", named, tc.want) + } + }) + } +} diff --git a/internal/transport/http/router.go b/internal/transport/http/router.go index 8378fff..99dc814 100644 --- a/internal/transport/http/router.go +++ b/internal/transport/http/router.go @@ -33,10 +33,14 @@ func NewRouter(log *zap.Logger) *gin.Engine { // answer it with a second request the client never meant to make. router.RedirectTrailingSlash = false - router.Use(middleware.LastResort(log)) + // A request is named in the log by the pattern it matched, from the table + // of the patterns this router serves. + routes := middleware.NewRoutes(router) + + router.Use(middleware.LastResort(log, routes)) router.Use(middleware.SecurityHeaders()) router.Use(middleware.RequestID()) - router.Use(middleware.ZapLogger(log)) + router.Use(middleware.ZapLogger(log, routes)) router.Use(middleware.ZapRecovery()) router.NoRoute(notFound)