diff options
Diffstat (limited to 'modules/caddyhttp/server.go')
-rw-r--r-- | modules/caddyhttp/server.go | 207 |
1 files changed, 168 insertions, 39 deletions
diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go index 366a307..2c0c44e 100644 --- a/modules/caddyhttp/server.go +++ b/modules/caddyhttp/server.go @@ -17,16 +17,18 @@ package caddyhttp import ( "context" "fmt" - "log" "net" "net/http" "net/url" "strconv" "strings" + "time" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddytls" "github.com/lucas-clemente/quic-go/http3" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) // Server is an HTTP server. @@ -43,11 +45,15 @@ type Server struct { AutoHTTPS *AutoHTTPSConfig `json:"automatic_https,omitempty"` MaxRehandles *int `json:"max_rehandles,omitempty"` StrictSNIHost *bool `json:"strict_sni_host,omitempty"` + Logs *ServerLogConfig `json:"logs,omitempty"` // This field is not subject to compatibility promises ExperimentalHTTP3 bool `json:"experimental_http3,omitempty"` - tlsApp *caddytls.TLS + tlsApp *caddytls.TLS + logger *zap.Logger + accessLogger *zap.Logger + errorLogger *zap.Logger h3server *http3.Server } @@ -59,58 +65,106 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { if s.h3server != nil { err := s.h3server.SetQuicHeaders(w.Header()) if err != nil { - log.Printf("[ERROR] Setting HTTP/3 Alt-Svc header: %v", err) + s.logger.Error("setting HTTP/3 Alt-Svc header", zap.Error(err)) } } - if s.tlsApp.HandleHTTPChallenge(w, r) { - return - } - // set up the context for the request repl := caddy.NewReplacer() ctx := context.WithValue(r.Context(), caddy.ReplacerCtxKey, repl) ctx = context.WithValue(ctx, ServerCtxKey, s) - ctx = context.WithValue(ctx, VarCtxKey, make(map[string]interface{})) - ctx = context.WithValue(ctx, OriginalURLCtxKey, cloneURL(r.URL)) + ctx = context.WithValue(ctx, VarsCtxKey, make(map[string]interface{})) + var url2 url.URL // avoid letting this escape to the heap + ctx = context.WithValue(ctx, OriginalRequestCtxKey, originalRequest(r, &url2)) r = r.WithContext(ctx) // once the pointer to the request won't change // anymore, finish setting up the replacer addHTTPVarsToReplacer(repl, r, w) - // build and execute the main handler chain + loggableReq := LoggableHTTPRequest{r} + errLog := s.errorLogger.With( + // encode the request for logging purposes before + // it enters any handler chain; this is necessary + // to capture the original request in case it gets + // modified during handling + zap.Object("request", loggableReq), + ) + + if s.Logs != nil { + wrec := NewResponseRecorder(w, nil, nil) + w = wrec + accLog := s.accessLogger.With( + // capture the original version of the request + zap.Object("request", loggableReq), + ) + start := time.Now() + defer func() { + latency := time.Since(start) + + repl.Set("http.response.status", strconv.Itoa(wrec.Status())) + repl.Set("http.response.size", strconv.Itoa(wrec.Size())) + repl.Set("http.response.latency", latency.String()) + + logger := accLog + if s.Logs.LoggerNames != nil { + logger = logger.Named(s.Logs.LoggerNames[r.Host]) + } + + log := logger.Info + if wrec.Status() >= 400 { + log = logger.Error + } + + log("request", + zap.String("common_log", repl.ReplaceAll(CommonLogFormat, "-")), + zap.Duration("latency", latency), + zap.Int("size", wrec.Size()), + zap.Int("status", wrec.Status()), + ) + }() + } + + // guarantee ACME HTTP challenges; handle them + // separately from any user-defined handlers + if s.tlsApp.HandleHTTPChallenge(w, r) { + return + } + + // build and execute the primary handler chain err := s.executeCompositeRoute(w, r, s.Routes) if err != nil { - // add the raw error value to the request context - // so it can be accessed by error handlers - c := context.WithValue(r.Context(), ErrorCtxKey, err) - r = r.WithContext(c) - - // add error values to the replacer - repl.Set("http.error", err.Error()) - if handlerErr, ok := err.(HandlerError); ok { - repl.Set("http.error.status_code", strconv.Itoa(handlerErr.StatusCode)) - repl.Set("http.error.status_text", http.StatusText(handlerErr.StatusCode)) - repl.Set("http.error.message", handlerErr.Message) - repl.Set("http.error.trace", handlerErr.Trace) - repl.Set("http.error.id", handlerErr.ID) + // prepare the error log + logger := errLog + if s.Logs.LoggerNames != nil { + logger = logger.Named(s.Logs.LoggerNames[r.Host]) } + // get the values that will be used to log the error + errStatus, errMsg, errFields := errLogValues(err) + + // add HTTP error information to request context + r = s.Errors.WithError(r, err) + if s.Errors != nil && len(s.Errors.Routes) > 0 { - err := s.executeCompositeRoute(w, r, s.Errors.Routes) - if err != nil { - // TODO: what should we do if the error handler has an error? - log.Printf("[ERROR] [%s %s] handling error: %v", r.Method, r.RequestURI, err) - } - } else { - // TODO: polish the default error handling - log.Printf("[ERROR] [%s %s] %v", r.Method, r.RequestURI, err) - if handlerErr, ok := err.(HandlerError); ok { - w.WriteHeader(handlerErr.StatusCode) + // execute user-defined error handling route + err2 := s.executeCompositeRoute(w, r, s.Errors.Routes) + if err2 == nil { + // user's error route handled the error response + // successfully, so now just log the error + logger.Error(errMsg, errFields...) } else { - w.WriteHeader(http.StatusInternalServerError) + // well... this is awkward + errFields = append([]zapcore.Field{ + zap.String("error", err2.Error()), + zap.Namespace("first_error"), + zap.String("msg", errMsg), + }, errFields...) + logger.Error("error handling handler error", errFields...) } + } else { + logger.Error(errMsg, errFields...) + w.WriteHeader(errStatus) } } } @@ -278,26 +332,101 @@ type HTTPErrorConfig struct { Routes RouteList `json:"routes,omitempty"` } +// WithError makes a shallow copy of r to add the error to its +// context, and sets placeholders on the request's replacer +// related to err. It returns the modified request which has +// the error information in its context and replacer. It +// overwrites any existing error values that are stored. +func (*HTTPErrorConfig) WithError(r *http.Request, err error) *http.Request { + // add the raw error value to the request context + // so it can be accessed by error handlers + c := context.WithValue(r.Context(), ErrorCtxKey, err) + r = r.WithContext(c) + + // add error values to the replacer + repl := r.Context().Value(caddy.ReplacerCtxKey).(caddy.Replacer) + repl.Set("http.error", err.Error()) + if handlerErr, ok := err.(HandlerError); ok { + repl.Set("http.error.status_code", strconv.Itoa(handlerErr.StatusCode)) + repl.Set("http.error.status_text", http.StatusText(handlerErr.StatusCode)) + repl.Set("http.error.message", handlerErr.Message) + repl.Set("http.error.trace", handlerErr.Trace) + repl.Set("http.error.id", handlerErr.ID) + } + + return r +} + +// ServerLogConfig describes a server's logging configuration. +type ServerLogConfig struct { + LoggerNames map[string]string `json:"logger_names,omitempty"` +} + +// errLogValues inspects err and returns the status code +// to use, the error log message, and any extra fields. +// If err is a HandlerError, the returned values will +// have richer information. +func errLogValues(err error) (status int, msg string, fields []zapcore.Field) { + if handlerErr, ok := err.(HandlerError); ok { + status = handlerErr.StatusCode + msg = handlerErr.Err.Error() + fields = []zapcore.Field{ + zap.Int("status", handlerErr.StatusCode), + zap.String("err_id", handlerErr.ID), + zap.String("err_trace", handlerErr.Trace), + } + return + } + status = http.StatusInternalServerError + msg = err.Error() + return +} + +// originalRequest returns a partial, shallow copy of +// req, including: req.Method, deep copy of req.URL +// (into the urlCopy parameter, which should be on the +// stack), and req.RequestURI. Notably, headers are not +// copied. This function is designed to be very fast +// and efficient, and useful primarly for read-only +// logging purposes. +func originalRequest(req *http.Request, urlCopy *url.URL) http.Request { + urlCopy = cloneURL(req.URL) + return http.Request{ + Method: req.Method, + RequestURI: req.RequestURI, + URL: urlCopy, + } +} + // cloneURL makes a copy of r.URL and returns a // new value that doesn't reference the original. -func cloneURL(u *url.URL) url.URL { +func cloneURL(u *url.URL) *url.URL { urlCopy := *u if u.User != nil { userInfo := new(url.Userinfo) *userInfo = *u.User urlCopy.User = userInfo } - return urlCopy + return &urlCopy } +const ( + // CommonLogFormat is the common log format. https://en.wikipedia.org/wiki/Common_Log_Format + CommonLogFormat = `{http.request.remote.host} ` + CommonLogEmptyValue + ` {http.handlers.authentication.user.id} [{time.now.common_log}] "{http.request.orig_method} {http.request.orig_uri} {http.request.proto}" {http.response.status} {http.response.size}` + + // CommonLogEmptyValue is the common empty log value. + CommonLogEmptyValue = "-" +) + // Context keys for HTTP request context values. const ( // For referencing the server instance ServerCtxKey caddy.CtxKey = "server" // For the request's variable table - VarCtxKey caddy.CtxKey = "vars" + VarsCtxKey caddy.CtxKey = "vars" - // For the unmodified URL that originally came in with a request - OriginalURLCtxKey caddy.CtxKey = "original_url" + // For a partial copy of the unmodified request that + // originally came into the server's entry handler + OriginalRequestCtxKey caddy.CtxKey = "original_request" ) |