api/server/middleware: log before, not after the request by thaJeztah · Pull Request #48740 · moby/moby

thaJeztah · 2024-10-23T22:28:03Z

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

commit 1701bce updated the debug logs to use structured logs, and to include more information in the logs, such as the form-data used and the status-code, and combining them into a single log.

However, for the status-code, we need to wait for the handler to do its thing and (ahum) this was staring me right in the face, and crossed my mind, but then I didn't act on it; the handler may take some time to run, and produce logs, which now means that our nice "handling request" log will be logged after the request, which is obviously confusing.

This patch splits the log into two;

a log entry when starting to handle the request
a log entry if a non-200 status is returned (assuming 200 status codes are less interesting to log).

Before this patch:

DEBU[2024-10-23T15:23:31.677184128Z] handling HEAD request                         method=HEAD module=api request-url=/_ping spanID=8180b03fa17f9783 status=200 traceID=a5dfa9b86445467889274145ad31bb9a vars="map[]"
DEBU[2024-10-23T15:23:31.712833045Z] resolving                                     host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:31.712883670Z] do request                                    host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.051728378Z] fetch response received                       host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.051830920Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:32.051909045Z] do request                                    host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.544987920Z] fetch response received                       host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.545112212Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
INFO[2024-10-23T15:23:32.545270087Z] trying next host                              error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:32.550666962Z] handling POST request                         error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=38286e48a07445ef status=404 traceID=3c01e6c2cf19cf82237fdd01c0294fb4 vars="map[version:1.47]"

With this patch applied:

DEBU[2024-10-23T15:18:18.876346178Z] handling HEAD request                         method=HEAD module=api request-url=/_ping spanID=7fd5eb011140f546 traceID=80ffd75a39de78a1f51ffda89fc4f227 vars="map[]"
DEBU[2024-10-23T15:18:18.878006428Z] handling POST request                         method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]"
DEBU[2024-10-23T15:18:18.919686136Z] resolving                                     host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:18.919748094Z] do request                                    host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.258132303Z] fetch response received                       host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.258219803Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:19.258406886Z] do request                                    host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.755911762Z] fetch response received                       host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.757501928Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
INFO[2024-10-23T15:18:19.757689387Z] trying next host                              error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:19.763826095Z] error response for POST request               error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 status=404 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]"

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

akerouanton · 2024-10-24T06:17:37Z

 				fields["status"] = httpstatus.FromError(retErr)
+				logger.WithFields(fields).Debugf("error response for %s request", r.Method)
 			}
-			logger.WithFields(fields).Debugf("handling %s request", r.Method)


I think it makes sense to uncondtionnally write a debug log when the response is sent, even if everything goes well. That could help detect which request is causing an extra delay on shutdown for instance.

Yeah, that's a fair point.

I somewhat tried to avoid spamming too much (e.g. HEAD /_ping would produce 2 log entries); wondering if we should have some condition for that 🤔 WDYT?

OH! I also stumbled on this code; looks like we already log 5xx errors as an error-log, so I may want to align that with what we have here, and prevent this middleware from logging it as well;

moby/api/server/server.go

Lines 56 to 64 in b04246c

if err := handlerFunc(ctx, w, r, vars); err != nil {

statusCode := httpstatus.FromError(err)

if statusCode >= 500 {

log.G(ctx).Errorf("Handler for %s %s returned error: %v", r.Method, r.URL.Path, err)

}

_ = httputils.WriteJSON(w, statusCode, &types.ErrorResponse{

Message: err.Error(),

})

}

So current situation with this PR is that for internal server errors we'll be logging errors twice if the daemon runs with debug enabled;

Successful request;

INFO[2025-01-17T09:42:23.860442586Z] API listen on /var/run/docker.sock DEBU[2025-01-17T09:42:38.414440259Z] handling HEAD request method=HEAD module=api request-url=/_ping vars="map[]" DEBU[2025-01-17T09:42:38.415122676Z] handling GET request method=GET module=api request-url=/v1.47/version vars="map[version:1.47]"

Invalid parameter error:

DEBU[2025-01-17T09:48:36.261281425Z] handling HEAD request method=HEAD module=api request-url=/_ping vars="map[]" DEBU[2025-01-17T09:48:36.262166216Z] handling GET request method=GET module=api request-url=/v1.47/events vars="map[version:1.47]" DEBU[2025-01-17T09:48:36.262446133Z] error response for GET request error-response="some invalid parameter" method=GET module=api request-url=/v1.47/events status=400 vars="map[version:1.47]"

Internal server error request (logged both at debug level through the debug middleware and as error):

DEBU[2025-01-17T09:44:01.295508756Z] handling HEAD request method=HEAD module=api request-url=/_ping vars="map[]" DEBU[2025-01-17T09:44:01.296869589Z] handling GET request method=GET module=api request-url=/v1.47/events vars="map[version:1.47]" DEBU[2025-01-17T09:44:01.298480131Z] error response for GET request error-response="something bad happened" method=GET module=api request-url=/v1.47/events status=500 vars="map[version:1.47]" ERRO[2025-01-17T09:44:01.298567131Z] Handler for GET /v1.47/events returned error: something bad happened

I think that should be fine for now, but I'll add a comment to the code to reconsider what we want to do; I think as an improvement we could;

update the format used by Server.makeHTTPHandler to align with the debug-middleware and make the debug handler skip status >= 500

perhaps move the code together (either debug middleware or handler)

I decided to NOT de-duplicate the logs for now, because the debug-middleware use structured logs, which can help filtering, whereas the other one does not.

commit 1701bce updated the debug logs to use structured logs, and to include more information in the logs, such as the form-data used and the status-code, and combining them into a single log. However, for the status-code, we need to wait for the handler to do its thing and (ahum) this was staring me right in the face, and crossed my mind, but then I didn't act on it; the handler may take some time to run, and produce logs, which now means that our nice "handling request" log will be logged _after_ the request, which is obviously confusing. This patch splits the log into two; - a log entry when starting to handle the request - a log entry if a non-200 status is returned (assuming 200 status codes are less interesting to log). Before this patch: DEBU[2024-10-23T15:23:31.677184128Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=8180b03fa17f9783 status=200 traceID=a5dfa9b86445467889274145ad31bb9a vars="map[]" DEBU[2024-10-23T15:23:31.712833045Z] resolving host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 DEBU[2024-10-23T15:23:31.712883670Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:23:32.051728378Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:23:32.051830920Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 DEBU[2024-10-23T15:23:32.051909045Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:23:32.544987920Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:23:32.545112212Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 INFO[2024-10-23T15:23:32.545270087Z] trying next host error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 DEBU[2024-10-23T15:23:32.550666962Z] handling POST request error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=38286e48a07445ef status=404 traceID=3c01e6c2cf19cf82237fdd01c0294fb4 vars="map[version:1.47]" With this patch applied: DEBU[2024-10-23T15:18:18.876346178Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=7fd5eb011140f546 traceID=80ffd75a39de78a1f51ffda89fc4f227 vars="map[]" DEBU[2024-10-23T15:18:18.878006428Z] handling POST request method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]" DEBU[2024-10-23T15:18:18.919686136Z] resolving host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b DEBU[2024-10-23T15:18:18.919748094Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:18:19.258132303Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:18:19.258219803Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b DEBU[2024-10-23T15:18:19.258406886Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:18:19.755911762Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest" DEBU[2024-10-23T15:18:19.757501928Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b INFO[2024-10-23T15:18:19.757689387Z] trying next host error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b DEBU[2024-10-23T15:18:19.763826095Z] error response for POST request error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 status=404 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]" Signed-off-by: Sebastiaan van Stijn <[email protected]>

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

thaJeztah added this to the 28.0.0 milestone Oct 23, 2024

thaJeztah self-assigned this Oct 23, 2024

austinvazquez approved these changes Oct 24, 2024

View reviewed changes

akerouanton reviewed Oct 24, 2024

View reviewed changes

thaJeztah force-pushed the fix_debug_logs branch from 129dfb3 to 2433190 Compare January 13, 2025 13:31

thaJeztah force-pushed the fix_debug_logs branch from 2433190 to c817ea2 Compare January 17, 2025 10:00

vvoland approved these changes Jan 17, 2025

View reviewed changes

thaJeztah merged commit 58de8c7 into moby:master Jan 17, 2025

thaJeztah deleted the fix_debug_logs branch January 17, 2025 15:59

thaJeztah mentioned this pull request Apr 10, 2025

api/server/middleware: fix debug-logs missing form-data #49785

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

api/server/middleware: log before, not after the request#48740
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:fix_debug_logs

thaJeztah commented Oct 23, 2024

Uh oh!

akerouanton Oct 24, 2024

Uh oh!

thaJeztah Oct 24, 2024

Uh oh!

thaJeztah Oct 25, 2024

Uh oh!

thaJeztah Jan 17, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

	if err := handlerFunc(ctx, w, r, vars); err != nil {
	statusCode := httpstatus.FromError(err)
	if statusCode >= 500 {
	log.G(ctx).Errorf("Handler for %s %s returned error: %v", r.Method, r.URL.Path, err)
	}
	_ = httputils.WriteJSON(w, statusCode, &types.ErrorResponse{
	Message: err.Error(),
	})
	}

Conversation

thaJeztah commented Oct 23, 2024

Uh oh!

akerouanton Oct 24, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Oct 24, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Oct 25, 2024

Choose a reason for hiding this comment

Uh oh!

thaJeztah Jan 17, 2025

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants