Watchtower: Log "Spam": "Could not do a head request

[fkrauthan]

Describe the bug
I recently updated to the latest watchtower version. But now I seem to get spammed with the error message:

Could not do a head request, falling back to regular pull.

which gets logged as well as creates an email notification every time.

To Reproduce
Steps to reproduce the behavior:

1. Updated watchtower to latest image
2. Deploy a container from a gitlab hosted registry
3. Let it run
4. Monitor logs and emails

Expected behavior
Ether a way to disable email notifications in case of this error. Or a fix for why the HEAD request is failing.

Environment

• Platform: Ubuntu (Linux)
• Architecture: x86_64
• Docker version: 19.03.13, build 4484c46d9d

Logs from running watchtower with the --debug option

2020-12-20T22:04:01Z [I] Running a one time update.
2020-12-20T22:04:01Z [D] Checking containers for updated images
2020-12-20T22:04:01Z [D] Retrieving running containers
2020-12-20T22:04:01Z [D] Trying to load authentication credentials.
                         container: /play-for-today-website
                         image: registry.gitlab.com/***/website:latest
2020-12-20T22:04:01Z [D] Loaded auth credentials for user gitlab+deploy-token-32212, on registry registry.gitlab.com/***/website:latest, from file /config.json
2020-12-20T22:04:01Z [D] Got image name: registry.gitlab.com/***/website:latest
2020-12-20T22:04:01Z [D] Credentials loaded
2020-12-20T22:04:01Z [D] Checking if pull is needed
                         container: /play-for-today-website
                         image: registry.gitlab.com/***/website:latest
2020-12-20T22:04:01Z [D] Building challenge URL
                         URL: https://registry.gitlab.com/v2/
2020-12-20T22:04:02Z [D] Got response to challenge request
                         header: Bearer realm="https://gitlab.com/jwt/auth",service="container_registry"
                         status: 401 Unauthorized
2020-12-20T22:04:02Z [D] Checking challenge header content
                         realm: https://gitlab.com/jwt/auth
                         service: container_registry
2020-12-20T22:04:02Z [D] Setting scope for auth token
                         image: registry.gitlab.com/***/website
                         scope: repository:registry.gitlab.com/***/website:pull
2020-12-20T22:04:02Z [D] Credentials found.
                         credentials: ******
2020-12-20T22:04:02Z [D] Parsing image ref
                         host: registry.gitlab.com
                         image: cogindo/***/website
                         normalized: registry.gitlab.com/***/website:latest
                         tag: latest
2020-12-20T22:04:02Z [D] Doing a HEAD request to fetch a digest
                         url: https://registry.gitlab.com/v2/***/website/manifests/latest
2020-12-20T22:04:02Z [I] Could not do a head request, falling back to regular pull.
2020-12-20T22:04:02Z [D] Reason: registry responded to head request with 401
2020-12-20T22:04:02Z [D] Pulling image
                         container: /play-for-today-website
                         image: registry.gitlab.com/***/website:latest
2020-12-20T22:04:04Z [D] No new images found for /play-for-today-website

Additional context

The issue seem to happen only for the gitlab registry. Maybe that helps fixing it.

[github-actions[bot]]

Hi there! 👋🏼 As you're new to this repo, we'd like to suggest that you read our code of conduct as well as our contribution guidelines. Thanks a bunch for opening your first issue! 🙏

[eilandert]

i can confirm this, upgraded few hours back and getting spammed

[piksel]

Yeah, this is because Github Packages (not Github Container Registry) uses non-standard URLs for their images so it's not possible to normalize the names.
This shouldn't matter as neither the rate limits, nor the HEAD requests apply to Github Packages.
There definitely should be a way to opt out of HEAD-based checking for repos that does not conform to the OCI Distribution spec.

Edit: Saw that this was about GitLab and not Github. But the same thing applies. They also use a three-part URL, but it seems like you could omit the image name?

[eilandert]

Yeah, this is because Github Packages (not Github Container Registry) uses non-standard URLs for their images so it's not possible to normalize the names.
This shouldn't matter as neither the rate limits, nor the HEAD requests apply to Github Packages.
There definitely should be a way to opt out of HEAD-based checking for repos that does not conform to the OCI Distribution spec.

_Edit_: Saw that this was about Git_Lab_ and not Github. But the same thing applies. They also use a three-part URL, but it seems like you could omit the image name?

I have the issue on dockerhub, not github or gitlab. Or am I missing something?

I have no limits since I have a pro account on dockerhub, so I am good either way.
If it makes no difference, maybe it's a good idea to get rid of the spam message and move it to debug?

[jpayne-procella]

I'm not sure I understand this last comment. Watchtower upgraded itself on me today and ever since then I've been getting this log spam (to teams notification in my case). What am I supposed to be doing differently?

[fkrauthan]

@piksel Yeah my problem is less rate limiting (as you are correct at least so far they did not introduce anything like docker) as the amount of noice this (by the sounds of it expected) behaviour brings.

[piksel]

The reason for it being displayed is that it's warning a that it the check will count towards the rate limit (that it failed to do a rate-limit friendly check).

@eilandert That's odd, could you open a ticket with debug logs? That should not be happening for dockerhub.

Just moving it to debug is not ideal as for those that need the HEAD-based checking it's relevant if it stops working as it may lead to them getting rate limited. But it shouldn't be too difficult to just add some way to turn it off if it's not relevant.

[fkrauthan]

Maybe this can be ether an opt-in feature (e.g. specifying for which registry we want it). Or at least an opt-out feature (again should be configurable on a per registry level).

[eilandert]

@piksel

I see I got a authentication failed, thats strange. I replaced my full credentials with a token last week, ran it with debug and everything was fine.

Output of one docker (i removed the credentials)

2020-12-21T04:27:56+01 [D] Trying to load authentication credentials.
                           container: /nginx
                           image: index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
2020-12-21T04:27:56+01 [D] Loaded auth credentials for user eilandert, on registry index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest, from file /config.json
2020-12-21T04:27:56+01 [D] Got image name: index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
2020-12-21T04:27:56+01 [D] Credentials loaded
2020-12-21T04:27:56+01 [D] Checking if pull is needed
                           container: /nginx
                           image: index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
2020-12-21T04:27:56+01 [D] Building challenge URL
                           URL: https://index.docker.io/v2/
2020-12-21T04:27:57+01 [D] Got response to challenge request
                           header: Bearer realm=
                           https://auth.docker.io/token\",service: \"registry.docker.io\""
                           status: 401 Unauthorized
2020-12-21T04:27:57+01 [D] Checking challenge header content
                           realm: https://auth.docker.io/token
                           service: registry.docker.io
2020-12-21T04:27:57+01 [D] Setting scope for auth token
                           image: index.docker.io/eilandert/nginx-modsecurity3-pagespeed
                           scope: repository:index.docker.io/eilandert/nginx-modsecurity3-pagespeed:pull
2020-12-21T04:27:57+01 [D] Credentials found.
                           credentials: 
2020-12-21T04:27:57+01 [D] Parsing image ref
                           host: index.docker.io
                           image: eilandert/nginx-modsecurity3-pagespeed
                           normalized: docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
                           tag: latest
2020-12-21T04:27:57+01 [D] Doing a HEAD request to fetch a digest
                           url: https://index.docker.io/v2/eilandert/nginx-modsecurity3-pagespeed/manifests/latest
2020-12-21T04:27:57+01 [I] Could not do a head request, falling back to regular pull.
2020-12-21T04:27:57+01 [D] Reason: registry responded to head request with 401
2020-12-21T04:27:57+01 [D] Pulling image
                           container: /nginx
                           image: index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
2020-12-21T04:27:58+01 [D] No new images found for /nginx

[simskij]

@eilandert does it fail the head request for all containers/images or just some? any difference depending on whether it's a public or private image, for instance? would you mind showing us your docker run command or docker-compose.yml ?

[eilandert]

@eilandert does it fail the head request for all containers/images or just some? any difference depending on whether it's a public or private image, for instance? would you mind showing us your docker run command or docker-compose.yml ?

@simskij it fails for every image

Here is a part of my docker-compose, the container I pasted before and watchtower

version: '2.4'
services:
  nginx:
    container_name: nginx
    image: index.docker.io/eilandert/nginx-modsecurity3-pagespeed:latest
    stop_grace_period: 3s
    depends_on:
-removed-
    ports:
    - 80:80
    - 443:443
    restart: always
    volumes:
-removed-
    environment:
      - TZ=Europe/Amsterdam
    networks:
-removed-
    labels:
      - "com.centurylinklabs.watchtower.scope=myguard"

  watchtower:
    image: containrrr/watchtower
    container_name: watchtower
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
      - ./watchtower/config.json:/config.json
    networks:
-removed-
    environment:
      - TZ=Europe/Amsterdam
      - WATCHTOWER_DEBUG=true
      - WATCHTOWER_TRACE=true
    command: --interval 300 --scope myguard

[simskij]

Sorry to bother you with a lot of questions, @eilandert, but it really sounds like you've still got some issues with your credentials. 🤔

Would you mind diffing your docker config to the one you use for watchtower? Something along the lines of diff ~/.docker/config.json ./watchtower/config.json should probably do.

[piksel]

Also @fkrauthan you have masked out a key part to this issue, the image URL. If you don't want to post it here and it's more acceptable to do so, would you mind sending it to info at containrrr dot dev?

[eilandert]

@simskij
the only difference are the credentials,
in ~/.docker/config.json are my full credentials,
in ./watchtower/config.json I've put a dockerhub token, which worked fine until yesterday

I linked back to ~/.docker/config.json (with the full credentials) but the issue remains the same. I can push builds to dockerhub so the credentials must be working.

[eilandert]

@simskij same issue when I run watchtower anonymous

[deividaspetraitis]

Not sure is it related but I got same errors but with reason: registry responded to head request with 404

time="2020-12-21T14:03:51+02:00" level=debug msg="Got response to challenge request" header="Basic realm=\"Registry realm\"" status="401 Unauthorized"
time="2020-12-21T14:03:51+02:00" level=debug msg="Parsing image ref" host=docker.**** image=admin-api normalized="docker.****/admin-api:e03ce2e106ad37493d6eb8a1519ee0975e4e42ab" tag=e03ce2e106ad37493d6eb8a1519ee0975e4e42ab
time="2020-12-21T14:03:51+02:00" level=debug msg="Doing a HEAD request to fetch a digest" url="https://docker.****/v2/library/admin-api/manifests/e03ce2e106ad37493d6eb8a1519ee0975e4e42ab"
time="2020-12-21T14:03:51+02:00" level=info msg="Could not do a head request, falling back to regular pull."
time="2020-12-21T14:03:52+02:00" level=debug msg="Reason: registry responded to head request with 404"
time="2020-12-21T14:03:52+02:00" level=debug msg="Pulling image" container=/admin-api_1 image="docker.****/admin-api:e03ce2e106ad37493d6eb8a1519ee0975e4e42ab"
time="2020-12-21T14:03:52+02:00" level=debug msg="No new images found for /admin-api_1"

It seems request URL is not correct according to the reference it should be:
https://docker.****/v2/admin-api/manifests/e03ce2e106ad37493d6eb8a1519ee0975e4e42ab but not
https://docker.****/v2/library/admin-api/manifests/e03ce2e106ad37493d6eb8a1519ee0975e4e42ab

---

Edit 1: We're using self-hosted docker registry based on https://docs.docker.com/registry/

[piksel]

@deividaspetraitis what type of container registry is it you use?
It's kind of hard to tell when the relevant parts of the log are censored out, but I think it might be same problem, using a three-stage path to the image...

[deividaspetraitis]

@piksel sorry for not providing this information in my original comment. We're using self-hosted docker registry based on https://docs.docker.com/registry/

[piksel]

@deividaspetraitis is "library" part of your image ref?

[deividaspetraitis]

@piksel not really, I'm capable to pull image manually by issuing following query: docker pull docker.registry.local/admin-api:e03ce2e106ad37493d6eb8a1519ee0975e4e42ab and it works just fine, I might be wrong but it seems like Watchtower appends this prefix to the URL when sending HEAD request to obtain resource information.

[simskij]

@deividaspetraitis:

I might be wrong but it seems like Watchtower appends this prefix to the URL when sending HEAD request to obtain resource information.

You're totally correct in that observation! It does this for all images not stored under an org or user, as this is how "official images" are resolved. We could probably hotfix this so it only does this for dockerhub images. In the meantime, if you push the image as someorg/somerepo it should work with head requests as well.

And yes, as someone said previously, being able to opt out of head requests should likely be an option. Initially globally, but down the line even per repo or registry.

[piksel]

Okay, yeah it's the opposite problem. Because you only have a single segment it adds the library/ prefix as the first segment, since that is where the docker-library images are using.

[jpayne-procella]

time="2020-12-21T14:23:48Z" level=debug msg="Credentials found." credentials=XXXX
time="2020-12-21T14:23:48Z" level=debug msg="Parsing image ref" host=index.docker.io image=XXX/XXX normalized="docker.io/XXX/XXX:release" tag=release
time="2020-12-21T14:23:48Z" level=debug msg="Doing a HEAD request to fetch a digest" url="https://index.docker.io/v2/XXX/XXX/manifests/release"
time="2020-12-21T14:23:48Z" level=info msg="Could not do a head request, falling back to regular pull."
time="2020-12-21T14:23:48Z" level=debug msg="Reason: registry responded to head request with 401"

My credentials are correct (token based) and I'd rather bump into rate limits than get an alert every time this runs and gets a HEAD error.

[simskij]

v1.1.1 will begin to roll out quite soon. Could you please have a look again once it's updated?

@jpayne-procella: I get your point, but at the same time, we want watchtower to always use head requests for DockerHub, both for rate limit and for alleviating their servers from some unnecessary requests.

[jpayne-procella]

Sure... but there's a difference between always trying HEAD on dockerhub and spamming notifications every time it fails. Which is every time in my case.

[tkalus]

What about splitting the difference? Keep the HEAD check for _all_ containers/registries but selectively log.Debug() or log.Warning() based on the registry hostname?

[jpayne-procella]

so far so good for me.

[simskij]

@tkalus

What about splitting the difference? Keep the HEAD check for _all_ containers/registries but selectively log.Debug() or log.Warning() based on the registry hostname?

Yeah, that might be a decent compromise forward. 👍

@jpayne-procella

I totally get that it's annoying and I'm really sorry for any issues it may create for you. As always, these things need a little trim in, our initial tests, as well as people beta testing the latest-dev build, showed no signs of this being an issue.

We're trying to be swift and responsive when it comes to solving these issues. I'm still hoping the solution will be "getting it right" rather than suppressing log messages. If that fails, however, I'm more than open to proceed with @tkalus suggestion.

[fkrauthan]

@piksel I just send you the URL via email. I also noticed that the emails from watchtower I receive look like this:

2020-12-21 12:02:26 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:02:28 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:02:31 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:02:34 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:02:52 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:03:02 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:03:05 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:03:08 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:03:11 (info): Could not do a head request, falling back to regular pull. 
2020-12-21 12:03:21 (info): Could not do a head request, falling back to regular pull. 

It probably would be good to include the image name for the email and log output as currently the only way to find out which image failed is by starting watchtower in debug mode.

[eilandert]

Seems alright now! thanks

[simskij]

@fkrauthan and @jpayne-procella: did v1.1.2 improve the situation for y'all as well?

[tkalus]

Hey @simskij

I can confirm that I'm still seeing the non-actionable-because-HEAD-unsupported notification for Could not do a head request, falling back to regular pull while running v1.1.2.

Here's the lightly-redacted loglines I'm seeing:

watchtower    | time="2020-12-21T23:37:29Z" level=info msg="Could not do a head request, falling back to regular pull."
watchtower    | time="2020-12-21T23:37:29Z" level=debug msg="Reason: registry responded to head request with &{401 Unauthorized 401 HTTP/1.1 1 1 map[Content-Length:[160] Content-Type:[application/json] Date:[Mon, 21 Dec 2020 23:37:29 GMT] Docker-Distribution-Api-Version:[registry/2.0] Www-Authenticate:[Bearer realm=\"https://gitlab.com/jwt/auth\",service=\"container_registry\",scope=\"repository:<snip:gitlab_org>/<snip:gitlab_repo>:pull\",error=\"insufficient_scope\"] X-Content-Type-Options:[nosniff]] {} 160 [] false false map[] <snip>}"
watchtower    | time="2020-12-21T23:37:29Z" level=debug msg="Pulling image" container=/<snip:gitlab_repo> image="registry.gitlab.com/<snip:gitlab_org>/<snip:gitlab_repo>:latest"
watchtower    | time="2020-12-21T23:37:30Z" level=debug msg="No new images found for /<snip:gitlab_repo>"

[simskij]

Alright! Lets proceed with your suggestion then. 👍🏻 I'll have a look tomorrow. Thanks for letting me know!

[jpayne-procella]

@fkrauthan and @jpayne-procella: did v1.1.2 improve the situation for y'all as well?

yes - the noise has completely disappeared from my notifications. Thanks!

[fkrauthan]

Looks good now. Thank you very much for the fast fix.

[jwillmer]

I still get this message with the latest (10h old - 0ecb05bef26f) watchtower image. I'm using a private GitHub registry.

[simskij]

I still get this message with the latest (10h old - 0ecb05bef26f) watchtower image. I'm using a private GitHub registry.

Are you using GitHub Packages or ghcr.io?

[jwillmer]

@simskij sorry, I wanted to write GitLab registry. Nowadays all services have a registry so I got confused. Let me know if I can post any log output that might help you.

[yonisolo]

Hello, I got the same problem, until yesterday i was running on 1.0.3, after upgrading to 1.1.3, i got the same log
Could not do a head request, falling back to regular pull.
dowgrading solved the issue.

[simskij]

Hello, I got the same problem, until yesterday i was running on 1.0.3, after upgrading to 1.1.3, i got the same log
Could not do a head request, falling back to regular pull.
dowgrading solved the issue.

@yonisolo, I assume you're also on either GitHub Packages or GitLab? 😅

[yonisolo]

Hello, I got the same problem, until yesterday i was running on 1.0.3, after upgrading to 1.1.3, i got the same log
Could not do a head request, falling back to regular pull.
dowgrading solved the issue.

@yonisolo, I assume you're also on either GitHub Packages or GitLab? 😅

My bad, sorry, i'm pulling from a private repository, same than @deividaspetraitis
and i'm using the docker image containrrr/watchtower

thank you for your reply

[fkrauthan]

I just noticed that since today I am getting the log messages emailed again. Was there another release that reverted the fix?

[simskij]

Hey @fkrauthan!

v1.1.3, which is the current live version should have all the fixes. Although the PR provided by @tkalus will further improve things as it will push all failed HEAD request logs to debug except when the registry is DockerHub.

@yonisolo and @deividaspetraitis, this should improve things for you as well, given that the GitLab Registry hasn't implemented the HEAD option.

[fkrauthan]

Ok so it looks like that version 1.1.2 fixed the issue (I was not getting any emails about the HEAD request) and version 1.1.3 started triggering the emails again for the issue.

[devbots-lock-issue[bot]]

To avoid important communication to get lost in a closed issues no one monitors, I'll go ahead and lock this issue. If you want to continue the discussion, please open a new issue. Thank you! 🙏🏼

[simskij]

let's keep this open for a while longer 😅

[simskij]

v1.1.4 in CI now. Should be with you in an hour or so. Please keep the updates coming regarding whether you get spammed or not, as well as whether HEAD requests work (if you're on quay.io, dockerhub.com, or ghcr.io)