mirror of
https://github.com/moby/moby.git
synced 2026-07-10 16:48:40 +00:00
c817ea2159
commit 1701bce9e0 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 <github@gone.nl>