api/server/middleware: use structured logs for debug-logs by thaJeztah · Pull Request #48677 · moby/moby

thaJeztah · 2024-10-16T12:50:14Z

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"}}

- What I did

- How I did it

- How to verify it

- Description for the changelog

Use structured logs for logging requests if the daemon has debug enabled

- A picture of a cute animal (not mandatory but encouraged)

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 <[email protected]>

vvoland · 2024-10-16T13:28:04Z

+			// 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)
+				}


What do we lose if we just use fields["form-data"] = postForm without bothering to marshal the JSON ourselves for non-JSON formatters?

The output would be in Go's formatting used for map[string]any. It's still readable, but slightly less useful if you want to (e.g.) replicate a request with cURL;

form-data="map[Driver:local Name:foo]"

The JSON format also allows for (e.g.) using jq to format, which can be useful when troubleshooting requests (to print it in pretty format).

cpuguy83 · 2024-10-17T18:38:25Z

+			"method":      r.Method,
+			"request-url": r.RequestURI,
+			"vars":        vars,
+			"status":      http.StatusOK,


I don't think we can set status here?

Oh; this is the default; I set it to StatusOK by default, and in the defer, I set it to the status-code based on the error returned, does that make sense?

Yep, silly me I didn't notice it in the defer below.

No worries, thanks for reviewing; could've been a bug!

thaJeztah added area/api API status/1-design-review kind/enhancement Enhancements are not bugs or new features but can improve usability or performance. labels Oct 16, 2024

thaJeztah self-assigned this Oct 16, 2024

thaJeztah added this to the 28.0.0 milestone Oct 16, 2024

vvoland reviewed Oct 16, 2024

View reviewed changes

vvoland approved these changes Oct 16, 2024

View reviewed changes

cpuguy83 requested changes Oct 17, 2024

View reviewed changes

dmcgowan approved these changes Oct 17, 2024

View reviewed changes

cpuguy83 approved these changes Oct 18, 2024

View reviewed changes

cpuguy83 merged commit e7f9f06 into moby:master Oct 18, 2024

thaJeztah deleted the debug_structured_logs branch October 18, 2024 19:08

thaJeztah added status/4-merge and removed status/1-design-review labels Oct 23, 2024

thaJeztah mentioned this pull request Oct 23, 2024

api/server/middleware: log before, not after the request #48740

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

api/server/middleware: use structured logs for debug-logs#48677
cpuguy83 merged 1 commit intomoby:masterfrom
thaJeztah:debug_structured_logs

thaJeztah commented Oct 16, 2024

Uh oh!

vvoland Oct 16, 2024

Uh oh!

thaJeztah Oct 16, 2024 •

edited

Loading

Uh oh!

cpuguy83 Oct 17, 2024

Uh oh!

thaJeztah Oct 17, 2024

Uh oh!

cpuguy83 Oct 18, 2024

Uh oh!

thaJeztah Oct 18, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

thaJeztah commented Oct 16, 2024

Uh oh!

vvoland Oct 16, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Oct 16, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cpuguy83 Oct 17, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Oct 17, 2024

Choose a reason for hiding this comment

Uh oh!

cpuguy83 Oct 18, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Oct 18, 2024

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

thaJeztah Oct 16, 2024 •

edited

Loading