VCH appears to pull 5 times manifest from Harbor when I issue "docker pull", it blocks docker pull

[reasonerjt]

~# docker --tlsverify=false info
....
Server Version: v1.1.0-rc3-12824-a85701d
Storage Driver: vSphere Integrated Containers v1.1.0-rc3-12824-a85701d Backend Engine
VolumeStores: default
vSphere Integrated Containers v1.1.0-rc3-12824-a85701d Backend Engine: RUNNING
....

When I issue docker pull 10.160.247.138/default-project/hello-world:signed via a vanilla docker the requests look like this:

Aug  8 09:01:36 172.18.0.1 proxy[399]: 10.112.122.203 - "GET /v2/ HTTP/1.1" 401 87 "-" "docker/17.03.1-ce go/go1.7.5 git-commit/c6d412e kernel/3.13.0-24-generic os/linux arch/amd64 UpstreamClient(Docker-Client/17.03.1-ce \x5C(linux\x5C))" 0.007 0.007 .
Aug  8 09:01:37 172.18.0.1 proxy[399]: 10.112.122.203 - "GET /service/token?account=administrator%40vsphere.local&scope=repository%3Adefault-project%2Fhello-world%3Apull&service=harbor-registry HTTP/1.1" 200 1001 "-" "docker/17.03.1-ce go/go1.7.5 git-commit/c6d412e kernel/3.13.0-24-generic os/linux arch/amd64 UpstreamClient(Docker-Client/17.03.1-ce \x5C(linux\x5C))" 0.504 0.504 .
Aug  8 09:01:38 172.18.0.1 proxy[399]: 10.112.122.203 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" 200 730 "-" "docker/17.03.1-ce go/go1.7.5 git-commit/c6d412e kernel/3.13.0-24-generic os/linux arch/amd64 UpstreamClient(Docker-Client/17.03.1-ce \x5C(linux\x5C))" 0.032 0.032 .

However when I issue the same command against a VCH, it failed:

~# docker --tlsverify=false pull 10.160.247.138/default-project/hello-world:signed
signed: Pulling from default-project/hello-world
Error while pulling image manifest: Unexpected http code: 412, URL: https://10.160.247.138/v2/default-project/hello-world/manifests/signed

And the requests look like this:

Aug  8 11:53:01 172.18.0.1 proxy[399]: 10.162.10.142 - "HEAD /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 401 0 "-" "Go-http-client/1.1" 0.010 0.010 .
Aug  8 11:53:01 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /service/token?scope=repository%3Adefault-project%2Fhello-world%3Apull&service=harbor-registry HTTP/1.1" "-" 200 999 "-" "vic/v1.1.0-rc3" 0.661 0.661 .
Aug  8 11:53:02 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "application/vnd.docker.distribution.manifest.v2+json" 200 730 "-" "vic/v1.1.0-rc3" 0.142 0.142 .
Aug  8 11:53:02 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 412 119 "-" "vic/v1.1.0-rc3" 0.057 0.057 .
Aug  8 11:53:07 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 412 119 "-" "vic/v1.1.0-rc3" 0.032 0.032 .
Aug  8 11:53:17 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 412 119 "-" "vic/v1.1.0-rc3" 0.045 0.045 .
Aug  8 11:53:32 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 412 119 "-" "vic/v1.1.0-rc3" 0.028 0.028 .
Aug  8 11:53:52 172.18.0.1 proxy[399]: 10.162.10.142 - "GET /v2/default-project/hello-world/manifests/signed HTTP/1.1" "-" 412 119 "-" "vic/v1.1.0-rc3" 0.038 0.038 .

Note only the first request has header "application/vnd.docker.distribution.manifest.v2+json"
The problem is that it appears VCH keep sending request after receiving the 200.
And Harbor will use the v2 digest of image to match the signature and vulnerability data of an image, when the header is not set the digest returned by Registry is incorrect, probably v1.

Hence the "project level content trust" and "prevent pulling vulnerable image" works with vanilla docker but failed in the integration with VCH.

[reasonerjt]

logs.zip

Uploading log bundle.

[hickeng]

Looking at the timestamps it's overtly performing a retry/backoff increasing by 5s each time, meaning this loop: https://github.com/vmware/vic/blob/master/pkg/fetcher/fetcher.go#L172
If we have the docker-personality log and VCH is configured with debug logging then we'll have a record of each of the errors, otherwise we will only have a record of the last.

[andrewtchin]

This was done using this OVA https://storage.googleapis.com/vic-product-ova-builds/vic-4efc2f2e-dev.ova

[reasonerjt]

logs-debug.zip
attaching log bundle after enabling debug

[hickeng]

This HTTP 412 is the cause of the retry from our side - this is while pulling the v1 manifest:

Aug  8 2017 10:55:17.037Z INFO  Unexpected http code: 412, URL: https://10.160.247.138/v2/default-project/hello-world/manifests/latest

Other items of note:

Probably introduced by the Admiral integration - they almost always coming in clusters of 3, with two basically concurrent and then a third after some delay. I'm assuming for now this relates to whatever is pulling.
Regardless this should be squashed as it's misleading to warn about it and will be the most common result:

• change log severity based on whether error is ErrConfigNotModified or not

Aug  8 2017 10:14:37.329Z WARN  error getting config from source: config not modified
Aug  8 2017 10:14:37.388Z WARN  error getting config from source: config not modified
Aug  8 2017 10:18:26.232Z WARN  error getting config from source: config not modified

Access denied errors should be self explanatory - this is a problem only if we should have been able to access the registry at this point - unknown without more context.
@reasonerjt can you confirm that there was testing occurring that should have rejected the registry?

Aug  8 2017 10:18:26.232Z ERROR Access denied to unauthorized registry (10.160.247.138) while VCH is in whitelist mode
Aug  8 2017 10:18:29.361Z WARN  error getting config from source: config not modified
Aug  8 2017 10:18:29.361Z ERROR Access denied to unauthorized registry (10.160.247.138) while VCH is in whitelist mode
Aug  8 2017 10:18:41.161Z WARN  error getting config from source: config not modified
Aug  8 2017 10:18:49.392Z WARN  error getting config from source: config not modified
Aug  8 2017 10:18:49.392Z ERROR Access denied to unauthorized registry (10.160.247.138) while VCH is in whitelist mode
Aug  8 2017 10:19:07.215Z WARN  error getting config from source: config not modified
Aug  8 2017 10:19:13.128Z WARN  error getting config from source: config not modified
Aug  8 2017 10:19:13.128Z ERROR Access denied to unauthorized registry (10.160.247.138) while VCH is in whitelist mode
Aug  8 2017 10:19:18.168Z WARN  error getting config from source: config not modified
Aug  8 2017 10:19:18.168Z ERROR Access denied to unauthorized registry (10.160.247.138) while VCH is in whitelist mode

This is a problem - either the error message should not be an error (if the registry is configured as insecure and there'll be a fallback), or the registry is misconfigured.
@reasonerjt Do you know why this is occurring? It seems like an error to ever be served a certificate configured for 127.0.0.1.

Aug  8 2017 10:50:27.880Z ERROR Error while pulling image: Head https://10.112.122.21/v2/: x509: certificate is valid for 127.0.0.1, not 10.112.122.21

[reasonerjt]

@hickeng I can confirm only the 412 is relevant, other errors are due to misconfigurations.

I have discussed with @chengwang86 , we believe the root cause is VCH trying to pull v1 manifest, while vanilla docker only pulls v2 manifest.

[chengwang86]

Chatted with @reasonerjt . Here is our understanding of this issue:

In vic engine, we pull the image manifest twice:

• For the first time, we pull manifestSchemaV2 --- succeeded with 200
• For the second time, we pull manifestSchemaV1 --- failed with 412 and then retried (hence we see 6 GET request for manifest in the original post)
  • this is due to our legacy code that we need to construct the image config out of manifestSchemaV1
  • however, vanilla docker only pulls manifestSchemaV2 if it succeeds

At harbor side, for project level content trust,

• harbor only supports image pull for schemaV2. So the first request succeeded
• when receiving request for schemaV1, harbor obtained the image digest from the registry and then compares this digest against the one stored in content trust. However, the one in content trust is based on schemaV2. So there is a mismatch between the two digests. And harbor returned the 412 status code to vic.

@hickeng @jzt @sflxn

[sflxn]

Harbor will fix this on their side by adding support for schema 1 for content trust.

We will add schema 2 pull support in VIC engine in the future. #5963