Http response recording/logging + Environment variables based config

.golangci.yml

@@ -52,6 +52,7 @@ linters-settings:
         allow:
           - $gostd
           - fortio.org/log
+          - fortio.org/struct2env
   lll:
     # max line length, lines longer will be reported. Default is 120.
     # '\t' is counted as 1 character by default, and can be changed with the tab-width option

README.md

@@ -74,3 +74,29 @@ When on console:
 JSON formatted logs can also be converted back to text later/after capture and similarly colorized using [fortio.org/logc](https://github.com/fortio/logc#logc)
 
 The `log.Colors` can be used by callers and they'll be empty string when not in color mode, and the ansi escape codes otherwise.
+
+# HTTP request/response logging
+
+`LogAndCall()` combines `LogRequest` and `LogResponse` for a light middleware recording what happens during serving of a request (both incoming and outgoing attributes).
+
+For instance (most attributes elided for brevity, also logs client cert and TLSInfo if applicable)
+```json
+{"level":"info","msg":"test-log-and-call2","method":"GET","url":"/tea","status":418,"size":5,"microsec":100042}
+```
+
+# Config
+
+You can either use `fortio.org/cli` or `fortio.org/scli` (or `dflags`) for configuration using flags (or dynamic flags and config map) or use the environment variables:
+
+```bash
+LOGGER_LOG_PREFIX=' '
+LOGGER_LOG_FILE_AND_LINE=false
+LOGGER_FATAL_PANICS=false
+LOGGER_JSON=false
+LOGGER_NO_TIMESTAMP=false
+LOGGER_CONSOLE_COLOR=true
+LOGGER_FORCE_COLOR=false
+LOGGER_GOROUTINE_ID=false
+LOGGER_COMBINE_REQUEST_AND_RESPONSE=true
+LOGGER_LEVEL='Info'
+```

go.mod

@@ -1,3 +1,5 @@
 module fortio.org/log
 
 go 1.18
+
+require fortio.org/struct2env v0.4.0

go.sum

@@ -0,0 +1,2 @@
+fortio.org/struct2env v0.4.0 h1:k5alSOTf3YHiB3MuacjDHQ3YhVWvNZ95ZP/a6MqvyLo=
+fortio.org/struct2env v0.4.0/go.mod h1:lENUe70UwA1zDUCX+8AsO663QCFqYaprk5lnPhjD410=

http_logging.go

@@ -19,7 +19,10 @@ import (
 	"fmt"
 	"log"
 	"net/http"
+	"runtime/debug"
+	"sort"
 	"strings"
+	"time"
 )
 
 // TLSInfo returns ' https <cipher suite> "<peer CN>"' if the request is using TLS
@@ -47,31 +50,162 @@ func AppendTLSInfoAttrs(attrs []KeyVal, r *http.Request) []KeyVal {
 	return attrs
 }
 
+func AddIfNotEmpty(attrs []KeyVal, key, value string) []KeyVal {
+	if value != "" {
+		attrs = append(attrs, Str(key, value))
+	}
+	return attrs
+}
+
 // LogRequest logs the incoming request, TLSInfo,
 // including headers when loglevel is verbose.
 // additional key:value pairs can be passed as extraAttributes.
 //
-//nolint:revive
+//nolint:revive // name is fine.
 func LogRequest(r *http.Request, msg string, extraAttributes ...KeyVal) {
 	if !Log(Info) {
 		return
 	}
+	// URL struct is quite verbose and not that interesting to log all pieces so we log the String() version
+	var url KeyVal
+	if r.URL == nil {
+		url = Any("url", r.URL) // basically 'null'
+	} else {
+		url = Str("url", r.URL.String())
+	}
 	attr := []KeyVal{
-		Str("method", r.Method), Attr("url", r.URL), Str("proto", r.Proto),
-		Str("remote_addr", r.RemoteAddr), Str("host", r.Host),
-		Str("header.x-forwarded-proto", r.Header.Get("X-Forwarded-Proto")),
-		Str("header.x-forwarded-for", r.Header.Get("X-Forwarded-For")),
-		Str("user-agent", r.Header.Get("User-Agent")),
+		Str("method", r.Method), url, Str("host", r.Host),
+		Str("proto", r.Proto), Str("remote_addr", r.RemoteAddr),
+	}
+	if !LogVerbose() { // in verbose all headers are already logged
+		attr = AddIfNotEmpty(attr, "user-agent", r.Header.Get("User-Agent"))
+		// note this only prints the first one, while verbose mode will join all values with ','
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-proto", r.Header.Get("X-Forwarded-Proto"))
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-for", r.Header.Get("X-Forwarded-For"))
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-host", r.Header.Get("X-Forwarded-Host"))
 	}
 	attr = AppendTLSInfoAttrs(attr, r)
 	attr = append(attr, extraAttributes...)
 	if LogVerbose() {
 		// Host is removed from headers map and put separately
-		for name, headers := range r.Header {
-			attr = append(attr, Str("header."+name, strings.Join(headers, ",")))
+		// Need to sort to get a consistent order
+		keys := make([]string, 0, len(r.Header))
+		for name := range r.Header {
+			keys = append(keys, name)
+		}
+		sort.Strings(keys)
+		for _, name := range keys {
+			nl := strings.ToLower(name)
+			if nl != "user-agent" {
+				nl = "header." + nl
+			}
+			attr = append(attr, Str(nl, strings.Join(r.Header[name], ",")))
 		}
 	}
-	S(Info, msg, attr...)
+	// not point in having the line number be this file
+	s(Info, false, Config.JSON, msg, attr...)
+}
+
+// LogResponse logs the response code, byte size and duration of the request.
+// additional key:value pairs can be passed as extraAttributes.
+//
+//nolint:revive // name is fine.
+func LogResponse[T *ResponseRecorder | *http.Response](r T, msg string, extraAttributes ...KeyVal) {
+	if !Log(Info) {
+		return
+	}
+	var status int
+	var size int64
+	switch v := any(r).(type) { // go generics...
+	case *ResponseRecorder:
+		status = v.StatusCode
+		size = v.ContentLength
+	case *http.Response:
+		status = v.StatusCode
+		size = v.ContentLength
+	}
+	attr := []KeyVal{
+		Int("status", status),
+		Int64("size", size),
+	}
+	attr = append(attr, extraAttributes...)
+	// not point in having the line number be this file
+	s(Info, false, Config.JSON, msg, attr...)
+}
+
+// Can be used (and is used by LogAndCall()) to wrap a http.ResponseWriter to record status code and size.
+type ResponseRecorder struct {
+	w             http.ResponseWriter
+	startTime     time.Time
+	StatusCode    int
+	ContentLength int64
+}
+
+func (rr *ResponseRecorder) Header() http.Header {
+	return rr.w.Header()
+}
+
+func (rr *ResponseRecorder) Write(p []byte) (int, error) {
+	size, err := rr.w.Write(p)
+	rr.ContentLength += int64(size)
+	if err != nil {
+		rr.StatusCode = http.StatusInternalServerError
+	} else if rr.StatusCode == 0 {
+		rr.StatusCode = http.StatusOK
+	}
+	return size, err
+}
+
+func (rr *ResponseRecorder) WriteHeader(code int) {
+	rr.w.WriteHeader(code)
+	rr.StatusCode = code
+}
+
+// Implement http.Flusher interface.
+func (rr *ResponseRecorder) Flush() {
+	if f, ok := rr.w.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+// LogAndCall logs the incoming request and the response code, byte size and duration
+// of the request.
+//
+// If Config.CombineRequestAndResponse or the LOGGER_COMBINE_REQUEST_AND_RESPONSE
+// environment variable is true, then a single log entry is done combining request and
+// response information, including catching for panic.
+//
+// Additional key:value pairs can be passed as extraAttributes.
+//
+//nolint:revive // name is fine.
+func LogAndCall(msg string, handlerFunc http.HandlerFunc, extraAttributes ...KeyVal) http.HandlerFunc {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		// This is really 2 functions but we want to be able to change config without rewiring the middleware
+		if Config.CombineRequestAndResponse {
+			respRec := &ResponseRecorder{w: w, startTime: time.Now()}
+			defer func() {
+				if err := recover(); err != nil {
+					s(Critical, false, Config.JSON, "panic in handler", Any("error", err))
+					if Log(Verbose) {
+						s(Verbose, false, Config.JSON, "stack trace", Str("stack", string(debug.Stack())))
+					}
+				}
+				attr := []KeyVal{
+					Int("status", respRec.StatusCode),
+					Int64("size", respRec.ContentLength),
+					Int64("microsec", time.Since(respRec.startTime).Microseconds()),
+				}
+				attr = append(attr, extraAttributes...)
+				LogRequest(r, msg, attr...)
+			}()
+			handlerFunc(respRec, r)
+			return
+		}
+		LogRequest(r, msg, extraAttributes...)
+		respRec := &ResponseRecorder{w: w, startTime: time.Now()}
+		handlerFunc(respRec, r)
+		LogResponse(respRec, msg, Int64("microsec", time.Since(respRec.startTime).Microseconds()))
+	})
 }
 
 type logWriter struct {