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 brievety, also logs client cert and TLSInfo if applicable)
+```json
+{"level":"info","msg":"test-log-and-call2","method":"GET","url":{"Path":"/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

@@ -20,6 +20,7 @@ import (
 	"log"
 	"net/http"
 	"strings"
+	"time"
 )
 
 // TLSInfo returns ' https <cipher suite> "<peer CN>"' if the request is using TLS
@@ -51,7 +52,7 @@ func AppendTLSInfoAttrs(attrs []KeyVal, r *http.Request) []KeyVal {
 // 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
@@ -74,6 +75,96 @@ func LogRequest(r *http.Request, msg string, extraAttributes ...KeyVal) {
 	S(Info, 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...)
+	S(Info, 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
+}
+
+// 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, hf http.HandlerFunc, extraAttributes ...KeyVal) http.HandlerFunc {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		if Config.CombineRequestAndResponse {
+			rr := &ResponseRecorder{w: w, startTime: time.Now()}
+			defer func() {
+				if err := recover(); err != nil {
+					S(Critical, "panic in handler", Any("error", err))
+				}
+				attr := []KeyVal{
+					Int("status", rr.StatusCode),
+					Int64("size", rr.ContentLength),
+					Int64("microsec", time.Since(rr.startTime).Microseconds()),
+				}
+				attr = append(attr, extraAttributes...)
+				LogRequest(r, msg, attr...)
+			}()
+			hf(rr, r)
+			return
+		}
+		LogRequest(r, msg, extraAttributes...)
+		rr := &ResponseRecorder{w: w, startTime: time.Now()}
+		hf(rr, r)
+		LogResponse(rr, msg, Int64("microsec", time.Since(rr.startTime).Microseconds()))
+	})
+}
+
 type logWriter struct {
 	source string
 	level  Level

http_logging_test.go

@@ -6,9 +6,13 @@ import (
 	"crypto/tls"
 	"crypto/x509"
 	"crypto/x509/pkix"
+	"fmt"
 	"log"
 	"net/http"
+	"net/url"
+	"strings"
 	"testing"
+	"time"
 )
 
 // There is additional functional testing in fortio.org/fortio/fhttp.
@@ -38,6 +42,124 @@ func TestLogRequest(t *testing.T) {
 	}
 }
 
+func testHandler(w http.ResponseWriter, r *http.Request) {
+	if r.URL != nil && r.URL.Path == "/tea" {
+		w.WriteHeader(http.StatusTeapot)
+	}
+	w.Write([]byte("hello"))
+	time.Sleep(100 * time.Millisecond)
+}
+
+type NullHTTPWriter struct {
+	doErr   bool
+	doPanic bool
+}
+
+func (n *NullHTTPWriter) Header() http.Header {
+	return nil
+}
+
+func (n *NullHTTPWriter) Write(b []byte) (int, error) {
+	if n.doPanic {
+		panic("some fake http write panic")
+	}
+	if n.doErr {
+		return 0, fmt.Errorf("some fake http write error")
+	}
+	return len(b), nil
+}
+
+func (n *NullHTTPWriter) WriteHeader(_ int) {}
+
+func TestLogAndCall(t *testing.T) {
+	Config.LogFileAndLine = false
+	Config.JSON = true
+	Config.NoTimestamp = true
+	Config.CombineRequestAndResponse = false // Separate request and response logging
+	var b bytes.Buffer
+	w := bufio.NewWriter(&b)
+	SetOutput(w)
+	hr := &http.Request{}
+	n := &NullHTTPWriter{}
+	hw := &ResponseRecorder{w: n}
+	LogAndCall("test-log-and-call", testHandler).ServeHTTP(hw, hr)
+	w.Flush()
+	actual := b.String()
+	//nolint: lll
+	expectedPrefix := `{"level":"info","msg":"test-log-and-call","method":"","url":null,"proto":"","remote_addr":"","host":"","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":""}
+{"level":"info","msg":"test-log-and-call","status":200,"size":5,"microsec":1` // the 1 is for the 100ms sleep
+	if !strings.HasPrefix(actual, expectedPrefix) {
+		t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix)
+	}
+	if hw.Header() != nil {
+		t.Errorf("unexpected non nil header: %v", hw.Header())
+	}
+	hr.URL = &url.URL{Path: "/tea"}
+	b.Reset()
+	Config.CombineRequestAndResponse = true // Combined logging test
+	LogAndCall("test-log-and-call2", testHandler).ServeHTTP(hw, hr)
+	w.Flush()
+	actual = b.String()
+	//nolint: lll
+	expectedPrefix = `{"level":"info","msg":"test-log-and-call2","method":"","url":{"Scheme":"","Opaque":"","User":null,"Host":"","Path":"/tea","RawPath":"","OmitHost":false,"ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"proto":"","remote_addr":"","host":"","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","status":418,"size":5,"microsec":1`
+	if !strings.HasPrefix(actual, expectedPrefix) {
+		t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix)
+	}
+	b.Reset()
+	n.doErr = true
+	LogAndCall("test-log-and-call3", testHandler).ServeHTTP(hw, hr)
+	w.Flush()
+	actual = b.String()
+	expectedFragment := `"user-agent":"","status":500,"size":0,"microsec":1`
+	if !strings.Contains(actual, expectedFragment) {
+		t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment)
+	}
+	n.doPanic = true
+	n.doErr = false
+	b.Reset()
+	LogAndCall("test-log-and-call4", testHandler).ServeHTTP(hw, hr)
+	w.Flush()
+	actual = b.String()
+	expectedFragment = `,"size":0,`
+	Config.GoroutineID = false
+	if !strings.Contains(actual, expectedFragment) {
+		t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment)
+	}
+	if !strings.Contains(actual, `{"level":"crit","msg":"panic in handler","error":"some fake http write panic"`) {
+		t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, "some fake http write panic")
+	}
+	// restore for other tests
+	Config.GoroutineID = true
+}
+
+func TestLogResponseOnHTTPResponse(t *testing.T) {
+	SetLogLevel(Info)
+	Config.LogFileAndLine = false
+	Config.JSON = true
+	Config.NoTimestamp = true
+	var b bytes.Buffer
+	w := bufio.NewWriter(&b)
+	SetOutput(w)
+	r := &http.Response{StatusCode: http.StatusTeapot, ContentLength: 123}
+	LogResponse(r, "test1")
+	w.Flush()
+	actual := b.String()
+	expected := `{"level":"info","msg":"test1","status":418,"size":123}
+`
+	if actual != expected {
+		t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected)
+	}
+	SetLogLevelQuiet(Warning)
+	b.Reset()
+	LogResponse(r, "test2")
+	w.Flush()
+	actual = b.String()
+	if actual != "" {
+		t.Errorf("unexpected: %q", actual)
+	}
+	SetLogLevelQuiet(Verbose)
+}
+
 func TestLogRequestNoLog(t *testing.T) {
 	SetLogLevel(Warning) // make sure it's already debug when we capture
 	Config.LogFileAndLine = false