summaryrefslogtreecommitdiff
path: root/modules
diff options
context:
space:
mode:
Diffstat (limited to 'modules')
-rw-r--r--modules/caddyhttp/logging.go22
-rw-r--r--modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go9
-rw-r--r--modules/caddyhttp/server.go95
-rw-r--r--modules/caddyhttp/server_test.go146
-rw-r--r--modules/caddyhttp/tracing/tracer.go12
5 files changed, 232 insertions, 52 deletions
diff --git a/modules/caddyhttp/logging.go b/modules/caddyhttp/logging.go
index 4faaec7..6bfeb51 100644
--- a/modules/caddyhttp/logging.go
+++ b/modules/caddyhttp/logging.go
@@ -20,6 +20,7 @@ import (
"net/http"
"strings"
+ "github.com/caddyserver/caddy/v2"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
@@ -139,6 +140,21 @@ func errLogValues(err error) (status int, msg string, fields []zapcore.Field) {
return
}
-// Variable name used to indicate that this request
-// should be omitted from the access logs
-const SkipLogVar = "skip_log"
+// ExtraLogFields is a list of extra fields to log with every request.
+type ExtraLogFields struct {
+ fields []zapcore.Field
+}
+
+// Add adds a field to the list of extra fields to log.
+func (e *ExtraLogFields) Add(field zap.Field) {
+ e.fields = append(e.fields, field)
+}
+
+const (
+ // Variable name used to indicate that this request
+ // should be omitted from the access logs
+ SkipLogVar string = "skip_log"
+
+ // For adding additional fields to the access logs
+ ExtraLogFieldsCtxKey caddy.CtxKey = "extra_log_fields"
+)
diff --git a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
index ec194e7..5160067 100644
--- a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
+++ b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
@@ -254,9 +254,7 @@ func (t Transport) buildEnv(r *http.Request) (envVars, error) {
// if we didn't get a split result here.
// See https://github.com/caddyserver/caddy/issues/3718
if pathInfo == "" {
- if remainder, ok := repl.GetString("http.matchers.file.remainder"); ok {
- pathInfo = remainder
- }
+ pathInfo, _ = repl.GetString("http.matchers.file.remainder")
}
// SCRIPT_FILENAME is the absolute path of SCRIPT_NAME
@@ -286,10 +284,7 @@ func (t Transport) buildEnv(r *http.Request) (envVars, error) {
reqHost = r.Host
}
- authUser := ""
- if val, ok := repl.Get("http.auth.user.id"); ok {
- authUser = val.(string)
- }
+ authUser, _ := repl.GetString("http.auth.user.id")
// Some variables are unused but cleared explicitly to prevent
// the parent environment from interfering.
diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go
index 9721007..fb71b1b 100644
--- a/modules/caddyhttp/server.go
+++ b/modules/caddyhttp/server.go
@@ -282,46 +282,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
// capture the original version of the request
accLog := s.accessLogger.With(loggableReq)
- defer func() {
- // this request may be flagged as omitted from the logs
- if skipLog, ok := GetVar(r.Context(), SkipLogVar).(bool); ok && skipLog {
- return
- }
-
- repl.Set("http.response.status", wrec.Status()) // will be 0 if no response is written by us (Go will write 200 to client)
- repl.Set("http.response.size", wrec.Size())
- repl.Set("http.response.duration", duration)
- repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
-
- logger := accLog
- if s.Logs != nil {
- logger = s.Logs.wrapLogger(logger, r.Host)
- }
-
- log := logger.Info
- if wrec.Status() >= 400 {
- log = logger.Error
- }
-
- userID, _ := repl.GetString("http.auth.user.id")
-
- reqBodyLength := 0
- if bodyReader != nil {
- reqBodyLength = bodyReader.Length
- }
-
- log("handled request",
- zap.Int("bytes_read", reqBodyLength),
- zap.String("user_id", userID),
- zap.Duration("duration", duration),
- zap.Int("size", wrec.Size()),
- zap.Int("status", wrec.Status()),
- zap.Object("resp_headers", LoggableHTTPHeader{
- Header: wrec.Header(),
- ShouldLogCredentials: shouldLogCredentials,
- }),
- )
- }()
+ defer s.logRequest(accLog, r, wrec, &duration, repl, bodyReader, shouldLogCredentials)
}
start := time.Now()
@@ -703,6 +664,57 @@ func (s *Server) shouldLogRequest(r *http.Request) bool {
return !s.Logs.SkipUnmappedHosts
}
+// logRequest logs the request to access logs, unless skipped.
+func (s *Server) logRequest(
+ accLog *zap.Logger, r *http.Request, wrec ResponseRecorder, duration *time.Duration,
+ repl *caddy.Replacer, bodyReader *lengthReader, shouldLogCredentials bool,
+) {
+ // this request may be flagged as omitted from the logs
+ if skipLog, ok := GetVar(r.Context(), SkipLogVar).(bool); ok && skipLog {
+ return
+ }
+
+ repl.Set("http.response.status", wrec.Status()) // will be 0 if no response is written by us (Go will write 200 to client)
+ repl.Set("http.response.size", wrec.Size())
+ repl.Set("http.response.duration", duration)
+ repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
+
+ logger := accLog
+ if s.Logs != nil {
+ logger = s.Logs.wrapLogger(logger, r.Host)
+ }
+
+ log := logger.Info
+ if wrec.Status() >= 400 {
+ log = logger.Error
+ }
+
+ userID, _ := repl.GetString("http.auth.user.id")
+
+ reqBodyLength := 0
+ if bodyReader != nil {
+ reqBodyLength = bodyReader.Length
+ }
+
+ extra := r.Context().Value(ExtraLogFieldsCtxKey).(*ExtraLogFields)
+
+ fieldCount := 6
+ fields := make([]zapcore.Field, 0, fieldCount+len(extra.fields))
+ fields = append(fields,
+ zap.Int("bytes_read", reqBodyLength),
+ zap.String("user_id", userID),
+ zap.Duration("duration", *duration),
+ zap.Int("size", wrec.Size()),
+ zap.Int("status", wrec.Status()),
+ zap.Object("resp_headers", LoggableHTTPHeader{
+ Header: wrec.Header(),
+ ShouldLogCredentials: shouldLogCredentials,
+ }))
+ fields = append(fields, extra.fields...)
+
+ log("handled request", fields...)
+}
+
// protocol returns true if the protocol proto is configured/enabled.
func (s *Server) protocol(proto string) bool {
for _, p := range s.Protocols {
@@ -738,6 +750,9 @@ func PrepareRequest(r *http.Request, repl *caddy.Replacer, w http.ResponseWriter
var url2 url.URL // avoid letting this escape to the heap
ctx = context.WithValue(ctx, OriginalRequestCtxKey, originalRequest(r, &url2))
+
+ ctx = context.WithValue(ctx, ExtraLogFieldsCtxKey, new(ExtraLogFields))
+
r = r.WithContext(ctx)
// once the pointer to the request won't change
diff --git a/modules/caddyhttp/server_test.go b/modules/caddyhttp/server_test.go
new file mode 100644
index 0000000..96a241b
--- /dev/null
+++ b/modules/caddyhttp/server_test.go
@@ -0,0 +1,146 @@
+package caddyhttp
+
+import (
+ "bytes"
+ "context"
+ "io"
+ "net/http"
+ "net/http/httptest"
+ "testing"
+ "time"
+
+ "github.com/stretchr/testify/assert"
+ "go.uber.org/zap"
+ "go.uber.org/zap/zapcore"
+)
+
+type writeFunc func(p []byte) (int, error)
+
+type nopSyncer writeFunc
+
+func (n nopSyncer) Write(p []byte) (int, error) {
+ return n(p)
+}
+
+func (n nopSyncer) Sync() error {
+ return nil
+}
+
+// testLogger returns a logger and a buffer to which the logger writes. The
+// buffer can be read for asserting log output.
+func testLogger(wf writeFunc) *zap.Logger {
+ ws := nopSyncer(wf)
+ encoderCfg := zapcore.EncoderConfig{
+ MessageKey: "msg",
+ LevelKey: "level",
+ NameKey: "logger",
+ EncodeLevel: zapcore.LowercaseLevelEncoder,
+ EncodeTime: zapcore.ISO8601TimeEncoder,
+ EncodeDuration: zapcore.StringDurationEncoder,
+ }
+ core := zapcore.NewCore(zapcore.NewJSONEncoder(encoderCfg), ws, zap.DebugLevel)
+
+ return zap.New(core)
+}
+
+func TestServer_LogRequest(t *testing.T) {
+ s := &Server{}
+
+ ctx := context.Background()
+ ctx = context.WithValue(ctx, ExtraLogFieldsCtxKey, new(ExtraLogFields))
+ req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx)
+ rec := httptest.NewRecorder()
+ wrec := NewResponseRecorder(rec, nil, nil)
+
+ duration := 50 * time.Millisecond
+ repl := NewTestReplacer(req)
+ bodyReader := &lengthReader{Source: req.Body}
+ shouldLogCredentials := false
+
+ buf := bytes.Buffer{}
+ accLog := testLogger(buf.Write)
+ s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, shouldLogCredentials)
+
+ assert.JSONEq(t, `{
+ "msg":"handled request", "level":"info", "bytes_read":0,
+ "duration":"50ms", "resp_headers": {}, "size":0,
+ "status":0, "user_id":""
+ }`, buf.String())
+}
+
+func TestServer_LogRequest_WithTraceID(t *testing.T) {
+ s := &Server{}
+
+ extra := new(ExtraLogFields)
+ ctx := context.WithValue(context.Background(), ExtraLogFieldsCtxKey, extra)
+ extra.Add(zap.String("traceID", "1234567890abcdef"))
+
+ req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx)
+ rec := httptest.NewRecorder()
+ wrec := NewResponseRecorder(rec, nil, nil)
+
+ duration := 50 * time.Millisecond
+ repl := NewTestReplacer(req)
+ bodyReader := &lengthReader{Source: req.Body}
+ shouldLogCredentials := false
+
+ buf := bytes.Buffer{}
+ accLog := testLogger(buf.Write)
+ s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, shouldLogCredentials)
+
+ assert.JSONEq(t, `{
+ "msg":"handled request", "level":"info", "bytes_read":0,
+ "duration":"50ms", "resp_headers": {}, "size":0,
+ "status":0, "user_id":"",
+ "traceID":"1234567890abcdef"
+ }`, buf.String())
+}
+
+func BenchmarkServer_LogRequest(b *testing.B) {
+ s := &Server{}
+
+ extra := new(ExtraLogFields)
+ ctx := context.WithValue(context.Background(), ExtraLogFieldsCtxKey, extra)
+
+ req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx)
+ rec := httptest.NewRecorder()
+ wrec := NewResponseRecorder(rec, nil, nil)
+
+ duration := 50 * time.Millisecond
+ repl := NewTestReplacer(req)
+ bodyReader := &lengthReader{Source: req.Body}
+
+ buf := io.Discard
+ accLog := testLogger(buf.Write)
+
+ b.ResetTimer()
+
+ for i := 0; i < b.N; i++ {
+ s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false)
+ }
+}
+
+func BenchmarkServer_LogRequest_WithTraceID(b *testing.B) {
+ s := &Server{}
+
+ extra := new(ExtraLogFields)
+ ctx := context.WithValue(context.Background(), ExtraLogFieldsCtxKey, extra)
+ extra.Add(zap.String("traceID", "1234567890abcdef"))
+
+ req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx)
+ rec := httptest.NewRecorder()
+ wrec := NewResponseRecorder(rec, nil, nil)
+
+ duration := 50 * time.Millisecond
+ repl := NewTestReplacer(req)
+ bodyReader := &lengthReader{Source: req.Body}
+
+ buf := io.Discard
+ accLog := testLogger(buf.Write)
+
+ b.ResetTimer()
+
+ for i := 0; i < b.N; i++ {
+ s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false)
+ }
+}
diff --git a/modules/caddyhttp/tracing/tracer.go b/modules/caddyhttp/tracing/tracer.go
index cb72743..c6dd7aa 100644
--- a/modules/caddyhttp/tracing/tracer.go
+++ b/modules/caddyhttp/tracing/tracer.go
@@ -14,6 +14,7 @@ import (
"go.opentelemetry.io/otel/sdk/resource"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
semconv "go.opentelemetry.io/otel/semconv/v1.17.0"
+ "go.opentelemetry.io/otel/trace"
"go.uber.org/zap"
)
@@ -81,8 +82,15 @@ func newOpenTelemetryWrapper(
// serveHTTP injects a tracing context and call the next handler.
func (ot *openTelemetryWrapper) serveHTTP(w http.ResponseWriter, r *http.Request) {
- ot.propagators.Inject(r.Context(), propagation.HeaderCarrier(r.Header))
- next := r.Context().Value(nextCallCtxKey).(*nextCall)
+ ctx := r.Context()
+ ot.propagators.Inject(ctx, propagation.HeaderCarrier(r.Header))
+ spanCtx := trace.SpanContextFromContext(ctx)
+ if spanCtx.IsValid() {
+ if extra, ok := ctx.Value(caddyhttp.ExtraLogFieldsCtxKey).(*caddyhttp.ExtraLogFields); ok {
+ extra.Add(zap.String("traceID", spanCtx.TraceID().String()))
+ }
+ }
+ next := ctx.Value(nextCallCtxKey).(*nextCall)
next.err = next.next.ServeHTTP(w, r)
}
generated by cgit v1.2.3 (git 2.25.1) at 2024-12-25 17:38:29 +0000