mirror of
https://github.com/moby/moby.git
synced 2026-07-12 10:35:14 +00: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 <github@gone.nl>
114 lines
3.2 KiB
Go
114 lines
3.2 KiB
Go
package middleware // import "github.com/docker/docker/api/server/middleware"
|
|
|
|
import (
|
|
"bufio"
|
|
"context"
|
|
"encoding/json"
|
|
"io"
|
|
"net/http"
|
|
"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) (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)
|
|
}
|
|
if err := httputils.CheckForJSON(r); err != nil {
|
|
return handler(ctx, w, r, vars)
|
|
}
|
|
maxBodySize := 4096 // 4KB
|
|
if r.ContentLength > int64(maxBodySize) {
|
|
return handler(ctx, w, r, vars)
|
|
}
|
|
|
|
body := r.Body
|
|
bufReader := bufio.NewReaderSize(body, maxBodySize)
|
|
r.Body = ioutils.NewReadCloserWrapper(bufReader, func() error { return body.Close() })
|
|
|
|
b, err := bufReader.Peek(maxBodySize)
|
|
if err != io.EOF {
|
|
// either there was an error reading, or the buffer is full (in which case the request is too large)
|
|
return handler(ctx, w, r, vars)
|
|
}
|
|
|
|
var postForm map[string]interface{}
|
|
if err := json.Unmarshal(b, &postForm); err == nil {
|
|
maskSecretKeys(postForm)
|
|
// 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 {
|
|
if data, err := json.Marshal(postForm); err != nil {
|
|
fields["form-data"] = postForm
|
|
} else {
|
|
fields["form-data"] = string(data)
|
|
}
|
|
}
|
|
}
|
|
|
|
return handler(ctx, w, r, vars)
|
|
}
|
|
}
|
|
|
|
func maskSecretKeys(inp interface{}) {
|
|
if arr, ok := inp.([]interface{}); ok {
|
|
for _, f := range arr {
|
|
maskSecretKeys(f)
|
|
}
|
|
return
|
|
}
|
|
|
|
if form, ok := inp.(map[string]interface{}); ok {
|
|
scrub := []string{
|
|
// Note: The Data field contains the base64-encoded secret in 'secret'
|
|
// and 'config' create and update requests. Currently, no other POST
|
|
// API endpoints use a data field, so we scrub this field unconditionally.
|
|
// Change this handling to be conditional if a new endpoint is added
|
|
// in future where this field should not be scrubbed.
|
|
"data",
|
|
"jointoken",
|
|
"password",
|
|
"secret",
|
|
"signingcakey",
|
|
"unlockkey",
|
|
}
|
|
loop0:
|
|
for k, v := range form {
|
|
for _, m := range scrub {
|
|
if strings.EqualFold(m, k) {
|
|
form[k] = "*****"
|
|
continue loop0
|
|
}
|
|
}
|
|
maskSecretKeys(v)
|
|
}
|
|
}
|
|
}
|