resolver/docker: fix confusing "trying next host" log

The resolver uses some log messages to indicate the next host will be used,
however it would print this message even if no next host was available
to try.

This patch changes the log messages to indicate the action taken, which is
either "fetch failed" or if there's no other hosts to try, "trying next host".

While updating, also slightly updated the logs for consistency.

Before this patch:

    DEBU[2024-10-23T20:49:29.640581097Z] resolving                                     host=registry-1.docker.io spanID=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6
    DEBU[2024-10-23T20:49:29.640632763Z] 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/27.3.1 go/go1.22.7 git-commit/41ca978 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(linux\\))" request.method=HEAD spanID=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T20:49:29.979613013Z] 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 20:49:29 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=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T20:49:29.979907138Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6
    DEBU[2024-10-23T20:49:29.980038430Z] 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/27.3.1 go/go1.22.7 git-commit/41ca978 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(linux\\))" request.method=HEAD spanID=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T20:49:30.466825972Z] 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 20:49:30 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\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T20:49:30.467056055Z] 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=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6
    INFO[2024-10-23T20:49:30.467273305Z] 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=6e2b9c871009cfd9 traceID=6c65b97879548fce4372faa8375d17e6

With this patch:

    DEBU[2024-10-23T21:17:53.487428843Z] resolving                                     host=registry-1.docker.io spanID=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db
    DEBU[2024-10-23T21:17:53.487498968Z] 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=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T21:17:53.832270052Z] 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 21:17:53 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=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T21:17:53.832843177Z] Unauthorized                                  header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db
    DEBU[2024-10-23T21:17:53.833364760Z] 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=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T21:17:54.345483219Z] 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 21:17:54 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=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
    DEBU[2024-10-23T21:17:54.345601386Z] 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=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db
    INFO[2024-10-23T21:17:54.345801761Z] fetch failed                                  error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=4a74f71b08243447 traceID=fc1177ef212d33617c883842b9b9b8db

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
This commit is contained in:
Sebastiaan van Stijn 2024-10-23 23:57:55 +02:00
parent cf86af6fcd
commit 700b90618d
No known key found for this signature in database
GPG Key ID: 76698F39D527CE8C

View File

@ -285,8 +285,16 @@ func (r *dockerResolver) Resolve(ctx context.Context, ref string) (string, ocisp
firstErr error
firstErrPriority int
)
nextHostOrFail := func(i int) string {
if i < len(hosts)-1 {
return "trying next host"
}
return "fetch failed"
}
for _, u := range paths {
for _, host := range hosts {
for i, host := range hosts {
ctx := log.WithLogger(ctx, log.G(ctx).WithField("host", host.Host))
req := base.request(host, http.MethodHead, u...)
@ -308,7 +316,7 @@ func (r *dockerResolver) Resolve(ctx context.Context, ref string) (string, ocisp
firstErr = err
firstErrPriority = 1
}
log.G(ctx).WithError(err).Info("trying next host")
log.G(ctx).WithError(err).Info(nextHostOrFail(i))
continue // try another host
}
resp.Body.Close() // don't care about body contents.
@ -319,7 +327,7 @@ func (r *dockerResolver) Resolve(ctx context.Context, ref string) (string, ocisp
firstErr = fmt.Errorf("%s: %w", ref, errdefs.ErrNotFound)
firstErrPriority = 2
}
log.G(ctx).Info("trying next host - response was http.StatusNotFound")
log.G(ctx).Infof("%s after status: %s", nextHostOrFail(i), resp.Status)
continue
}
if resp.StatusCode > 399 {
@ -327,7 +335,7 @@ func (r *dockerResolver) Resolve(ctx context.Context, ref string) (string, ocisp
firstErr = remoteerrors.NewUnexpectedStatusErr(resp)
firstErrPriority = 3
}
log.G(ctx).Infof("trying next host - response was %s", resp.Status)
log.G(ctx).Infof("%s after status: %s", nextHostOrFail(i), resp.Status)
continue // try another host
}
return "", ocispec.Descriptor{}, remoteerrors.NewUnexpectedStatusErr(resp)