diff --git a/cmd/cachewd/main.go b/cmd/cachewd/main.go index bad875a1..5220d222 100644 --- a/cmd/cachewd/main.go +++ b/cmd/cachewd/main.go @@ -23,6 +23,7 @@ import ( "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" + "github.com/block/cachew/internal/accesslog" "github.com/block/cachew/internal/cache" "github.com/block/cachew/internal/config" "github.com/block/cachew/internal/gitclone" @@ -54,6 +55,7 @@ type GlobalConfig struct { MetricsConfig metrics.Config `hcl:"metrics,block"` GitCloneConfig gitclone.Config `hcl:"git-clone,block"` S3Config s3client.Config `hcl:"s3,block,optional"` + AccessLogConfig accesslog.Config `hcl:"access-log,block,optional"` GithubAppConfigs []githubapp.Config `hcl:"github-app,block,optional"` OPAConfig opa.Config `hcl:"opa,block"` } @@ -141,22 +143,19 @@ func main() { mux, err := newMux(ctx, &shuttingDown, cr, mr, sr, providersConfigHCL, envars) fatalIfError(ctx, logger, err, "Failed to load config") - metricsClient, err := metrics.New(ctx, globalConfig.MetricsConfig) - fatalIfError(ctx, logger, err, "Failed to create metrics client") + metricsClient := startMetrics(ctx, logger, globalConfig.MetricsConfig) defer func() { if err := metricsClient.Close(); err != nil { logger.ErrorContext(ctx, "Failed to close metrics client", "error", err) } }() - if err := metricsClient.ServeMetrics(ctx); err != nil { - fatalIfError(ctx, logger, err, "Failed to start metrics server") - } - runOPATests(ctx, logger, globalConfig.OPAConfig) logger.InfoContext(ctx, "Starting cachewd", "bind", globalConfig.Bind) + accessLogWriter := newAccessLogWriter(ctx, logger, globalConfig.AccessLogConfig, s3ClientProvider) + server, err := newServer( ctx, mux, @@ -164,6 +163,8 @@ func main() { globalConfig.MetricsConfig, globalConfig.OPAConfig, globalConfig.LoggingConfig, + globalConfig.AccessLogConfig, + accessLogWriter, ) fatalIfError(ctx, logger, err, "Failed to create server") @@ -186,10 +187,46 @@ func main() { gracefulShutdown(ctx, logger, server, &shuttingDown, globalConfig.ShutdownReadinessDelay, globalConfig.ShutdownTimeout) + closeAccessLogWriter(ctx, logger, accessLogWriter) + cancelScheduler() drainScheduler(ctx, logger, schedulerProvider) } +// startMetrics creates the metrics client and starts the metrics server, +// exiting the process on failure. +func startMetrics(ctx context.Context, logger *slog.Logger, config metrics.Config) *metrics.Client { + metricsClient, err := metrics.New(ctx, config) + fatalIfError(ctx, logger, err, "Failed to create metrics client") + if err := metricsClient.ServeMetrics(ctx); err != nil { + fatalIfError(ctx, logger, err, "Failed to start metrics server") + } + return metricsClient +} + +// newAccessLogWriter returns nil when access log export is not configured, +// exiting the process on invalid configuration. +func newAccessLogWriter(ctx context.Context, logger *slog.Logger, config accesslog.Config, provider s3client.ClientProvider) *accesslog.Writer { + if config.Bucket == "" { + return nil + } + fatalIfError(ctx, logger, config.Validate(), "Invalid access log config") + return accesslog.NewWriter(ctx, config, provider) +} + +const accessLogCloseTimeout = 30 * time.Second + +func closeAccessLogWriter(ctx context.Context, logger *slog.Logger, writer *accesslog.Writer) { + if writer == nil { + return + } + closeCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), accessLogCloseTimeout) + defer cancel() + if err := writer.Close(closeCtx); err != nil { + logger.ErrorContext(ctx, "Failed to flush access log writer", "error", err) + } +} + // gracefulShutdown fails readiness, waits readinessDelay for load balancers // to drain, then runs http.Server.Shutdown bounded by shutdownTimeout. func gracefulShutdown( @@ -380,6 +417,8 @@ func newServer( metricsConfig metrics.Config, opaConfig opa.Config, logConfig logging.Config, + accessLogConfig accesslog.Config, + accessLogWriter *accesslog.Writer, ) (*http.Server, error) { var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { labeler, _ := otelhttp.LabelerFromContext(r.Context()) @@ -392,6 +431,11 @@ func newServer( return nil, errors.Errorf("initialise OPA middleware: %w", err) } + // Wrap outside OPA so denied requests are captured too. + if accessLogWriter != nil { + handler = accesslog.Middleware(handler, accessLogWriter, accessLogConfig) + } + // Add standard otelhttp middleware handler = otelhttp.NewMiddleware(metricsConfig.ServiceName, otelhttp.WithMeterProvider(otel.GetMeterProvider()), diff --git a/internal/accesslog/accesslog.go b/internal/accesslog/accesslog.go new file mode 100644 index 00000000..46c1e0f1 --- /dev/null +++ b/internal/accesslog/accesslog.go @@ -0,0 +1,134 @@ +// Package accesslog exports structured HTTP access log events to S3 as +// batched JSONL objects (gzip-compressed by default), suitable for ingestion +// by log analysis and security monitoring pipelines. +package accesslog + +import ( + "net/http" + "time" + + "github.com/alecthomas/errors" +) + +// Compression modes for exported objects. +const ( + CompressionGzip = "gzip" + CompressionNone = "none" +) + +// Config configures access log export to S3. Export is enabled when Bucket is +// non-empty. Connection parameters (endpoint, region, credentials) come from +// the global s3 block. +type Config struct { + Bucket string `hcl:"bucket" help:"S3 bucket to export access log events to."` + Prefix string `hcl:"prefix,optional" default:"access-logs" help:"Object key prefix for exported batches."` + FlushInterval time.Duration `hcl:"flush-interval,optional" default:"1m" help:"How often buffered events are flushed to S3."` + MaxBufferedEvents int `hcl:"max-buffered-events,optional" default:"65536" help:"Maximum events held in memory; new events are dropped when the buffer is full."` + Compression string `hcl:"compression,optional" default:"gzip" help:"Compression for exported objects: gzip or none."` + Headers map[string]string `hcl:"headers,optional" help:"Record these inbound request headers as the given event field."` +} + +// Validate checks the configuration for invalid values. +func (c Config) Validate() error { + if c.FlushInterval <= 0 { + return errors.Errorf("invalid access log flush-interval %s: must be positive", c.FlushInterval) + } + switch c.Compression { + case "", CompressionGzip, CompressionNone: + return nil + default: + return errors.Errorf("invalid access log compression %q: must be %q or %q", c.Compression, CompressionGzip, CompressionNone) + } +} + +// Event is a single access log record. It is serialised as one JSON object +// per line (JSONL). +type Event struct { + Timestamp time.Time `json:"timestamp"` + Method string `json:"method"` + Path string `json:"path"` + Query string `json:"query,omitempty"` + Status int `json:"status"` + BytesSent int64 `json:"bytes_sent"` + DurationMS float64 `json:"duration_ms"` + RemoteAddr string `json:"remote_addr"` + Host string `json:"host,omitempty"` + UserAgent string `json:"user_agent,omitempty"` + Headers map[string]string `json:"headers,omitempty"` +} + +// Recorder accepts access log events. Implemented by *Writer. +type Recorder interface { + Record(event Event) +} + +// Middleware records one Event per request to the given Recorder. +func Middleware(next http.Handler, recorder Recorder, config Config) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + rec := &responseRecorder{ResponseWriter: w} + start := time.Now() + next.ServeHTTP(rec, r) + + event := Event{ + Timestamp: start.UTC(), + Method: r.Method, + Path: r.URL.Path, + Query: r.URL.RawQuery, + Status: rec.statusCode(), + BytesSent: rec.bytes, + DurationMS: float64(time.Since(start)) / float64(time.Millisecond), + RemoteAddr: r.RemoteAddr, + Host: r.Host, + UserAgent: r.UserAgent(), + } + for header, field := range config.Headers { + if v := r.Header.Get(header); v != "" { + if event.Headers == nil { + event.Headers = map[string]string{} + } + event.Headers[field] = v + } + } + recorder.Record(event) + }) +} + +type responseRecorder struct { + http.ResponseWriter + status int + bytes int64 +} + +func (r *responseRecorder) WriteHeader(status int) { + if r.status == 0 { + r.status = status + } + r.ResponseWriter.WriteHeader(status) +} + +func (r *responseRecorder) Write(b []byte) (int, error) { + if r.status == 0 { + r.status = http.StatusOK + } + n, err := r.ResponseWriter.Write(b) + r.bytes += int64(n) + return n, err //nolint:wrapcheck +} + +// Flush is implemented explicitly because streaming handlers type-assert +// http.Flusher directly on the ResponseWriter they receive. +func (r *responseRecorder) Flush() { + if f, ok := r.ResponseWriter.(http.Flusher); ok { + f.Flush() + } +} + +// Unwrap supports http.ResponseController. +func (r *responseRecorder) Unwrap() http.ResponseWriter { return r.ResponseWriter } + +func (r *responseRecorder) statusCode() int { + if r.status == 0 { + return http.StatusOK + } + return r.status +} diff --git a/internal/accesslog/accesslog_test.go b/internal/accesslog/accesslog_test.go new file mode 100644 index 00000000..b548d44c --- /dev/null +++ b/internal/accesslog/accesslog_test.go @@ -0,0 +1,54 @@ +package accesslog_test + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/alecthomas/assert/v2" + + "github.com/block/cachew/internal/accesslog" +) + +type recorder struct { + events []accesslog.Event +} + +func (r *recorder) Record(event accesslog.Event) { r.events = append(r.events, event) } + +func TestMiddleware(t *testing.T) { + rec := &recorder{} + handler := accesslog.Middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusTeapot) + _, _ = w.Write([]byte("hello")) //nolint:errcheck + }), rec, accesslog.Config{Headers: map[string]string{"X-Client-Id": "client_id"}}) + + req := httptest.NewRequest(http.MethodGet, "/git/github.com/org/repo?service=git-upload-pack", nil) + req.Header.Set("X-Client-Id", "abc-123") + req.Header.Set("User-Agent", "git/2.44.0") + handler.ServeHTTP(httptest.NewRecorder(), req) + + assert.Equal(t, 1, len(rec.events)) + event := rec.events[0] + assert.Equal(t, http.MethodGet, event.Method) + assert.Equal(t, "/git/github.com/org/repo", event.Path) + assert.Equal(t, "service=git-upload-pack", event.Query) + assert.Equal(t, http.StatusTeapot, event.Status) + assert.Equal(t, 5, int(event.BytesSent)) + assert.Equal(t, "git/2.44.0", event.UserAgent) + assert.Equal(t, map[string]string{"client_id": "abc-123"}, event.Headers) + assert.False(t, event.Timestamp.IsZero()) +} + +func TestMiddlewareImplicitOK(t *testing.T) { + rec := &recorder{} + handler := accesslog.Middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte("ok")) //nolint:errcheck + }), rec, accesslog.Config{}) + + handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil)) + + assert.Equal(t, 1, len(rec.events)) + assert.Equal(t, http.StatusOK, rec.events[0].Status) + assert.Zero(t, rec.events[0].Headers) +} diff --git a/internal/accesslog/writer.go b/internal/accesslog/writer.go new file mode 100644 index 00000000..2efdf767 --- /dev/null +++ b/internal/accesslog/writer.go @@ -0,0 +1,190 @@ +package accesslog + +import ( + "bytes" + "compress/gzip" + "context" + "encoding/json" + "fmt" + "log/slog" + "os" + "path" + "sync" + "time" + + "github.com/alecthomas/errors" + "github.com/minio/minio-go/v7" + + "github.com/block/cachew/internal/logging" + "github.com/block/cachew/internal/s3client" +) + +// Writer buffers access log events in memory and periodically flushes them to +// S3 as JSONL objects, gzip-compressed unless configured otherwise. Recording +// never blocks the request path: when the buffer is full new events are +// dropped and counted, and a failed flush requeues its batch for the next +// attempt. +type Writer struct { + logger *slog.Logger + config Config + clientProvider s3client.ClientProvider + hostname string + + mu sync.Mutex + events []Event + dropped int64 + + stop chan struct{} + stopped chan struct{} +} + +// NewWriter creates a Writer and starts its background flush loop. The config +// must have been validated with Config.Validate. +func NewWriter(ctx context.Context, config Config, clientProvider s3client.ClientProvider) *Writer { + hostname, err := os.Hostname() + if err != nil { + hostname = "unknown" + } + w := &Writer{ + logger: logging.FromContext(ctx), + config: config, + clientProvider: clientProvider, + hostname: hostname, + stop: make(chan struct{}), + stopped: make(chan struct{}), + } + go w.run(ctx) + return w +} + +// Record buffers an event for the next flush, dropping it if the buffer is full. +func (w *Writer) Record(event Event) { + w.mu.Lock() + defer w.mu.Unlock() + if len(w.events) >= w.config.MaxBufferedEvents { + w.dropped++ + return + } + w.events = append(w.events, event) +} + +// Close stops the background loop, performs the final flush, and returns its +// error. It must be called after the last Record, once the HTTP server has +// fully shut down. +func (w *Writer) Close(ctx context.Context) error { + close(w.stop) + select { + case <-w.stopped: + case <-ctx.Done(): + return errors.Errorf("access log writer close: %w", ctx.Err()) + } + return w.flushBatch(ctx) +} + +// run flushes periodically until Close is called. Cancellation of ctx must +// not stop the loop or fail uploads: the root context is cancelled on SIGTERM +// while the server is still handling (and recording) requests during graceful +// shutdown, and Close performs the final flush only after that drain. +func (w *Writer) run(ctx context.Context) { + defer close(w.stopped) + ctx = context.WithoutCancel(ctx) + ticker := time.NewTicker(w.config.FlushInterval) + defer ticker.Stop() + for { + select { + case <-ticker.C: + w.flush(ctx) + case <-w.stop: + return + } + } +} + +func (w *Writer) flush(ctx context.Context) { + if err := w.flushBatch(ctx); err != nil { + w.logger.ErrorContext(ctx, "Failed to export access log batch", "error", err) + } +} + +// flushBatch drains the buffer and uploads it as one object, requeueing the +// batch on failure so a later flush can retry it. +func (w *Writer) flushBatch(ctx context.Context) error { + w.mu.Lock() + events := w.events + dropped := w.dropped + w.events = nil + w.dropped = 0 + w.mu.Unlock() + + if dropped > 0 { + w.logger.WarnContext(ctx, "Dropped access log events, buffer full", "dropped", dropped) + } + if len(events) == 0 { + return nil + } + if err := w.upload(ctx, events); err != nil { + w.requeue(events) + return errors.Errorf("flush %d access log events: %w", len(events), err) + } + return nil +} + +// requeue puts a failed batch back at the front of the buffer so ordering is +// preserved, dropping the newest events if the combined size exceeds the cap. +func (w *Writer) requeue(events []Event) { + w.mu.Lock() + defer w.mu.Unlock() + combined := append(events, w.events...) //nolint:gocritic + if len(combined) > w.config.MaxBufferedEvents { + w.dropped += int64(len(combined) - w.config.MaxBufferedEvents) + combined = combined[:w.config.MaxBufferedEvents] + } + w.events = combined +} + +func (w *Writer) upload(ctx context.Context, events []Event) error { + client, err := w.clientProvider() + if err != nil { + return errors.Errorf("s3 client: %w", err) + } + + buf, suffix, contentType, err := encodeBatch(events, w.config.Compression) + if err != nil { + return err + } + + now := time.Now().UTC() + key := path.Join(w.config.Prefix, now.Format("2006/01/02"), + fmt.Sprintf("%s-%d%s", w.hostname, now.UnixNano(), suffix)) + _, err = client.PutObject(ctx, w.config.Bucket, key, buf, int64(buf.Len()), + minio.PutObjectOptions{ContentType: contentType}) + if err != nil { + return errors.Errorf("upload access log batch: %w", err) + } + w.logger.DebugContext(ctx, "Exported access log batch", "bucket", w.config.Bucket, "key", key, "events", len(events)) + return nil +} + +func encodeBatch(events []Event, compression string) (body *bytes.Buffer, suffix, contentType string, err error) { + var buf bytes.Buffer + if compression == CompressionNone { + enc := json.NewEncoder(&buf) + for _, event := range events { + if err := enc.Encode(event); err != nil { + return nil, "", "", errors.Errorf("encode access log event: %w", err) + } + } + return &buf, ".jsonl", "application/x-ndjson", nil + } + gz := gzip.NewWriter(&buf) + enc := json.NewEncoder(gz) + for _, event := range events { + if err := enc.Encode(event); err != nil { + return nil, "", "", errors.Errorf("encode access log event: %w", err) + } + } + if err := gz.Close(); err != nil { + return nil, "", "", errors.Errorf("compress access log batch: %w", err) + } + return &buf, ".jsonl.gz", "application/gzip", nil +} diff --git a/internal/accesslog/writer_internal_test.go b/internal/accesslog/writer_internal_test.go new file mode 100644 index 00000000..0caba0c6 --- /dev/null +++ b/internal/accesslog/writer_internal_test.go @@ -0,0 +1,46 @@ +package accesslog + +import ( + "compress/gzip" + "encoding/json" + "testing" + "time" + + "github.com/alecthomas/assert/v2" +) + +func TestEncodeBatch(t *testing.T) { + events := []Event{ + {Timestamp: time.Unix(1, 0).UTC(), Method: "GET", Path: "/a", Status: 200}, + {Timestamp: time.Unix(2, 0).UTC(), Method: "POST", Path: "/b", Status: 403}, + } + + buf, suffix, contentType, err := encodeBatch(events, CompressionNone) + assert.NoError(t, err) + assert.Equal(t, ".jsonl", suffix) + assert.Equal(t, "application/x-ndjson", contentType) + var decoded []Event + dec := json.NewDecoder(buf) + for dec.More() { + var event Event + assert.NoError(t, dec.Decode(&event)) + decoded = append(decoded, event) + } + assert.Equal(t, events, decoded) + + buf, suffix, contentType, err = encodeBatch(events, CompressionGzip) + assert.NoError(t, err) + assert.Equal(t, ".jsonl.gz", suffix) + assert.Equal(t, "application/gzip", contentType) + gz, err := gzip.NewReader(buf) + assert.NoError(t, err) + decoded = nil + dec = json.NewDecoder(gz) + for dec.More() { + var event Event + assert.NoError(t, dec.Decode(&event)) + decoded = append(decoded, event) + } + assert.NoError(t, gz.Close()) + assert.Equal(t, events, decoded) +} diff --git a/internal/accesslog/writer_test.go b/internal/accesslog/writer_test.go new file mode 100644 index 00000000..c288fce7 --- /dev/null +++ b/internal/accesslog/writer_test.go @@ -0,0 +1,125 @@ +package accesslog_test + +import ( + "compress/gzip" + "encoding/json" + "io" + "log/slog" + "net/http" + "strings" + "testing" + "time" + + "github.com/alecthomas/assert/v2" + "github.com/minio/minio-go/v7" + + "github.com/block/cachew/internal/accesslog" + "github.com/block/cachew/internal/logging" + "github.com/block/cachew/internal/s3client" + "github.com/block/cachew/internal/s3client/s3clienttest" +) + +func newWriter(t *testing.T, bucket string, maxBuffered int, compression string) *accesslog.Writer { + t.Helper() + _, ctx := logging.Configure(t.Context(), logging.Config{Level: slog.LevelDebug}) + provider := s3client.NewClientProvider(ctx, s3client.Config{ + Endpoint: s3clienttest.Addr, + UseSSL: false, + }) + config := accesslog.Config{ + Bucket: bucket, + Prefix: "access-logs", + FlushInterval: time.Hour, + MaxBufferedEvents: maxBuffered, + Compression: compression, + } + assert.NoError(t, config.Validate()) + return accesslog.NewWriter(ctx, config, provider) +} + +func TestWriterExportsJSONLBatch(t *testing.T) { + bucket := s3clienttest.Start(t) + w := newWriter(t, bucket, 100, accesslog.CompressionGzip) + + now := time.Now().UTC().Truncate(time.Millisecond) + w.Record(accesslog.Event{Timestamp: now, Method: http.MethodGet, Path: "/git/a", Status: 200, BytesSent: 42}) + w.Record(accesslog.Event{Timestamp: now, Method: http.MethodPost, Path: "/api/v1/object/ns/key", Status: 403}) + assert.NoError(t, w.Close(t.Context())) + + events := readExportedEvents(t, bucket) + assert.Equal(t, 2, len(events)) + assert.Equal(t, "/git/a", events[0].Path) + assert.Equal(t, int64(42), events[0].BytesSent) + assert.Equal(t, now, events[0].Timestamp) + assert.Equal(t, 403, events[1].Status) +} + +func TestWriterExportsUncompressedJSONL(t *testing.T) { + bucket := s3clienttest.Start(t) + w := newWriter(t, bucket, 100, accesslog.CompressionNone) + + now := time.Now().UTC().Truncate(time.Millisecond) + w.Record(accesslog.Event{Timestamp: now, Method: http.MethodGet, Path: "/git/a", Status: 200}) + assert.NoError(t, w.Close(t.Context())) + + events := readExportedEvents(t, bucket) + assert.Equal(t, 1, len(events)) + assert.Equal(t, "/git/a", events[0].Path) + assert.Equal(t, now, events[0].Timestamp) +} + +func TestConfigValidate(t *testing.T) { + assert.Error(t, accesslog.Config{Bucket: "b", FlushInterval: time.Minute, Compression: "zstd"}.Validate()) + assert.Error(t, accesslog.Config{Bucket: "b"}.Validate()) + assert.Error(t, accesslog.Config{Bucket: "b", FlushInterval: -time.Second}.Validate()) + assert.NoError(t, accesslog.Config{Bucket: "b", FlushInterval: time.Minute}.Validate()) + assert.NoError(t, accesslog.Config{Bucket: "b", FlushInterval: time.Minute, Compression: accesslog.CompressionNone}.Validate()) +} + +func TestWriterDropsWhenBufferFull(t *testing.T) { + bucket := s3clienttest.Start(t) + w := newWriter(t, bucket, 2, accesslog.CompressionGzip) + + for range 5 { + w.Record(accesslog.Event{Timestamp: time.Now(), Method: http.MethodGet, Path: "/x", Status: 200}) + } + assert.NoError(t, w.Close(t.Context())) + + events := readExportedEvents(t, bucket) + assert.Equal(t, 2, len(events)) +} + +// readExportedEvents decodes every exported JSONL object in the bucket in key order. +func readExportedEvents(t *testing.T, bucket string) []accesslog.Event { + t.Helper() + client := s3clienttest.Client(t) + var events []accesslog.Event + for object := range client.ListObjects(t.Context(), bucket, minio.ListObjectsOptions{Recursive: true}) { + assert.NoError(t, object.Err) + assert.True(t, strings.HasPrefix(object.Key, "access-logs/")) + + obj, err := client.GetObject(t.Context(), bucket, object.Key, minio.GetObjectOptions{}) + assert.NoError(t, err) + var body io.Reader = obj + var gz *gzip.Reader + if strings.HasSuffix(object.Key, ".jsonl.gz") { + var err error + gz, err = gzip.NewReader(obj) + assert.NoError(t, err) + body = gz + } else { + assert.True(t, strings.HasSuffix(object.Key, ".jsonl")) + } + dec := json.NewDecoder(body) + for dec.More() { + var event accesslog.Event + assert.NoError(t, dec.Decode(&event)) + events = append(events, event) + } + if gz != nil { + assert.NoError(t, gz.Close()) + } + assert.NoError(t, obj.Close()) + } + return events +}