caddy/modules/caddyhttp/server_test.go
Dave Henderson f0e3981774
logging: Add traceID field to access logs when tracing is active (#5507)
Co-authored-by: Francis Lavoie <lavofr@gmail.com>
2023-04-27 02:46:41 +00:00

146 lines
3.8 KiB
Go

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)
}
}