api/server/middleware: use structured logs for debug-logs

thaJeztah · thaJeztah · commit 1701bce9e09f · 2024-10-16T14:47:53.000+02:00
Rewrite the debug-logs produced

- Use structured logs
- Combine into a single log per request, instead of separate log-entry
  for the "form-data".
- Include error-messages returned by the handler ("error-response" field)
- Include HTTP status-code returned ("status" field)
- Include the "vars" as a field; these are fields extracted from the URL
  and passed to the handler

Examples below are logs for:

    docker ps
    docker container inspect nosuchcontainer
    docker volume create --name foo

Before this change:

    DEBU[2024-10-16T10:59:40.484254465Z] Calling HEAD /_ping                           spanID=43d76043f8e30dbb traceID=04f980a33901f35ba33c3927d3bb4bbb
    DEBU[2024-10-16T10:59:40.485551840Z] Calling GET /v1.47/containers/json            spanID=b9979f2b36572a43 traceID=5c2167537df2dede6bdbab030f8350bc
    DEBU[2024-10-16T11:00:00.374864502Z] Calling HEAD /_ping                           spanID=d637e39684d56a16 traceID=efaed7838901dd6a597c5446ce3f83e2
    DEBU[2024-10-16T11:00:00.384198127Z] Calling GET /v1.47/containers/nosuchcontainer/json  spanID=f9cc4520b95d814b traceID=c15ae04ca248929d6e52474e711d48b0
    DEBU[2024-10-16T11:00:11.576426632Z] Calling HEAD /_ping                           spanID=2bc30d2be873a8e5 traceID=53ccc3d2af87aa5425421306906660a6
    DEBU[2024-10-16T11:00:11.588877966Z] Calling POST /v1.47/volumes/create            spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23
    DEBU[2024-10-16T11:00:11.589198966Z] form data: {"Driver":"local","Name":"foo"}    spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23
    DEBU[2024-10-16T11:00:11.594828216Z] using regular volume                          spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23

After this:

When using plain-text, we continue encoding the form-data to JSON, but
as it's now in a field, it'll be shown escaped;

    DEBU[2024-10-16T11:17:35.465777379Z] handling HEAD request                         method=HEAD module=api request-url=/_ping spanID=9b7ea0288b2b70c3 status=200 traceID=94ef9345624e92ac0263931fbe9e15db vars="map[]"
    DEBU[2024-10-16T11:17:35.468050171Z] handling GET request                          method=GET module=api request-url=/v1.47/containers/json spanID=04675edee7b5ec9d status=200 traceID=a9d81dcdbf2650fa6d794a7a856fb66b vars="map[version:1.47]"
    DEBU[2024-10-16T11:17:38.502289297Z] handling HEAD request                         method=HEAD module=api request-url=/_ping spanID=7c43a8dfd8fb5043 status=200 traceID=7a2a7c71cd421570e811474749a04ccd vars="map[]"
    DEBU[2024-10-16T11:17:38.504847506Z] handling GET request                          error-response="No such container: nosuchcontainer" method=GET module=api request-url=/v1.47/containers/nosuchcontainer/json spanID=ab721bbbe5cf8035 status=404 traceID=4a08dcd5054fc8090e3af8846beea10d vars="map[name:nosuchcontainer version:1.47]"
    DEBU[2024-10-16T11:17:40.788838340Z] handling HEAD request                         method=HEAD module=api request-url=/_ping spanID=2dbc18ba1334635b status=200 traceID=ea9af681d096dc4a2c2f2ed7338ea417 vars="map[]"
    DEBU[2024-10-16T11:17:40.790496465Z] handling POST request                         form-data="{\"Driver\":\"local\",\"Name\":\"foo\"}" method=POST module=api request-url=/v1.47/volumes/create spanID=03690760b6f6dec4 status=200 traceID=79a985fff0dd5fac7c90d36b04941e0a vars="map[version:1.47]"

The alternative to the above would be to unconditionally set it as-is,
but in that case it would use Go's formatting for `map[string]any`;

    DEBU[2024-10-16T11:27:54.937232805Z] handling POST request                         form-data="map[Driver:local Name:foo]" method=POST module=api request-url=/v1.47/volumes/create spanID=2d7985a900791bf6 status=200 traceID=33feab9fd5feba3b0f4b6ec5a6971a67 vars="map[version:1.47]"

Or to use some trickery to not quote this specific field, but that may limit the
output from being parsable;

    DEBU[2024-10-16T11:17:40.790496465Z] handling POST request                         form-data={"Driver":"local","Name":"foo"} method=POST module=api request-url=/v1.47/volumes/create spanID=03690760b6f6dec4 status=200 traceID=79a985fff0dd5fac7c90d36b04941e0a vars="map[version:1.47]"

When using `--log-format=json`, the form-data is kept as structured, becoming
part of the main JSON struct:

    {"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"166dc12eeeadf82b","status":200,"time":"2024-10-16T11:16:09.427380423Z","traceID":"7f4f2501eee3b15ae608481ba214bd56","vars":{}}
    {"level":"debug","method":"GET","module":"api","msg":"handling GET request","request-url":"/v1.47/containers/json","spanID":"bf95e2ce9eca41c2","status":200,"time":"2024-10-16T11:16:09.429077631Z","traceID":"041b26b30dacc240e8e3afc9c567195d","vars":{"version":"1.47"}}
    {"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"454953906c36ea6b","status":200,"time":"2024-10-16T11:16:13.455633008Z","traceID":"3ffc0a256d6ec1a56cd7f6bf1008e55d","vars":{}}
    {"error-response":"No such container: nosuchcontainer","level":"debug","method":"GET","module":"api","msg":"handling GET request","request-url":"/v1.47/containers/nosuchcontainer/json","spanID":"dcf0d42921928b29","status":404,"time":"2024-10-16T11:16:13.460309925Z","traceID":"fdfd2c89941c9c7a459bec7a05e46ef8","vars":{"name":"nosuchcontainer","version":"1.47"}}
    {"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"701dc623cf1b0253","status":200,"time":"2024-10-16T11:16:16.155730884Z","traceID":"786885a9f79cbfba99097eeb4145ca1e","vars":{}}
    {"form-data":{"Driver":"local","Name":"foo"},"level":"debug","method":"POST","module":"api","msg":"handling POST request","request-url":"/v1.47/volumes/create","spanID":"dc1429c1c636b30a","status":200,"time":"2024-10-16T11:16:16.162002426Z","traceID":"fc49ee4a7acafbbb8eb50ed34c434765","vars":{"version":"1.47"}}

Signed-off-by: Sebastiaan van Stijn &lt;github@gone.nl&gt;
diff --git a/api/server/middleware/debug.go b/api/server/middleware/debug.go
@@ -9,14 +9,33 @@ import (
 	"strings"
 
 	"github.com/containerd/log"
+	"github.com/docker/docker/api/server/httpstatus"
 	"github.com/docker/docker/api/server/httputils"
 	"github.com/docker/docker/pkg/ioutils"
+	"github.com/sirupsen/logrus"
 )
 
 // DebugRequestMiddleware dumps the request to logger
 func DebugRequestMiddleware(handler func(ctx context.Context, w http.ResponseWriter, r *http.Request, vars map[string]string) error) func(ctx context.Context, w http.ResponseWriter, r *http.Request, vars map[string]string) error {
-	return func(ctx context.Context, w http.ResponseWriter, r *http.Request, vars map[string]string) error {
-		log.G(ctx).Debugf("Calling %s %s", r.Method, r.RequestURI)
+	return func(ctx context.Context, w http.ResponseWriter, r *http.Request, vars map[string]string) (retErr error) {
+		logger := log.G(ctx)
+
+		// Use a variable for fields to prevent overhead of repeatedly
+		// calling WithFields.
+		fields := log.Fields{
+			"module":      "api",
+			"method":      r.Method,
+			"request-url": r.RequestURI,
+			"vars":        vars,
+			"status":      http.StatusOK,
+		}
+		defer func() {
+			if retErr != nil {
+				fields["error-response"] = retErr
+				fields["status"] = httpstatus.FromError(retErr)
+			}
+			logger.WithFields(fields).Debugf("handling %s request", r.Method)
+		}()
 
 		if r.Method != http.MethodPost {
 			return handler(ctx, w, r, vars)
@@ -42,11 +61,15 @@ func DebugRequestMiddleware(handler func(ctx context.Context, w http.ResponseWri
 		var postForm map[string]interface{}
 		if err := json.Unmarshal(b, &postForm); err == nil {
 			maskSecretKeys(postForm)
-			formStr, errMarshal := json.Marshal(postForm)
-			if errMarshal == nil {
-				log.G(ctx).Debugf("form data: %s", string(formStr))
+			// TODO(thaJeztah): is there a better way to detect if we're using JSON-formatted logs?
+			if _, ok := logger.Logger.Formatter.(*logrus.JSONFormatter); ok {
+				fields["form-data"] = postForm
 			} else {
-				log.G(ctx).Debugf("form data: %q", postForm)
+				if data, err := json.Marshal(postForm); err != nil {
+					fields["form-data"] = postForm
+				} else {
+					fields["form-data"] = string(data)
+				}
 			}
 		}
 
