Add (optional) debug logging for console requests (#3440)

* Add (optional) debug logging for console requests
* Check vulnerabilities with 1.22.7

Author: ramondeklein

.github/workflows/vulncheck.yaml

@@ -19,7 +19,7 @@ jobs:
       - name: Set up Go
         uses: actions/setup-go@v5
         with:
-          go-version: 1.22.5
+          go-version: 1.22.7
           check-latest: true
       - name: Get official govulncheck
         run: go install golang.org/x/vuln/cmd/govulncheck@latest
@@ -33,7 +33,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        go-version: [ 1.22.5 ]
+        go-version: [ 1.22.7 ]
         os: [ ubuntu-latest ]
     steps:
       - name: Check out code

README.md

@@ -205,6 +205,27 @@ export CONSOLE_MINIO_SERVER=https://localhost:9000
 
 You can verify that the apis work by doing the request on `localhost:9090/api/v1/...`
 
+## Debug logging
+
+In some cases it may be convenient to log all HTTP requests. This can be enabled by setting
+the `CONSOLE_DEBUG_LOGLEVEL` environment variable to one of the following values:
+
+ - `0` (default) uses no logging.
+ - `1` log single line per request for server-side errors (status-code 5xx).
+ - `2` log single line per request for client-side and server-side errors (status-code 4xx/5xx).
+ - `3` log single line per request for all requests (status-code 4xx/5xx).
+ - `4` log details per request for server-side errors (status-code 5xx).
+ - `5` log details per request for client-side and server-side errors (status-code 4xx/5xx).
+ - `6` log details per request for all requests (status-code 4xx/5xx).
+
+ A single line logging has the following information:
+ - Remote endpoint (IP + port) of the request. Note that reverse proxies may hide the actual remote endpoint of the client's browser.
+ - HTTP method and URL
+ - Status code of the response (websocket connections are hijacked, so no response is shown)
+ - Duration of the request
+
+The detailed logging also includes all request and response headers (if any).
+ 
 # Contribute to console Project
 
 Please follow console [Contributor's Guide](https://github.com/minio/console/blob/master/CONTRIBUTING.md)

api/configure_console.go

@@ -31,6 +31,8 @@ import (
 	"path"
 	"path/filepath"
 	"regexp"
+	"sort"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -216,6 +218,97 @@ func AuditLogMiddleware(next http.Handler) http.Handler {
 	})
 }
 
+func DebugLogMiddleware(next http.Handler) http.Handler {
+	debugLogLevel, _ := env.GetInt("CONSOLE_DEBUG_LOGLEVEL", 0)
+	if debugLogLevel == 0 {
+		return next
+	}
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		rw := logger.NewResponseWriter(w)
+		next.ServeHTTP(rw, r)
+		debugLog(debugLogLevel, r, rw)
+	})
+}
+
+func debugLog(debugLogLevel int, r *http.Request, rw *logger.ResponseWriter) {
+	switch debugLogLevel {
+	case 1:
+		// Log server errors only (summary)
+		if rw.StatusCode >= 500 {
+			debugLogSummary(r, rw)
+		}
+	case 2:
+		// Log server and client errors (summary)
+		if rw.StatusCode >= 400 {
+			debugLogSummary(r, rw)
+		}
+	case 3:
+		// Log all requests (summary)
+		debugLogSummary(r, rw)
+	case 4:
+		// Log server errors only (including headers)
+		if rw.StatusCode >= 500 {
+			debugLogDetails(r, rw)
+		}
+	case 5:
+		// Log server and client errors (including headers)
+		if rw.StatusCode >= 400 {
+			debugLogDetails(r, rw)
+		}
+	case 6:
+		// Log all requests (including headers)
+		debugLogDetails(r, rw)
+	}
+}
+
+func debugLogSummary(r *http.Request, rw *logger.ResponseWriter) {
+	statusCode := strconv.Itoa(rw.StatusCode)
+	if rw.Hijacked {
+		statusCode = "hijacked"
+	}
+	logger.Info(fmt.Sprintf("%s %s %s %s %dms", r.RemoteAddr, r.Method, r.URL, statusCode, time.Since(rw.StartTime).Milliseconds()))
+}
+
+func debugLogDetails(r *http.Request, rw *logger.ResponseWriter) {
+	var sb strings.Builder
+	sb.WriteString(fmt.Sprintf("- Method/URL:       %s %s\n", r.Method, r.URL))
+	sb.WriteString(fmt.Sprintf("  Remote endpoint:  %s\n", r.RemoteAddr))
+	if rw.Hijacked {
+		sb.WriteString("  Status code:      <hijacked, probably a websocket>\n")
+	} else {
+		sb.WriteString(fmt.Sprintf("  Status code:      %d\n", rw.StatusCode))
+	}
+	sb.WriteString(fmt.Sprintf("  Duration (ms):    %d\n", time.Since(rw.StartTime).Milliseconds()))
+	sb.WriteString("  Request headers:  ")
+	debugLogHeaders(&sb, r.Header)
+	sb.WriteString("  Response headers: ")
+	debugLogHeaders(&sb, rw.Header())
+	logger.Info(sb.String())
+}
+
+func debugLogHeaders(sb *strings.Builder, h http.Header) {
+	keys := make([]string, 0, len(h))
+	for key := range h {
+		keys = append(keys, key)
+	}
+	sort.Strings(keys)
+	first := true
+	for _, key := range keys {
+		values := h[key]
+		for _, value := range values {
+			if !first {
+				sb.WriteString("                    ")
+			} else {
+				first = false
+			}
+			sb.WriteString(fmt.Sprintf("%s: %s\n", key, value))
+		}
+	}
+	if first {
+		sb.WriteRune('\n')
+	}
+}
+
 // The middleware configuration happens before anything, this middleware also applies to serving the swagger.json document.
 // So this is a good place to plug in a panic handling middleware, logger and metrics
 func setupGlobalMiddleware(handler http.Handler) http.Handler {
@@ -228,6 +321,8 @@ func setupGlobalMiddleware(handler http.Handler) http.Handler {
 	next = ContextMiddleware(next)
 	// handle cookie or authorization header for session
 	next = AuthenticationMiddleware(next)
+	// handle debug logging
+	next = DebugLogMiddleware(next)
 
 	sslHostFn := secure.SSLHostFunc(func(host string) string {
 		xhost, err := xnet.ParseHost(host)

pkg/logger/audit.go

@@ -17,10 +17,13 @@
 package logger
 
 import (
+	"bufio"
 	"bytes"
 	"context"
+	"errors"
 	"fmt"
 	"io"
+	"net"
 	"net/http"
 	"strconv"
 	"sync/atomic"
@@ -35,6 +38,7 @@ import (
 type ResponseWriter struct {
 	http.ResponseWriter
 	StatusCode int
+	Hijacked   bool
 	// Log body of 4xx or 5xx responses
 	LogErrBody bool
 	// Log body of all responses
@@ -61,6 +65,15 @@ func NewResponseWriter(w http.ResponseWriter) *ResponseWriter {
 	}
 }
 
+func (lrw *ResponseWriter) Hijack() (conn net.Conn, rw *bufio.ReadWriter, err error) {
+	hijack, ok := lrw.ResponseWriter.(http.Hijacker)
+	if !ok {
+		return nil, nil, errors.New("base response writer doesn't implement hijacker")
+	}
+	lrw.Hijacked = true
+	return hijack.Hijack()
+}
+
 func (lrw *ResponseWriter) Write(p []byte) (int, error) {
 	if !lrw.headersLogged {
 		// We assume the response code to be '200 OK' when WriteHeader() is not called,