From b00dfd3965f400956c5bb5b388e9d54ef98052e5 Mon Sep 17 00:00:00 2001 From: Matt Holt Date: Mon, 28 Oct 2019 14:39:37 -0600 Subject: v2: Logging! (#2831) * logging: Initial implementation * logging: More encoder formats, better defaults * logging: Fix repetition bug with FilterEncoder; add more presets * logging: DiscardWriter; delete or no-op logs that discard their output * logging: Add http.handlers.log module; enhance Replacer methods The Replacer interface has new methods to customize how to handle empty or unrecognized placeholders. Closes #2815. * logging: Overhaul HTTP logging, fix bugs, improve filtering, etc. * logging: General cleanup, begin transitioning to using new loggers * Fixes after merge conflict --- modules/caddyhttp/caddyhttp.go | 72 +++++--- modules/caddyhttp/fileserver/staticfiles.go | 19 ++ modules/caddyhttp/marshalers.go | 89 ++++++++++ modules/caddyhttp/replacer.go | 32 ++-- modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go | 9 +- modules/caddyhttp/reverseproxy/reverseproxy.go | 9 + modules/caddyhttp/rewrite/rewrite.go | 40 +++-- modules/caddyhttp/server.go | 207 ++++++++++++++++++---- modules/caddyhttp/staticresp.go | 2 +- modules/caddyhttp/subroute.go | 25 ++- modules/caddyhttp/vars.go | 4 +- 11 files changed, 412 insertions(+), 96 deletions(-) create mode 100644 modules/caddyhttp/marshalers.go (limited to 'modules/caddyhttp') diff --git a/modules/caddyhttp/caddyhttp.go b/modules/caddyhttp/caddyhttp.go index 29a5ab0..aae65ab 100644 --- a/modules/caddyhttp/caddyhttp.go +++ b/modules/caddyhttp/caddyhttp.go @@ -21,7 +21,6 @@ import ( "encoding/json" "fmt" "io" - "log" weakrand "math/rand" "net" "net/http" @@ -33,6 +32,7 @@ import ( "github.com/caddyserver/caddy/v2/modules/caddytls" "github.com/lucas-clemente/quic-go/http3" "github.com/mholt/certmagic" + "go.uber.org/zap" ) func init() { @@ -40,7 +40,7 @@ func init() { err := caddy.RegisterModule(App{}) if err != nil { - log.Fatal(err) + caddy.Log().Fatal(err.Error()) } } @@ -55,7 +55,8 @@ type App struct { h3servers []*http3.Server h3listeners []net.PacketConn - ctx caddy.Context + ctx caddy.Context + logger *zap.Logger } // CaddyModule returns the Caddy module information. @@ -69,10 +70,15 @@ func (App) CaddyModule() caddy.ModuleInfo { // Provision sets up the app. func (app *App) Provision(ctx caddy.Context) error { app.ctx = ctx + app.logger = ctx.Logger(app) repl := caddy.NewReplacer() - for _, srv := range app.Servers { + for srvName, srv := range app.Servers { + srv.logger = app.logger.Named("log") + srv.accessLogger = app.logger.Named("log.access") + srv.errorLogger = app.logger.Named("log.error") + if srv.AutoHTTPS == nil { // avoid nil pointer dereferences srv.AutoHTTPS = new(AutoHTTPSConfig) @@ -93,20 +99,25 @@ func (app *App) Provision(ctx caddy.Context) error { } for i := range srv.Listen { - srv.Listen[i] = repl.ReplaceAll(srv.Listen[i], "") + lnOut, err := repl.ReplaceOrErr(srv.Listen[i], true, true) + if err != nil { + return fmt.Errorf("server %s, listener %d: %v", + srvName, i, err) + } + srv.Listen[i] = lnOut } if srv.Routes != nil { err := srv.Routes.Provision(ctx) if err != nil { - return fmt.Errorf("setting up server routes: %v", err) + return fmt.Errorf("server %s: setting up server routes: %v", srvName, err) } } if srv.Errors != nil { err := srv.Errors.Routes.Provision(ctx) if err != nil { - return fmt.Errorf("setting up server error handling routes: %v", err) + return fmt.Errorf("server %s: setting up server error handling routes: %v", srvName, err) } } @@ -194,7 +205,9 @@ func (app *App) Start() error { ///////// // TODO: HTTP/3 support is experimental for now if srv.ExperimentalHTTP3 { - log.Printf("[INFO] Enabling experimental HTTP/3 listener on %s", addr) + app.logger.Info("enabling experimental HTTP/3 listener", + zap.String("addr", addr), + ) h3ln, err := caddy.ListenPacket("udp", addr) if err != nil { return fmt.Errorf("getting HTTP/3 UDP listener: %v", err) @@ -284,19 +297,25 @@ func (app *App) automaticHTTPS() error { // skip if all listeners use the HTTP port if !srv.listenersUseAnyPortOtherThan(app.httpPort()) { - log.Printf("[INFO] Server %s is only listening on the HTTP port %d, so no automatic HTTPS will be applied to this server", - srvName, app.httpPort()) + app.logger.Info("server is only listening on the HTTP port, so no automatic HTTPS will be applied to this server", + zap.String("server_name", srvName), + zap.Int("http_port", app.httpPort()), + ) continue } // find all qualifying domain names, de-duplicated domainSet := make(map[string]struct{}) - for _, route := range srv.Routes { - for _, matcherSet := range route.MatcherSets { - for _, m := range matcherSet { + for routeIdx, route := range srv.Routes { + for matcherSetIdx, matcherSet := range route.MatcherSets { + for matcherIdx, m := range matcherSet { if hm, ok := m.(*MatchHost); ok { - for _, d := range *hm { - d = repl.ReplaceAll(d, "") + for hostMatcherIdx, d := range *hm { + d, err = repl.ReplaceOrErr(d, true, false) + if err != nil { + return fmt.Errorf("%s: route %d, matcher set %d, matcher %d, host matcher %d: %v", + srvName, routeIdx, matcherSetIdx, matcherIdx, hostMatcherIdx, err) + } if certmagic.HostQualifies(d) && !srv.AutoHTTPS.Skipped(d, srv.AutoHTTPS.Skip) { domainSet[d] = struct{}{} @@ -318,7 +337,10 @@ func (app *App) automaticHTTPS() error { // supposed to ignore loaded certificates if !srv.AutoHTTPS.IgnoreLoadedCerts && len(tlsApp.AllMatchingCertificates(d)) > 0 { - log.Printf("[INFO][%s] Skipping automatic certificate management because one or more matching certificates are already loaded", d) + app.logger.Info("skipping automatic certificate management because one or more matching certificates are already loaded", + zap.String("domain", d), + zap.String("server_name", srvName), + ) continue } domainsForCerts = append(domainsForCerts, d) @@ -351,7 +373,9 @@ func (app *App) automaticHTTPS() error { }) // manage their certificates - log.Printf("[INFO] Enabling automatic TLS certificate management for %v", domainsForCerts) + app.logger.Info("enabling automatic TLS certificate management", + zap.Strings("domains", domainsForCerts), + ) err := tlsApp.Manage(domainsForCerts) if err != nil { return fmt.Errorf("%s: managing certificate for %s: %s", srvName, domains, err) @@ -368,7 +392,9 @@ func (app *App) automaticHTTPS() error { continue } - log.Printf("[INFO] Enabling automatic HTTP->HTTPS redirects for %v", domains) + app.logger.Info("enabling automatic HTTP->HTTPS redirects", + zap.Strings("domains", domains), + ) // create HTTP->HTTPS redirects for _, addr := range srv.Listen { @@ -434,8 +460,10 @@ func (app *App) automaticHTTPS() error { // that the redirect runs from; simply append our // redirect route to the existing routes, with a // caveat that their config might override ours - log.Printf("[WARNING] Server %s is listening on %s, so automatic HTTP->HTTPS redirects might be overridden by your own configuration", - srvName, addr) + app.logger.Warn("server is listening on same interface as redirects, so automatic HTTP->HTTPS redirects might be overridden by your own configuration", + zap.String("server_name", srvName), + zap.String("interface", addr), + ) srv.Routes = append(srv.Routes, redirRoute) continue redirRoutesLoop } @@ -524,8 +552,8 @@ var emptyHandler HandlerFunc = func(http.ResponseWriter, *http.Request) error { // WeakString is a type that unmarshals any JSON value // as a string literal, with the following exceptions: -// 1) actual string values are decoded as strings, and -// 2) null is decoded as empty string +// 1) actual string values are decoded as strings; and +// 2) null is decoded as empty string; // and provides methods for getting the value as various // primitive types. However, using this type removes any // type safety as far as deserializing JSON is concerned. diff --git a/modules/caddyhttp/fileserver/staticfiles.go b/modules/caddyhttp/fileserver/staticfiles.go index 3e4cccc..26c0efe 100644 --- a/modules/caddyhttp/fileserver/staticfiles.go +++ b/modules/caddyhttp/fileserver/staticfiles.go @@ -18,6 +18,7 @@ import ( "bytes" "fmt" "html/template" + "io" weakrand "math/rand" "mime" "net/http" @@ -191,6 +192,24 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, _ cadd } } + // if this handler exists in an error context (i.e. is + // part of a handler chain that is supposed to handle + // a previous error), we have to serve the content + // manually in order to write the correct status code + if reqErr, ok := r.Context().Value(caddyhttp.ErrorCtxKey).(error); ok { + statusCode := http.StatusInternalServerError + if handlerErr, ok := reqErr.(caddyhttp.HandlerError); ok { + if handlerErr.StatusCode > 0 { + statusCode = handlerErr.StatusCode + } + } + w.WriteHeader(statusCode) + if r.Method != "HEAD" { + io.Copy(w, file) + } + return nil + } + // let the standard library do what it does best; note, however, // that errors generated by ServeContent are written immediately // to the response, so we cannot handle them (but errors there diff --git a/modules/caddyhttp/marshalers.go b/modules/caddyhttp/marshalers.go new file mode 100644 index 0000000..a672132 --- /dev/null +++ b/modules/caddyhttp/marshalers.go @@ -0,0 +1,89 @@ +// Copyright 2015 Matthew Holt and The Caddy Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package caddyhttp + +import ( + "crypto/tls" + "net/http" + + "go.uber.org/zap/zapcore" +) + +// LoggableHTTPRequest makes an HTTP request loggable with zap.Object(). +type LoggableHTTPRequest struct{ *http.Request } + +// MarshalLogObject satisfies the zapcore.ObjectMarshaler interface. +func (r LoggableHTTPRequest) MarshalLogObject(enc zapcore.ObjectEncoder) error { + enc.AddString("method", r.Method) + enc.AddString("uri", r.RequestURI) + enc.AddString("proto", r.Proto) + enc.AddString("remote_addr", r.RemoteAddr) + enc.AddString("host", r.Host) + enc.AddObject("headers", LoggableHTTPHeader(r.Header)) + if r.TLS != nil { + enc.AddObject("tls", LoggableTLSConnState(*r.TLS)) + } + return nil +} + +// LoggableHTTPHeader makes an HTTP header loggable with zap.Object(). +type LoggableHTTPHeader http.Header + +// MarshalLogObject satisfies the zapcore.ObjectMarshaler interface. +func (h LoggableHTTPHeader) MarshalLogObject(enc zapcore.ObjectEncoder) error { + if h == nil { + return nil + } + for key, val := range h { + enc.AddArray(key, LoggableStringArray(val)) + } + return nil +} + +// LoggableStringArray makes a slice of strings marshalable for logging. +type LoggableStringArray []string + +// MarshalLogArray satisfies the zapcore.ArrayMarshaler interface. +func (sa LoggableStringArray) MarshalLogArray(enc zapcore.ArrayEncoder) error { + if sa == nil { + return nil + } + for _, s := range sa { + enc.AppendString(s) + } + return nil +} + +// LoggableTLSConnState makes a TLS connection state loggable with zap.Object(). +type LoggableTLSConnState tls.ConnectionState + +// MarshalLogObject satisfies the zapcore.ObjectMarshaler interface. +func (t LoggableTLSConnState) MarshalLogObject(enc zapcore.ObjectEncoder) error { + enc.AddBool("resumed", t.DidResume) + enc.AddUint16("version", t.Version) + enc.AddUint16("resumed", t.CipherSuite) + enc.AddString("proto", t.NegotiatedProtocol) + enc.AddBool("proto_mutual", t.NegotiatedProtocolIsMutual) + enc.AddString("server_name", t.ServerName) + return nil +} + +// Interface guards +var ( + _ zapcore.ObjectMarshaler = (*LoggableHTTPRequest)(nil) + _ zapcore.ObjectMarshaler = (*LoggableHTTPHeader)(nil) + _ zapcore.ArrayMarshaler = (*LoggableStringArray)(nil) + _ zapcore.ObjectMarshaler = (*LoggableTLSConnState)(nil) +) diff --git a/modules/caddyhttp/replacer.go b/modules/caddyhttp/replacer.go index db329be..ddbc250 100644 --- a/modules/caddyhttp/replacer.go +++ b/modules/caddyhttp/replacer.go @@ -19,7 +19,6 @@ import ( "net" "net/http" "net/textproto" - "net/url" "path" "strconv" "strings" @@ -112,27 +111,30 @@ func addHTTPVarsToReplacer(repl caddy.Replacer, req *http.Request, w http.Respon } return qs, true - // original URI, before any internal changes + // original request, before any internal changes + case "http.request.orig_method": + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + return or.Method, true case "http.request.orig_uri": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - return u.RequestURI(), true + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + return or.RequestURI, true case "http.request.orig_uri.path": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - return u.Path, true + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + return or.URL.Path, true case "http.request.orig_uri.path.file": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - _, file := path.Split(u.Path) + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + _, file := path.Split(or.URL.Path) return file, true case "http.request.orig_uri.path.dir": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - dir, _ := path.Split(u.Path) + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + dir, _ := path.Split(or.URL.Path) return dir, true case "http.request.orig_uri.query": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - return u.RawQuery, true + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + return or.URL.RawQuery, true case "http.request.orig_uri.query_string": - u, _ := req.Context().Value(OriginalURLCtxKey).(url.URL) - qs := u.Query().Encode() + or, _ := req.Context().Value(OriginalRequestCtxKey).(http.Request) + qs := or.URL.Query().Encode() if qs != "" { qs = "?" + qs } @@ -183,7 +185,7 @@ func addHTTPVarsToReplacer(repl caddy.Replacer, req *http.Request, w http.Respon // middleware variables if strings.HasPrefix(key, varsReplPrefix) { varName := key[len(varsReplPrefix):] - tbl := req.Context().Value(VarCtxKey).(map[string]interface{}) + tbl := req.Context().Value(VarsCtxKey).(map[string]interface{}) raw, ok := tbl[varName] if !ok { // variables can be dynamic, so always return true diff --git a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go index eaf1f86..21aeb17 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go @@ -19,7 +19,6 @@ import ( "crypto/tls" "fmt" "net/http" - "net/url" "path" "path/filepath" "strconv" @@ -53,6 +52,9 @@ type Transport struct { // with the value of SplitPath. The first piece will be assumed as the // actual resource (CGI script) name, and the second piece will be set to // PATH_INFO for the CGI script to use. + // Future enhancements should be careful to avoid CVE-2019-11043, + // which can be mitigated with use of a try_files-like behavior + // that 404's if the fastcgi path info is not found. SplitPath string `json:"split_path,omitempty"` // Extra environment variables @@ -191,12 +193,13 @@ func (t Transport) buildEnv(r *http.Request) (map[string]string, error) { // original URI in as the value of REQUEST_URI (the user can overwrite this // if desired). Most PHP apps seem to want the original URI. Besides, this is // how nginx defaults: http://stackoverflow.com/a/12485156/1048862 - reqURL, ok := r.Context().Value(caddyhttp.OriginalURLCtxKey).(url.URL) + origReq, ok := r.Context().Value(caddyhttp.OriginalRequestCtxKey).(http.Request) if !ok { // some requests, like active health checks, don't add this to // the request context, so we can just use the current URL - reqURL = *r.URL + origReq = *r } + reqURL := origReq.URL requestScheme := "http" if r.TLS != nil { diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go index 566c9c4..c2fb751 100644 --- a/modules/caddyhttp/reverseproxy/reverseproxy.go +++ b/modules/caddyhttp/reverseproxy/reverseproxy.go @@ -441,6 +441,15 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di Dia } } + // TODO: there should be an option to return an error if the response + // matches some criteria; would solve https://github.com/caddyserver/caddy/issues/1447 + // by allowing the backend to determine whether this server should treat + // a 400+ status code as an error -- but we might need to be careful that + // we do not affect the health status of the backend... still looking into + // that; if we need to avoid that, we should return a particular error type + // that the caller of this function checks for and only applies health + // status changes if the error is not this special type + rw.WriteHeader(res.StatusCode) err = h.copyResponse(rw, res.Body, h.flushInterval(req, res)) diff --git a/modules/caddyhttp/rewrite/rewrite.go b/modules/caddyhttp/rewrite/rewrite.go index 7d4c6f7..5a84a33 100644 --- a/modules/caddyhttp/rewrite/rewrite.go +++ b/modules/caddyhttp/rewrite/rewrite.go @@ -23,6 +23,7 @@ import ( "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" + "go.uber.org/zap" ) func init() { @@ -39,6 +40,8 @@ type Rewrite struct { HTTPRedirect caddyhttp.WeakString `json:"http_redirect,omitempty"` Rehandle bool `json:"rehandle,omitempty"` + + logger *zap.Logger } // CaddyModule returns the Caddy module information. @@ -49,6 +52,12 @@ func (Rewrite) CaddyModule() caddy.ModuleInfo { } } +// Provision sets up rewr. +func (rewr *Rewrite) Provision(ctx caddy.Context) error { + rewr.logger = ctx.Logger(rewr) + return nil +} + // Validate ensures rewr's configuration is valid. func (rewr Rewrite) Validate() error { if rewr.HTTPRedirect != "" && rewr.Rehandle { @@ -61,6 +70,10 @@ func (rewr Rewrite) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddy repl := r.Context().Value(caddy.ReplacerCtxKey).(caddy.Replacer) var changed bool + logger := rewr.logger.With( + zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: r}), + ) + // rewrite the method if rewr.Method != "" { method := r.Method @@ -114,18 +127,23 @@ func (rewr Rewrite) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddy r.RequestURI = newURI } - if changed && rewr.Rehandle { - return caddyhttp.ErrRehandle - } - - if changed && rewr.HTTPRedirect != "" { - statusCode, err := strconv.Atoi(repl.ReplaceAll(rewr.HTTPRedirect.String(), "")) - if err != nil { - return caddyhttp.Error(http.StatusInternalServerError, err) + if changed { + logger.Debug("rewrote request", + zap.String("method", r.Method), + zap.String("uri", r.RequestURI), + ) + if rewr.Rehandle { + return caddyhttp.ErrRehandle + } + if rewr.HTTPRedirect != "" { + statusCode, err := strconv.Atoi(repl.ReplaceAll(rewr.HTTPRedirect.String(), "")) + if err != nil { + return caddyhttp.Error(http.StatusInternalServerError, err) + } + w.Header().Set("Location", r.RequestURI) + w.WriteHeader(statusCode) + return nil } - w.Header().Set("Location", r.RequestURI) - w.WriteHeader(statusCode) - return nil } return next.ServeHTTP(w, r) 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" ) diff --git a/modules/caddyhttp/staticresp.go b/modules/caddyhttp/staticresp.go index a435f87..732a3fb 100644 --- a/modules/caddyhttp/staticresp.go +++ b/modules/caddyhttp/staticresp.go @@ -112,7 +112,7 @@ func (s StaticResponse) ServeHTTP(w http.ResponseWriter, r *http.Request, _ Hand // write response body if s.Body != "" { - fmt.Fprint(w, repl.ReplaceAll(s.Body, "")) + fmt.Fprint(w, repl.ReplaceKnown(s.Body, "")) } return nil diff --git a/modules/caddyhttp/subroute.go b/modules/caddyhttp/subroute.go index 3b0d718..57fb80a 100644 --- a/modules/caddyhttp/subroute.go +++ b/modules/caddyhttp/subroute.go @@ -30,8 +30,15 @@ func init() { // matchers, or for routes with matchers that must be have deferred // evaluation (e.g. if they depend on placeholders created by other // matchers that need to be evaluated first). +// +// You can also use subroutes to handle errors from specific handlers. +// First the primary Routes will be executed, and if they return an +// error, the Errors routes will be executed; in that case, an error +// is only returned to the entry point at the server if there is an +// additional error returned from the errors routes. type Subroute struct { - Routes RouteList `json:"routes,omitempty"` + Routes RouteList `json:"routes,omitempty"` + Errors *HTTPErrorConfig `json:"errors,omitempty"` } // CaddyModule returns the Caddy module information. @@ -47,7 +54,13 @@ func (sr *Subroute) Provision(ctx caddy.Context) error { if sr.Routes != nil { err := sr.Routes.Provision(ctx) if err != nil { - return fmt.Errorf("setting up routes: %v", err) + return fmt.Errorf("setting up subroutes: %v", err) + } + if sr.Errors != nil { + err := sr.Errors.Routes.Provision(ctx) + if err != nil { + return fmt.Errorf("setting up error subroutes: %v", err) + } } } return nil @@ -55,7 +68,13 @@ func (sr *Subroute) Provision(ctx caddy.Context) error { func (sr *Subroute) ServeHTTP(w http.ResponseWriter, r *http.Request, _ Handler) error { subroute := sr.Routes.BuildCompositeRoute(r) - return subroute.ServeHTTP(w, r) + err := subroute.ServeHTTP(w, r) + if err != nil && sr.Errors != nil { + r = sr.Errors.WithError(r, err) + errRoute := sr.Errors.Routes.BuildCompositeRoute(r) + return errRoute.ServeHTTP(w, r) + } + return err } // Interface guards diff --git a/modules/caddyhttp/vars.go b/modules/caddyhttp/vars.go index bbd4568..3fb8fa3 100644 --- a/modules/caddyhttp/vars.go +++ b/modules/caddyhttp/vars.go @@ -38,7 +38,7 @@ func (VarsMiddleware) CaddyModule() caddy.ModuleInfo { } func (t VarsMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request, next Handler) error { - vars := r.Context().Value(VarCtxKey).(map[string]interface{}) + vars := r.Context().Value(VarsCtxKey).(map[string]interface{}) repl := r.Context().Value(caddy.ReplacerCtxKey).(caddy.Replacer) for k, v := range t { keyExpanded := repl.ReplaceAll(k, "") @@ -62,7 +62,7 @@ func (VarsMatcher) CaddyModule() caddy.ModuleInfo { // Match matches a request based on variables in the context. func (m VarsMatcher) Match(r *http.Request) bool { - vars := r.Context().Value(VarCtxKey).(map[string]string) + vars := r.Context().Value(VarsCtxKey).(map[string]string) repl := r.Context().Value(caddy.ReplacerCtxKey).(caddy.Replacer) for k, v := range m { keyExpanded := repl.ReplaceAll(k, "") -- cgit v1.2.3