init
This commit is contained in:
@@ -0,0 +1,287 @@
|
||||
package httpx
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"net/netip"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/iceBear67/simplepages/api"
|
||||
)
|
||||
|
||||
func prefixes(t *testing.T, ss ...string) []netip.Prefix {
|
||||
t.Helper()
|
||||
out := make([]netip.Prefix, 0, len(ss))
|
||||
for _, s := range ss {
|
||||
p, err := netip.ParsePrefix(s)
|
||||
if err != nil {
|
||||
t.Fatalf("ParsePrefix(%q): %v", s, err)
|
||||
}
|
||||
out = append(out, p)
|
||||
}
|
||||
return out
|
||||
}
|
||||
|
||||
// TestLogNeverContainsCredentials is the load-bearing test of this package:
|
||||
// an access log that leaks a bearer token turns every log shipper, backup and
|
||||
// support ticket into a credential store.
|
||||
func TestLogNeverContainsCredentials(t *testing.T) {
|
||||
const token = "pgs_k7m2q4x9v0zt3b8w_S3cr3tVa1ueThatMustNeverBeLogged00000000"
|
||||
|
||||
var buf bytes.Buffer
|
||||
log := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
|
||||
|
||||
h := Chain(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
// A handler that legitimately annotates the log must still not be able to
|
||||
// smuggle the secret in: it logs the key id, which is public.
|
||||
LogAttr(r.Context(), "key_id", "k7m2q4x9v0zt3b8w")
|
||||
LogAttr(r.Context(), "project", "demo")
|
||||
w.WriteHeader(http.StatusNoContent)
|
||||
}), WithRequestID(nil), AccessLog(log, nil), Recover(log))
|
||||
|
||||
r := httptest.NewRequest(http.MethodGet, "/api/v1/whoami?access_token="+token, nil)
|
||||
r.Header.Set("Authorization", "Bearer "+token)
|
||||
r.Header.Set("Cookie", "session="+token)
|
||||
h.ServeHTTP(httptest.NewRecorder(), r)
|
||||
|
||||
out := buf.String()
|
||||
if out == "" {
|
||||
t.Fatal("no log output produced")
|
||||
}
|
||||
for _, needle := range []string{token, "S3cr3tVa1ue", "Bearer", "Authorization", "session="} {
|
||||
if strings.Contains(out, needle) {
|
||||
t.Errorf("log contains %q\nlog: %s", needle, out)
|
||||
}
|
||||
}
|
||||
for _, want := range []string{`"key_id":"k7m2q4x9v0zt3b8w"`, `"project":"demo"`, `"status":204`} {
|
||||
if !strings.Contains(out, want) {
|
||||
t.Errorf("log missing %s\nlog: %s", want, out)
|
||||
}
|
||||
}
|
||||
// The raw query string is not logged either: tokens end up there when someone
|
||||
// ignores the docs, and we would rather drop the field than log the secret.
|
||||
if strings.Contains(out, "access_token") {
|
||||
t.Errorf("log contains the query string\nlog: %s", out)
|
||||
}
|
||||
}
|
||||
|
||||
func TestAccessLogRecordsStatusAndBytes(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
log := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
|
||||
|
||||
h := Chain(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
w.WriteHeader(http.StatusTeapot)
|
||||
fmt.Fprint(w, "hello")
|
||||
}), AccessLog(log, nil))
|
||||
h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/x", nil))
|
||||
|
||||
var rec map[string]any
|
||||
if err := json.Unmarshal(bytes.TrimSpace(buf.Bytes()), &rec); err != nil {
|
||||
t.Fatalf("log line is not JSON: %v (%s)", err, buf.String())
|
||||
}
|
||||
if got := rec["status"]; got != float64(http.StatusTeapot) {
|
||||
t.Errorf("status = %v, want 418", got)
|
||||
}
|
||||
if got := rec["bytes"]; got != float64(5) {
|
||||
t.Errorf("bytes = %v, want 5", got)
|
||||
}
|
||||
if rec["level"] != "WARN" {
|
||||
t.Errorf("level = %v, want WARN for a 4xx", rec["level"])
|
||||
}
|
||||
}
|
||||
|
||||
func TestRecoverReturnsOpaque500(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
log := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
|
||||
|
||||
h := Chain(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
panic("database password is hunter2")
|
||||
}), WithRequestID(nil), AccessLog(log, nil), Recover(log))
|
||||
|
||||
w := httptest.NewRecorder()
|
||||
h.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/boom", nil))
|
||||
|
||||
if w.Code != http.StatusInternalServerError {
|
||||
t.Fatalf("status = %d, want 500", w.Code)
|
||||
}
|
||||
// The panicking request must still produce an access-log line, which is only
|
||||
// true while Recover runs inside AccessLog.
|
||||
if !strings.Contains(buf.String(), `"msg":"request"`) {
|
||||
t.Errorf("no access-log line for the panicking request\nlog: %s", buf.String())
|
||||
}
|
||||
if strings.Contains(w.Body.String(), "hunter2") {
|
||||
t.Errorf("panic value leaked to the client: %s", w.Body.String())
|
||||
}
|
||||
var env api.ErrorEnvelope
|
||||
if err := json.Unmarshal(w.Body.Bytes(), &env); err != nil {
|
||||
t.Fatalf("body is not an error envelope: %v (%s)", err, w.Body.String())
|
||||
}
|
||||
if env.Error.Code != api.CodeInternal {
|
||||
t.Errorf("code = %q, want %q", env.Error.Code, api.CodeInternal)
|
||||
}
|
||||
if env.Error.Details["request_id"] == nil {
|
||||
t.Error("500 body carries no request_id, so the log line cannot be found")
|
||||
}
|
||||
if !strings.Contains(buf.String(), "hunter2") {
|
||||
t.Error("panic value was not logged; it must reach the operator even though it must not reach the client")
|
||||
}
|
||||
}
|
||||
|
||||
func TestClientIP(t *testing.T) {
|
||||
trusted := prefixes(t, "127.0.0.1/32", "10.0.0.0/8")
|
||||
|
||||
cases := []struct {
|
||||
name string
|
||||
remote string
|
||||
xff []string
|
||||
want string
|
||||
}{
|
||||
{"untrusted peer, header ignored", "203.0.113.9:1234", []string{"9.9.9.9"}, "203.0.113.9"},
|
||||
{"trusted peer, single hop", "127.0.0.1:1234", []string{"198.51.100.7"}, "198.51.100.7"},
|
||||
{"trusted peer, chain", "10.1.2.3:1234", []string{"198.51.100.7, 10.4.5.6"}, "198.51.100.7"},
|
||||
{"forged prefix ignored", "127.0.0.1:1234", []string{"1.2.3.4, 198.51.100.7"}, "198.51.100.7"},
|
||||
{"multiple headers", "127.0.0.1:1234", []string{"1.1.1.1", "198.51.100.7"}, "198.51.100.7"},
|
||||
{"garbage entries skipped", "127.0.0.1:1234", []string{"not-an-ip, 198.51.100.7, 10.0.0.1"}, "198.51.100.7"},
|
||||
{"all trusted, falls back to peer", "127.0.0.1:1234", []string{"10.0.0.1"}, "127.0.0.1"},
|
||||
{"no header", "127.0.0.1:1234", nil, "127.0.0.1"},
|
||||
}
|
||||
for _, tc := range cases {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
r := httptest.NewRequest(http.MethodGet, "/", nil)
|
||||
r.RemoteAddr = tc.remote
|
||||
for _, v := range tc.xff {
|
||||
r.Header.Add("X-Forwarded-For", v)
|
||||
}
|
||||
got, ok := ClientIP(r, trusted)
|
||||
if !ok {
|
||||
t.Fatal("ClientIP reported no address")
|
||||
}
|
||||
if got.String() != tc.want {
|
||||
t.Errorf("ClientIP = %s, want %s", got, tc.want)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func TestRequestIDAdoption(t *testing.T) {
|
||||
trusted := prefixes(t, "127.0.0.1/32")
|
||||
|
||||
cases := []struct {
|
||||
name string
|
||||
remote string
|
||||
header string
|
||||
wantSet bool // true = the inbound value is echoed back verbatim
|
||||
}{
|
||||
{"trusted peer, sane id", "127.0.0.1:1", "deadbeef-42", true},
|
||||
{"untrusted peer", "203.0.113.9:1", "deadbeef-42", false},
|
||||
{"trusted peer, space injected", "127.0.0.1:1", "id with space", false},
|
||||
{"trusted peer, newline injected", "127.0.0.1:1", "id\nlevel=INFO", false},
|
||||
{"trusted peer, over-long", "127.0.0.1:1", strings.Repeat("a", 65), false},
|
||||
}
|
||||
for _, tc := range cases {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
var seen string
|
||||
h := WithRequestID(trusted)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
seen = RequestIDFrom(r.Context())
|
||||
}))
|
||||
r := httptest.NewRequest(http.MethodGet, "/", nil)
|
||||
r.RemoteAddr = tc.remote
|
||||
r.Header.Set("X-Request-Id", tc.header)
|
||||
w := httptest.NewRecorder()
|
||||
h.ServeHTTP(w, r)
|
||||
|
||||
if tc.wantSet {
|
||||
if seen != tc.header {
|
||||
t.Errorf("request id = %q, want the inbound %q", seen, tc.header)
|
||||
}
|
||||
} else if seen == tc.header {
|
||||
t.Errorf("adopted an untrustworthy inbound id %q", tc.header)
|
||||
}
|
||||
if seen == "" {
|
||||
t.Error("no request id assigned")
|
||||
}
|
||||
if got := w.Header().Get("X-Request-Id"); got != seen {
|
||||
t.Errorf("echoed %q but handler saw %q", got, seen)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func TestWriteErrorMapsCodes(t *testing.T) {
|
||||
cases := []struct {
|
||||
err error
|
||||
want int
|
||||
}{
|
||||
{api.Errorf(api.CodeNotFound, "nope"), http.StatusNotFound},
|
||||
{api.Errorf(api.CodeDeploymentActive, "still active"), http.StatusConflict},
|
||||
{api.Errorf(api.CodeInvalidPath, "bad"), http.StatusBadRequest},
|
||||
{api.Errorf(api.CodeLimitExceeded, "too big"), http.StatusRequestEntityTooLarge},
|
||||
{fmt.Errorf("wrapped: %w", api.Errorf(api.CodeForbidden, "no")), http.StatusForbidden},
|
||||
{fmt.Errorf("open /var/lib/pages-server/secret: permission denied"), http.StatusInternalServerError},
|
||||
}
|
||||
log := slog.New(slog.NewJSONHandler(&bytes.Buffer{}, nil))
|
||||
for _, tc := range cases {
|
||||
w := httptest.NewRecorder()
|
||||
WriteError(w, httptest.NewRequest(http.MethodGet, "/", nil), log, tc.err)
|
||||
if w.Code != tc.want {
|
||||
t.Errorf("WriteError(%v) = %d, want %d", tc.err, w.Code, tc.want)
|
||||
}
|
||||
if ct := w.Header().Get("Content-Type"); !strings.HasPrefix(ct, "application/json") {
|
||||
t.Errorf("Content-Type = %q", ct)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// A non-api error must not put internal detail in the response body.
|
||||
func TestWriteErrorHidesInternalDetail(t *testing.T) {
|
||||
log := slog.New(slog.NewJSONHandler(&bytes.Buffer{}, nil))
|
||||
w := httptest.NewRecorder()
|
||||
WriteError(w, httptest.NewRequest(http.MethodGet, "/", nil), log,
|
||||
fmt.Errorf("sql: no rows in /var/lib/pages-server/pages.db"))
|
||||
if strings.Contains(w.Body.String(), "pages.db") {
|
||||
t.Errorf("internal detail leaked: %s", w.Body.String())
|
||||
}
|
||||
}
|
||||
|
||||
func TestDecodeJSON(t *testing.T) {
|
||||
type payload struct {
|
||||
Name string `json:"name"`
|
||||
}
|
||||
cases := []struct {
|
||||
name string
|
||||
body string
|
||||
max int64
|
||||
want api.Code
|
||||
}{
|
||||
{"ok", `{"name":"demo"}`, 1024, ""},
|
||||
{"unknown field", `{"name":"demo","nmae":"typo"}`, 1024, api.CodeBadRequest},
|
||||
{"wrong type", `{"name":42}`, 1024, api.CodeBadRequest},
|
||||
{"malformed", `{"name":`, 1024, api.CodeBadRequest},
|
||||
{"trailing content", `{"name":"a"} {"name":"b"}`, 1024, api.CodeBadRequest},
|
||||
{"too large", `{"name":"` + strings.Repeat("x", 200) + `"}`, 32, api.CodePayloadTooLarge},
|
||||
}
|
||||
for _, tc := range cases {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
r := httptest.NewRequest(http.MethodPost, "/", strings.NewReader(tc.body))
|
||||
var v payload
|
||||
err := DecodeJSON(httptest.NewRecorder(), r, tc.max, &v)
|
||||
if tc.want == "" {
|
||||
if err != nil {
|
||||
t.Fatalf("unexpected error: %v", err)
|
||||
}
|
||||
return
|
||||
}
|
||||
if err == nil {
|
||||
t.Fatal("expected an error")
|
||||
}
|
||||
if got := api.CodeOf(err); got != tc.want {
|
||||
t.Errorf("code = %q, want %q (%v)", got, tc.want, err)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,127 @@
|
||||
// Package httpx holds the HTTP plumbing shared by both listeners: the JSON
|
||||
// error envelope, the middleware chain, and server lifecycle management.
|
||||
package httpx
|
||||
|
||||
import (
|
||||
"encoding/json"
|
||||
"errors"
|
||||
"log/slog"
|
||||
"net/http"
|
||||
|
||||
"github.com/iceBear67/simplepages/api"
|
||||
)
|
||||
|
||||
// StatusFor maps a machine-readable code to its HTTP status.
|
||||
func StatusFor(code api.Code) int {
|
||||
switch code {
|
||||
case api.CodeBadRequest, api.CodeInvalidProjectName, api.CodeInvalidPath,
|
||||
api.CodeDigestMismatch, api.CodeSizeMismatch:
|
||||
return http.StatusBadRequest
|
||||
case api.CodeUnauthorized:
|
||||
return http.StatusUnauthorized
|
||||
case api.CodeForbidden:
|
||||
return http.StatusForbidden
|
||||
case api.CodeNotFound:
|
||||
return http.StatusNotFound
|
||||
case api.CodeMethodNotAllowed:
|
||||
return http.StatusMethodNotAllowed
|
||||
case api.CodeConflict, api.CodeProjectExists, api.CodeDeploymentNotReady,
|
||||
api.CodeDeploymentActive, api.CodeBlobsMissing:
|
||||
return http.StatusConflict
|
||||
case api.CodePayloadTooLarge, api.CodeLimitExceeded:
|
||||
return http.StatusRequestEntityTooLarge
|
||||
case api.CodeRateLimited:
|
||||
return http.StatusTooManyRequests
|
||||
case api.CodeUnavailable:
|
||||
return http.StatusServiceUnavailable
|
||||
default:
|
||||
return http.StatusInternalServerError
|
||||
}
|
||||
}
|
||||
|
||||
// WriteJSON writes v as JSON with the given status.
|
||||
func WriteJSON(w http.ResponseWriter, status int, v any) {
|
||||
buf, err := json.Marshal(v)
|
||||
if err != nil {
|
||||
// Marshalling our own response types should never fail; if it does the
|
||||
// handler already wrote nothing, so a bare 500 is the honest answer.
|
||||
http.Error(w, `{"error":{"code":"internal","message":"response encoding failed"}}`,
|
||||
http.StatusInternalServerError)
|
||||
return
|
||||
}
|
||||
w.Header().Set("Content-Type", "application/json; charset=utf-8")
|
||||
w.WriteHeader(status)
|
||||
_, _ = w.Write(buf)
|
||||
_, _ = w.Write([]byte("\n"))
|
||||
}
|
||||
|
||||
// WriteError renders err as the standard error envelope. Non-api errors become
|
||||
// an opaque 500: internal failure text may name paths or SQL and must not reach
|
||||
// the client. The full error is logged instead.
|
||||
func WriteError(w http.ResponseWriter, r *http.Request, log *slog.Logger, err error) {
|
||||
var apiErr *api.Error
|
||||
if !errors.As(err, &apiErr) {
|
||||
var maxErr *http.MaxBytesError
|
||||
if errors.As(err, &maxErr) {
|
||||
apiErr = api.Errorf(api.CodePayloadTooLarge, "request body exceeds %d bytes", maxErr.Limit)
|
||||
} else {
|
||||
if log != nil {
|
||||
log.ErrorContext(r.Context(), "unhandled error", "err", err,
|
||||
"method", r.Method, "path", r.URL.Path)
|
||||
}
|
||||
apiErr = api.Errorf(api.CodeInternal, "internal error")
|
||||
}
|
||||
}
|
||||
status := StatusFor(apiErr.Code)
|
||||
if status >= 500 && log != nil {
|
||||
log.ErrorContext(r.Context(), "request failed", "err", err,
|
||||
"code", string(apiErr.Code), "method", r.Method, "path", r.URL.Path)
|
||||
}
|
||||
WriteJSON(w, status, api.ErrorEnvelope{Error: *apiErr})
|
||||
}
|
||||
|
||||
// DecodeJSON reads a JSON body into v, capped at maxBytes. It rejects unknown
|
||||
// fields (a misspelled key in a deploy script should fail, not be ignored) and
|
||||
// trailing content after the top-level value.
|
||||
func DecodeJSON(w http.ResponseWriter, r *http.Request, maxBytes int64, v any) error {
|
||||
r.Body = http.MaxBytesReader(w, r.Body, maxBytes)
|
||||
dec := json.NewDecoder(r.Body)
|
||||
dec.DisallowUnknownFields()
|
||||
if err := dec.Decode(v); err != nil {
|
||||
var maxErr *http.MaxBytesError
|
||||
if errors.As(err, &maxErr) {
|
||||
return api.Errorf(api.CodePayloadTooLarge, "request body exceeds %d bytes", maxErr.Limit)
|
||||
}
|
||||
var syn *json.SyntaxError
|
||||
if errors.As(err, &syn) {
|
||||
return api.Errorf(api.CodeBadRequest, "malformed JSON at byte %d", syn.Offset)
|
||||
}
|
||||
var typeErr *json.UnmarshalTypeError
|
||||
if errors.As(err, &typeErr) {
|
||||
return api.Errorf(api.CodeBadRequest, "field %q: want %s", typeErr.Field, typeErr.Type)
|
||||
}
|
||||
return api.Errorf(api.CodeBadRequest, "%s", err)
|
||||
}
|
||||
if dec.More() {
|
||||
return api.Errorf(api.CodeBadRequest, "unexpected content after JSON value")
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
// newInternalEnvelope builds the opaque 500 body. The request id is included so
|
||||
// an operator can find the corresponding log line, which holds the real cause.
|
||||
func newInternalEnvelope(reqID string) api.ErrorEnvelope {
|
||||
e := api.Errorf(api.CodeInternal, "internal error")
|
||||
if reqID != "" {
|
||||
e = e.WithDetail("request_id", reqID)
|
||||
}
|
||||
return api.ErrorEnvelope{Error: *e}
|
||||
}
|
||||
|
||||
// NoBody rejects requests that carry a body where none is expected.
|
||||
func NoBody(r *http.Request) error {
|
||||
if r.ContentLength > 0 {
|
||||
return api.Errorf(api.CodeBadRequest, "unexpected request body")
|
||||
}
|
||||
return nil
|
||||
}
|
||||
@@ -0,0 +1,332 @@
|
||||
package httpx
|
||||
|
||||
import (
|
||||
"bufio"
|
||||
"context"
|
||||
"crypto/rand"
|
||||
"encoding/hex"
|
||||
"errors"
|
||||
"io"
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"net/netip"
|
||||
"runtime/debug"
|
||||
"strings"
|
||||
"sync"
|
||||
"time"
|
||||
)
|
||||
|
||||
// Middleware wraps a handler. Chain applies them so that the first listed runs
|
||||
// outermost.
|
||||
type Middleware func(http.Handler) http.Handler
|
||||
|
||||
// Chain wraps h with mw, outermost first.
|
||||
func Chain(h http.Handler, mw ...Middleware) http.Handler {
|
||||
for i := len(mw) - 1; i >= 0; i-- {
|
||||
h = mw[i](h)
|
||||
}
|
||||
return h
|
||||
}
|
||||
|
||||
type ctxKey int
|
||||
|
||||
const (
|
||||
ctxKeyRequestID ctxKey = iota
|
||||
ctxKeyLogState
|
||||
)
|
||||
|
||||
// ---------------------------------------------------------------- request id
|
||||
|
||||
// RequestIDFrom returns the request id assigned by WithRequestID.
|
||||
func RequestIDFrom(ctx context.Context) string {
|
||||
id, _ := ctx.Value(ctxKeyRequestID).(string)
|
||||
return id
|
||||
}
|
||||
|
||||
// WithRequestID assigns each request an id, echoes it in X-Request-Id, and makes
|
||||
// it available to handlers and the access log.
|
||||
//
|
||||
// An inbound X-Request-Id is adopted only when the peer is a trusted proxy and
|
||||
// the value is short and printable: it ends up in log records, and an arbitrary
|
||||
// client-controlled string there is a log-forging primitive.
|
||||
func WithRequestID(trusted []netip.Prefix) Middleware {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
id := ""
|
||||
if in := r.Header.Get("X-Request-Id"); in != "" && sanitaryID(in) {
|
||||
if addr, ok := peerAddr(r); ok && inAny(addr, trusted) {
|
||||
id = in
|
||||
}
|
||||
}
|
||||
if id == "" {
|
||||
id = newID()
|
||||
}
|
||||
w.Header().Set("X-Request-Id", id)
|
||||
ctx := context.WithValue(r.Context(), ctxKeyRequestID, id)
|
||||
next.ServeHTTP(w, r.WithContext(ctx))
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func newID() string {
|
||||
var b [8]byte
|
||||
if _, err := rand.Read(b[:]); err != nil {
|
||||
// crypto/rand cannot fail on any supported platform; if it somehow does,
|
||||
// an empty id is better than taking down the request.
|
||||
return ""
|
||||
}
|
||||
return hex.EncodeToString(b[:])
|
||||
}
|
||||
|
||||
func sanitaryID(s string) bool {
|
||||
if len(s) == 0 || len(s) > 64 {
|
||||
return false
|
||||
}
|
||||
for i := 0; i < len(s); i++ {
|
||||
c := s[i]
|
||||
if c < 0x21 || c > 0x7e {
|
||||
return false
|
||||
}
|
||||
}
|
||||
return true
|
||||
}
|
||||
|
||||
// ------------------------------------------------------------- log enrichment
|
||||
|
||||
// logState collects attributes that handlers discover mid-request (project,
|
||||
// deployment, key id) so the single access-log line can carry them.
|
||||
type logState struct {
|
||||
mu sync.Mutex
|
||||
attrs []slog.Attr
|
||||
}
|
||||
|
||||
// LogAttr attaches a key/value pair to this request's access-log line. It is a
|
||||
// no-op outside the middleware chain, so handlers may call it unconditionally.
|
||||
//
|
||||
// Never pass a token, an Authorization header, or any part of either.
|
||||
func LogAttr(ctx context.Context, key string, value any) {
|
||||
st, ok := ctx.Value(ctxKeyLogState).(*logState)
|
||||
if !ok {
|
||||
return
|
||||
}
|
||||
st.mu.Lock()
|
||||
st.attrs = append(st.attrs, slog.Any(key, value))
|
||||
st.mu.Unlock()
|
||||
}
|
||||
|
||||
// -------------------------------------------------------------- access logger
|
||||
|
||||
// AccessLog emits exactly one record per request.
|
||||
//
|
||||
// It logs the method, the URL path, and nothing else from the request: headers
|
||||
// are never logged (Authorization carries a bearer token) and neither is the raw
|
||||
// query string. Handlers add their own context with LogAttr.
|
||||
func AccessLog(log *slog.Logger, trusted []netip.Prefix) Middleware {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
st := &logState{}
|
||||
ctx := context.WithValue(r.Context(), ctxKeyLogState, st)
|
||||
r = r.WithContext(ctx)
|
||||
|
||||
rec := &recorder{ResponseWriter: w, status: http.StatusOK}
|
||||
start := time.Now()
|
||||
next.ServeHTTP(rec, r)
|
||||
dur := time.Since(start)
|
||||
|
||||
level := slog.LevelInfo
|
||||
switch {
|
||||
case rec.status >= 500:
|
||||
level = slog.LevelError
|
||||
case rec.status == http.StatusNotFound || rec.status == http.StatusMethodNotAllowed:
|
||||
// Ordinary outcomes on a public listener: a crawler, a stale link,
|
||||
// a missing favicon. Logging them as warnings would make warnings
|
||||
// the bulk of the file and hide the ones that mean something.
|
||||
level = slog.LevelInfo
|
||||
case rec.status >= 400:
|
||||
level = slog.LevelWarn
|
||||
case r.URL.Path == "/healthz" || r.URL.Path == "/readyz":
|
||||
level = slog.LevelDebug
|
||||
}
|
||||
if !log.Enabled(ctx, level) {
|
||||
return
|
||||
}
|
||||
|
||||
st.mu.Lock()
|
||||
extra := st.attrs
|
||||
st.mu.Unlock()
|
||||
|
||||
attrs := make([]slog.Attr, 0, 8+len(extra))
|
||||
attrs = append(attrs,
|
||||
slog.String("method", r.Method),
|
||||
slog.String("path", r.URL.Path),
|
||||
slog.Int("status", rec.status),
|
||||
slog.Int64("bytes", rec.written),
|
||||
slog.Float64("dur_ms", float64(dur.Microseconds())/1000),
|
||||
)
|
||||
if ip, ok := ClientIP(r, trusted); ok {
|
||||
attrs = append(attrs, slog.String("ip", ip.String()))
|
||||
}
|
||||
if id := RequestIDFrom(ctx); id != "" {
|
||||
attrs = append(attrs, slog.String("req_id", id))
|
||||
}
|
||||
attrs = append(attrs, extra...)
|
||||
log.LogAttrs(ctx, level, "request", attrs...)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// ------------------------------------------------------------------ recovery
|
||||
|
||||
// Recover turns a handler panic into a 500 instead of tearing down the process,
|
||||
// logging the stack. The panic value itself never reaches the client.
|
||||
func Recover(log *slog.Logger) Middleware {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
defer func() {
|
||||
v := recover()
|
||||
if v == nil {
|
||||
return
|
||||
}
|
||||
// ErrAbortHandler is the documented way to abort a response;
|
||||
// net/http expects to handle it and logs nothing.
|
||||
if err, ok := v.(error); ok && errors.Is(err, http.ErrAbortHandler) {
|
||||
panic(v)
|
||||
}
|
||||
log.ErrorContext(r.Context(), "handler panic",
|
||||
"panic", v,
|
||||
"method", r.Method,
|
||||
"path", r.URL.Path,
|
||||
"req_id", RequestIDFrom(r.Context()),
|
||||
"stack", string(debug.Stack()),
|
||||
)
|
||||
if rec, ok := w.(*recorder); ok && rec.wroteHeader {
|
||||
return // response already begun; nothing safe left to send
|
||||
}
|
||||
WriteJSON(w, http.StatusInternalServerError,
|
||||
newInternalEnvelope(RequestIDFrom(r.Context())))
|
||||
}()
|
||||
next.ServeHTTP(w, r)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// ---------------------------------------------------------------- client IP
|
||||
|
||||
// ClientIP returns the address to attribute the request to. X-Forwarded-For is
|
||||
// honoured only when the direct peer is itself a trusted proxy; otherwise any
|
||||
// client could forge its own source address and defeat per-IP rate limiting.
|
||||
func ClientIP(r *http.Request, trusted []netip.Prefix) (netip.Addr, bool) {
|
||||
peer, ok := peerAddr(r)
|
||||
if !ok {
|
||||
return netip.Addr{}, false
|
||||
}
|
||||
if !inAny(peer, trusted) {
|
||||
return peer, true
|
||||
}
|
||||
// Walk right to left and take the first address that is not itself trusted:
|
||||
// everything to its right was appended by infrastructure we control, and
|
||||
// everything to its left may have been forged by the client.
|
||||
xff := r.Header.Values("X-Forwarded-For")
|
||||
for i := len(xff) - 1; i >= 0; i-- {
|
||||
parts := strings.Split(xff[i], ",")
|
||||
for j := len(parts) - 1; j >= 0; j-- {
|
||||
addr, err := netip.ParseAddr(strings.TrimSpace(parts[j]))
|
||||
if err != nil {
|
||||
continue
|
||||
}
|
||||
addr = addr.Unmap()
|
||||
if !inAny(addr, trusted) {
|
||||
return addr, true
|
||||
}
|
||||
}
|
||||
}
|
||||
return peer, true
|
||||
}
|
||||
|
||||
func peerAddr(r *http.Request) (netip.Addr, bool) {
|
||||
host, _, err := net.SplitHostPort(r.RemoteAddr)
|
||||
if err != nil {
|
||||
host = r.RemoteAddr
|
||||
}
|
||||
addr, err := netip.ParseAddr(host)
|
||||
if err != nil {
|
||||
return netip.Addr{}, false
|
||||
}
|
||||
return addr.Unmap(), true
|
||||
}
|
||||
|
||||
func inAny(addr netip.Addr, prefixes []netip.Prefix) bool {
|
||||
for _, p := range prefixes {
|
||||
if p.Contains(addr) {
|
||||
return true
|
||||
}
|
||||
}
|
||||
return false
|
||||
}
|
||||
|
||||
// ------------------------------------------------------------ response record
|
||||
|
||||
// recorder observes the status and byte count without altering behaviour.
|
||||
//
|
||||
// It implements Unwrap, ReadFrom, Flush and Hijack so that wrapping costs
|
||||
// nothing: without ReadFrom the static handler would lose the sendfile fast
|
||||
// path that io.Copy takes when the destination is the raw *http.response.
|
||||
type recorder struct {
|
||||
http.ResponseWriter
|
||||
status int
|
||||
written int64
|
||||
wroteHeader bool
|
||||
}
|
||||
|
||||
func (r *recorder) WriteHeader(status int) {
|
||||
if r.wroteHeader {
|
||||
return
|
||||
}
|
||||
r.status = status
|
||||
r.wroteHeader = true
|
||||
r.ResponseWriter.WriteHeader(status)
|
||||
}
|
||||
|
||||
func (r *recorder) Write(b []byte) (int, error) {
|
||||
if !r.wroteHeader {
|
||||
r.WriteHeader(http.StatusOK)
|
||||
}
|
||||
n, err := r.ResponseWriter.Write(b)
|
||||
r.written += int64(n)
|
||||
return n, err
|
||||
}
|
||||
|
||||
func (r *recorder) ReadFrom(src io.Reader) (int64, error) {
|
||||
if !r.wroteHeader {
|
||||
r.WriteHeader(http.StatusOK)
|
||||
}
|
||||
rf, ok := r.ResponseWriter.(io.ReaderFrom)
|
||||
if !ok {
|
||||
n, err := io.Copy(r.ResponseWriter, src)
|
||||
r.written += n
|
||||
return n, err
|
||||
}
|
||||
n, err := rf.ReadFrom(src)
|
||||
r.written += n
|
||||
return n, err
|
||||
}
|
||||
|
||||
func (r *recorder) Unwrap() http.ResponseWriter { return r.ResponseWriter }
|
||||
|
||||
func (r *recorder) Flush() {
|
||||
if f, ok := r.ResponseWriter.(http.Flusher); ok {
|
||||
if !r.wroteHeader {
|
||||
r.WriteHeader(http.StatusOK)
|
||||
}
|
||||
f.Flush()
|
||||
}
|
||||
}
|
||||
|
||||
func (r *recorder) Hijack() (net.Conn, *bufio.ReadWriter, error) {
|
||||
h, ok := r.ResponseWriter.(http.Hijacker)
|
||||
if !ok {
|
||||
return nil, nil, errors.New("httpx: ResponseWriter does not support hijacking")
|
||||
}
|
||||
return h.Hijack()
|
||||
}
|
||||
@@ -0,0 +1,143 @@
|
||||
package httpx
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"time"
|
||||
)
|
||||
|
||||
// Timeouts configures a listener's deadlines.
|
||||
//
|
||||
// WriteTimeout is deliberately optional and left at zero for the static
|
||||
// listener: a global write deadline covers the whole response, so a large file
|
||||
// over a slow link gets its connection torn down mid-download even though
|
||||
// nothing is wrong. Per-response deadlines belong to the handler, via
|
||||
// http.ResponseController.
|
||||
type Timeouts struct {
|
||||
ReadHeader time.Duration
|
||||
Read time.Duration
|
||||
Idle time.Duration
|
||||
Write time.Duration // 0 = none
|
||||
}
|
||||
|
||||
// Server is an http.Server whose listener is already bound.
|
||||
//
|
||||
// Binding at construction time means a port conflict is reported before any
|
||||
// background work starts, and it lets a caller pass ":0" and read back the
|
||||
// chosen address — which is what the integration tests do.
|
||||
type Server struct {
|
||||
Name string
|
||||
|
||||
srv *http.Server
|
||||
ln net.Listener
|
||||
log *slog.Logger
|
||||
}
|
||||
|
||||
// Listen binds addr and prepares a server for h.
|
||||
func Listen(name, addr string, h http.Handler, t Timeouts, log *slog.Logger) (*Server, error) {
|
||||
ln, err := net.Listen("tcp", addr)
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
s := &Server{
|
||||
Name: name,
|
||||
ln: ln,
|
||||
log: log,
|
||||
srv: &http.Server{
|
||||
Handler: h,
|
||||
ReadHeaderTimeout: t.ReadHeader,
|
||||
ReadTimeout: t.Read,
|
||||
IdleTimeout: t.Idle,
|
||||
WriteTimeout: t.Write,
|
||||
// Route net/http's own errors (malformed requests, TLS handshake
|
||||
// failures) into the structured log rather than bare stderr.
|
||||
ErrorLog: slog.NewLogLogger(log.With("listener", name).Handler(), slog.LevelWarn),
|
||||
},
|
||||
}
|
||||
return s, nil
|
||||
}
|
||||
|
||||
// Addr is the address actually bound, which differs from the requested one when
|
||||
// port 0 was asked for.
|
||||
func (s *Server) Addr() string { return s.ln.Addr().String() }
|
||||
|
||||
// Serve blocks until the server stops. It returns nil on a graceful shutdown.
|
||||
func (s *Server) Serve() error {
|
||||
err := s.srv.Serve(s.ln)
|
||||
if errors.Is(err, http.ErrServerClosed) {
|
||||
return nil
|
||||
}
|
||||
return err
|
||||
}
|
||||
|
||||
// Shutdown stops accepting connections and waits for in-flight requests, up to
|
||||
// ctx's deadline. Past the deadline the remaining connections are closed.
|
||||
func (s *Server) Shutdown(ctx context.Context) error {
|
||||
err := s.srv.Shutdown(ctx)
|
||||
if err != nil {
|
||||
// Shutdown only fails by running out of time; Close is then the only way
|
||||
// to release the port.
|
||||
s.log.Warn("graceful shutdown timed out, closing connections",
|
||||
"listener", s.Name, "err", err)
|
||||
return s.srv.Close()
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
// Group runs several servers with a shared lifetime: if one fails, all stop.
|
||||
type Group struct {
|
||||
Servers []*Server
|
||||
Grace time.Duration
|
||||
Log *slog.Logger
|
||||
}
|
||||
|
||||
// Run serves until ctx is cancelled or a server fails, then shuts every server
|
||||
// down within Grace. It returns the first non-nil error.
|
||||
func (g *Group) Run(ctx context.Context) error {
|
||||
errs := make(chan error, len(g.Servers))
|
||||
for _, s := range g.Servers {
|
||||
go func() {
|
||||
g.Log.Info("listening", "listener", s.Name, "addr", s.Addr())
|
||||
errs <- s.Serve()
|
||||
}()
|
||||
}
|
||||
|
||||
var first error
|
||||
done := 0
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
g.Log.Info("shutting down", "grace", g.Grace)
|
||||
case err := <-errs:
|
||||
done++
|
||||
first = err
|
||||
if err != nil {
|
||||
g.Log.Error("listener failed, stopping", "err", err)
|
||||
}
|
||||
}
|
||||
|
||||
// The shutdown deadline must survive the cancellation that triggered it,
|
||||
// otherwise ctx.Done() would make Shutdown return immediately.
|
||||
shutCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), g.Grace)
|
||||
defer cancel()
|
||||
for _, s := range g.Servers {
|
||||
if err := s.Shutdown(shutCtx); err != nil && first == nil {
|
||||
first = err
|
||||
}
|
||||
}
|
||||
|
||||
// Drain the remaining Serve results so no goroutine is left blocked on send.
|
||||
for ; done < len(g.Servers); done++ {
|
||||
select {
|
||||
case err := <-errs:
|
||||
if err != nil && first == nil {
|
||||
first = err
|
||||
}
|
||||
case <-time.After(5 * time.Second):
|
||||
return first
|
||||
}
|
||||
}
|
||||
return first
|
||||
}
|
||||
Reference in New Issue
Block a user