Buildah: Subsequent push failures

[kbaegis]

Description

Upon pushing multiple tags to a docker registry, any after the first fail.

Steps to reproduce the issue:

1. buildah bud for a dockerfile
2. buildah commit
3. buildah push <image> docker://<image>:tag1
4. buildah push <image> docker://<image>:tag2

Describe the results you received:

Getting image source signatures
Copying blob sha256:f637bb87f74f0710bea59badbff1240cddaa7c47a12656789829396349d82b00

0 B / 578.24 MiB [------------------------------------------------------------]
8 B / 578.24 MiB [>-----------------------------------------------------------]
512 B / 578.24 MiB [>------------------------------------------------------] 0s
Patch https://crucible.lab:4000/v2/oci/portagedir/blobs/uploads/ee903314-762d-4bdd-8f4c-e4ee585a4cd4?_state=ez4VTc9aem0iZ0biV_Ujr0XtKFz83gsO3g9jlnFhCrh7Ik5hbWUiOiJvY2kvcG9ydGFnZWRpciIsIlVVSUQiOiJlZTkwMzMxNC03NjJkLTRiZGQtOGY0Yy1lNGVlNTg1YTRjZDQiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMTgtMDgtMzFUMTM6NTg6NTIuNjg0OTkyNDA3WiJ9: open /var/lib/containers/storage/overlay/f637bb87f74f0710bea59badbff1240cddaa7c47a12656789829396349d82b00/merged/Manifest: no such file or directory

Describe the results you expected:

A successful push to the registry.

The ideal results would be that buildah notices that those blobs already exist on the registry and then just adds a tag. I've never seen that behavior, however, and it just pushes one copy of the blob for every tag I use.

Output of buildah version:

Version:         1.4-dev
Go Version:      go1.10.3
Image Spec:      1.0.0
Runtime Spec:    1.0.0
CNI Spec:        0.4.0
libcni Version:  v0.7.0-alpha1
Git Commit:      20b236a8
Built:           Fri Aug 31 13:53:03 2018
OS/Arch:         linux/amd64

Output of uname -a:

Linux bb08613bf569 4.17.0-gentoo #1 SMP Thu Jun 7 02:49:57 UTC 2018 x86_64 Intel(R) Xeon(R) CPU D-1587 @ 1.70GHz GenuineIntel GNU/Linux

Output of cat /etc/containers/storage.conf:

cat: /etc/containers/storage.conf: No such file or directory

[kbaegis]

Troubleshooting this issue, I restarted/reset my registry. That didn't seem to help.

What does work, as an unfortunate workaround:
buildah push <image> docker://<image>:tag1
buildah rmi --all
buildah pull <image>:tag1
buildah tag <image>:tag1 <image>:tag2
buildah push docker://<image>:tag2

Something about the current push mechanism is destructive and corrupting/deleting the blobs on upload to a docker registry. The bug/defect above is re-demonstrated after download+push:

buildah tag <image>:tag2 <image>:tag3
buildah push docker://<image>:tag3

Patch https://crucible.lab:4000/v2/oci/portagedir/blobs/uploads/8df16b2e-28db-4318-af55-c1cc26f99bc4?_state=L1C1MMtLfdjZiF2IzA1jg-xxYPiX0ZLTvijnGA_Wu1Z7Ik5hbWUiOiJvY2kvcG9ydGFnZWRpciIsIlVVSUQiOiI4ZGYxNmIyZS0yOGRiLTQzMTgtYWY1NS1jMWNjMjZmOTliYzQiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMTgtMDgtMzFUMTY6MDY6MzkuNzU2NzY2MjYxWiJ9: open /var/lib/containers/storage/overlay/5fcc61df1537dd1a88f0ace633c635d160ad582d1951bf93e872bdf55d888ab5/merged/Manifest: no such file or directory

[TomSweeneyRedHat]

@kbaegis thanks for the issue report. I'm setting up a test system now. Just to verify, did you pull the latest Buildah bits from GitHub upstream? We submitted a patch or two last evening US East Coast time that might address this.

[kbaegis]

Current commit: 347478cccd02bffc715cf2c9db4c9268cd9e97dd

[TomSweeneyRedHat]

Thanks for the info, @mtrmac or @nalind any thoughts?

[mtrmac]

I have no idea what is going on, this is something in c/storage.

Only a tiny comment on the workaround:

buildah push <image> docker://<image>:tag1
buildah rmi --all
buildah pull <image>:tag1
buildah tag <image>:tag1 <image>:tag2
buildah push docker://<image>:tag2

This should be easier (and notably faster):

buildah push <image> docker://<image>:tag1
skopeo copy docker://<image>:tag1 docker://<image>:tag2

[mtrmac]

The ideal results would be that buildah notices that those blobs already exist on the registry and then just adds a tag. I've never seen that behavior, however, and it just pushes one copy of the blob for every tag I use.

That indeed does not currently happen, I am working on making that possible.

[TomSweeneyRedHat]

@kbaegis This worked for me against quay.io and docker.io (see below). Were you pushing to a private registry? Or did I mess up the push?

[root@localhost tmp]# buildah push --creds="username:password" localhost/testing2 quay.io/tomsweeneyredhat/testing:fourth
Getting image source signatures
Copying blob sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c
 4.46 MiB / 4.46 MiB [======================================================] 3s
Copying blob sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef
 1.00 KiB / 1.00 KiB [======================================================] 2s
Copying blob sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef
 1.00 KiB / 1.00 KiB [======================================================] 1s
Copying config sha256:929e751226baf44687e8d5d718c248f271fef24cf7ce1389c84adddca3cf4953
 823 B / 823 B [============================================================] 1s
Writing manifest to image destination
Copying config sha256:929e751226baf44687e8d5d718c248f271fef24cf7ce1389c84adddca3cf4953
 0 B / 823 B [--------------------------------------------------------------] 0s
Writing manifest to image destination
Writing manifest to image destination
Storing signatures

[root@localhost tmp]# buildah push --creds="username:password" localhost/testing2 quay.io/tomsweeneyredhat/testing:third
Getting image source signatures
Copying blob sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c
 4.46 MiB / 4.46 MiB [======================================================] 2s
Copying blob sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef
 1.00 KiB / 1.00 KiB [======================================================] 1s
Copying blob sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef
 1.00 KiB / 1.00 KiB [======================================================] 1s
Copying config sha256:929e751226baf44687e8d5d718c248f271fef24cf7ce1389c84adddca3cf4953
 0 B / 823 B [--------------------------------------------------------------] 0s
Writing manifest to image destination
Copying config sha256:929e751226baf44687e8d5d718c248f271fef24cf7ce1389c84adddca3cf4953
 0 B / 823 B [--------------------------------------------------------------] 0s
Writing manifest to image destination
Writing manifest to image destination
Storing signatures

[kbaegis]

Huh. Yes, a private registry. I am using buildah inside a container with a docker runtime- which might be the difference:

Containers: 15
 Running: 12
 Paused: 0
 Stopped: 3
Images: 3362
Server Version: 18.06.0-ce
Storage Driver: btrfs
 Build Version: Btrfs v4.10.2
 Library Version: 102
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: d64c661f1d51c48782c9cec8fda7604785f93587
runc version: 69663f0bd4b60df09991c08812a60108003fa340
init version: fec3683b971d9c3ef73f284f176672c44b448662
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.17.0-gentoo
Operating System: Gentoo/Linux
OSType: linux
Architecture: x86_64
CPUs: 32
Total Memory: 125.9GiB
Name: crucible
ID: LM6K:6A6Y:NATB:6CUG:5YJA:T5YB:JOF5:GGZZ:QNP7:MR5F:QZ5C:55AO
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

[TomSweeneyRedHat]

Thanks, I'm seeing it now to a private registry too. What's interesting is I was having problems getting the registry to behave and after doing a push with docker of busybox, my second push of alpine failed with a busybox reference.... See below.

# docker run -d -p 5000:5000 registry:2

# docker tag busybox 127.0.0.1:5000/busybox

# docker push 127.0.0.1:5000/busybox
The push refers to a repository [127.0.0.1:5000/busybox]
f9d9e4e6e2f0: Pushed 
latest: digest: sha256:5e8e0509e829bb8f990249135a36e81a3ecbe94294e7a185cc14616e5fad96bd size: 527

# buildah pull alpine

# buildah push --tls-verify=false alpine 127.0.0.1:5000/my-alpine:first
Getting image source signatures
Copying blob sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c
 4.46 MiB / 4.46 MiB [======================================================] 0s
Copying config sha256:11cd0b38bc3ceb958ffb2f9bd70be3fb317ce7d255c8a4c3f4af30e298aa1aab
 1.48 KiB / 1.48 KiB [======================================================] 0s
Writing manifest to image destination
Storing signatures

# # buildah --debug push --tls-verify=false alpine 127.0.0.1:5000/my-alpine:second
DEBU[0000] [graphdriver] trying provided driver "overlay" 
DEBU[0000] overlay: override_kernelcheck=true           
DEBU[0000] overlay test mount with multiple lowers succeeded 
DEBU[0000] backingFs=xfs, projectQuotaSupported=false, useNativeDiff=true 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,overlay.override_kernel_check=true]localhost/alpine:latest" 
DEBU[0000] reference "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,overlay.override_kernel_check=true]localhost/alpine:latest" does not resolve to an image ID 
DEBU[0000] error locating image "localhost/alpine": image not known 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,overlay.override_kernel_check=true]docker.io/library/alpine:latest" 
DEBU[0000] Using registries.d directory /etc/containers/registries.d for sigstore configuration 
DEBU[0000]  Using "default-docker" configuration        
DEBU[0000]   Using file:///var/lib/atomic/sigstore      
DEBU[0000] Looking for TLS certificates and private keys in /etc/docker/certs.d/127.0.0.1:5000 
DEBU[0000] IsRunningImageAllowed for image containers-storage:[overlay@/var/lib/containers/storage]docker.io/library/alpine:latest@11cd0b38bc3ceb958ffb2f9bd70be3fb317ce7d255c8a4c3f4af30e298aa1aab 
DEBU[0000]  Using default policy section                
DEBU[0000]  Requirement 0: allowed                      
DEBU[0000] Overall: allowed                             
Getting image source signatures
DEBU[0000] Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json] 
DEBU[0000] ... will first try using the original manifest unmodified 
DEBU[0000] Checking /v2/my-alpine/blobs/sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c 
DEBU[0000] GET https://127.0.0.1:5000/v2/               
DEBU[0000] Ping https://127.0.0.1:5000/v2/ err &url.Error{Op:"Get", URL:"https://127.0.0.1:5000/v2/", Err:(*errors.errorString)(0xc420146be0)} 
DEBU[0000] GET http://127.0.0.1:5000/v2/                
DEBU[0000] Ping http://127.0.0.1:5000/v2/ status 200    
DEBU[0000] HEAD http://127.0.0.1:5000/v2/my-alpine/blobs/sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c 
DEBU[0000] ... not present                              
Copying blob sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c
DEBU[0000] exporting filesystem layer "73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c" without compression for blob "sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c" 
DEBU[0000] No compression detected                      
 0 B / 4.46 MiB [--------------------------------------------------------------]DEBU[0000] Compressing blob on the fly                  
DEBU[0000] Uploading /v2/my-alpine/blobs/uploads/       
DEBU[0000] POST http://127.0.0.1:5000/v2/my-alpine/blobs/uploads/ 
DEBU[0000] PATCH http://127.0.0.1:5000/v2/my-alpine/blobs/uploads/63b25493-1106-4f76-bd54-6ca65413c030?_state=HLRBKeCfloQ4GWh2ANJonz_rAD3eY3qlK_tJhIPinoZ7Ik5hbWUiOiJteS1hbHBpbmUiLCJVVUlEIjoiNjNiMjU0OTMtMTEwNi00Zjc2LWJkNTQtNmNhNjU0MTNjMDMwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDE4LTA4LTMxVDIwOjM1OjI5LjU4OTg1Njc4OVoifQ%3D%3D 
DEBU[0000] Error uploading layer chunked, response (*http.Response)(nil) 
 3.00 KiB / 4.46 MiB [>-----------------------------------------------------] 0s
ERRO[0000] Patch http://127.0.0.1:5000/v2/my-alpine/blobs/uploads/63b25493-1106-4f76-bd54-6ca65413c030?_state=HLRBKeCfloQ4GWh2ANJonz_rAD3eY3qlK_tJhIPinoZ7Ik5hbWUiOiJteS1hbHBpbmUiLCJVVUlEIjoiNjNiMjU0OTMtMTEwNi00Zjc2LWJkNTQtNmNhNjU0MTNjMDMwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDE4LTA4LTMxVDIwOjM1OjI5LjU4OTg1Njc4OVoifQ%!D(MISSING)%!D(MISSING): open /var/lib/containers/storage/overlay/73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c/merged/bin/busybox: no such file or directory 

[kbaegis]

So it looks like buildah is trying to do a chunked upload, but might not be using a consistent UUID. I'm pretty new to all of this, so probably not the best to field it. That having been said, this looks troubling:
?_state=...%3D%3D
versus
?_state=...%!D(MISSING)%!D(MISSING): ....

1) Does a generic docker registry know how to handle the ?_state=* statement appended to the UUID? I'm not seeing that referenced here: https://docs.docker.com/registry/spec/api/#pushing-an-image.
2) What does buildah actually do for a chunked upload here? Is it altering the contents of the directory or spinning up a new copy and mounting it for validation purposes?

Best I can tell, buildah is mapping the container to the filesystem to validate it but choking on the uuid+state, which I'm not sure the registry knows how to interpret.

I'm not really a good resource for this though. :)

[rhatdan]

I saw something similar to this while playing last week. I was not able to push a second time to a
dir:/tmp/image
directory.

It almost seems that something is being modified in container/storage on the push.

# buildah push docker.io/library/alpine:latest dir:/tmp/dan
Getting image source signatures
Copying blob sha256:73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c
 3.00 KiB / 4.46 MiB [>-----------------------------------------------------] 0s
error pushing image "docker.io/library/alpine:latest" to "dir:/tmp/dan": error copying layers and metadata: Error writing blob: open /var/lib/containers/storage/overlay/73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c/merged/bin/busybox: no such file or directory

What is weird is the file is still there.

# ctr=$(buildah from docker.io/library/alpine:latest)
# mnt=$(buildah mount $ctr)
# ls -l $mnt/bin/busybox
-rwxr-xr-x. 1 root root 796312 May 30 06:46 /var/lib/containers/storage/overlay/fc28213940301dc3664236d2e2dd5b4599acafd186fd08138e9ecfce8724b505/merged/bin/busybox

[rhatdan]

@mtrmac Any ideas?

[kbaegis]

I really hope it's not altering the contents of the container. That would invalidate the sha hashing and so libpod/buildah would be pointing to an invalid object reference.

[mtrmac]

@mtrmac Any ideas?

None really; I know pretty much nothing about how overlay and storage drivers work. This is all internal state of c/storage.

One thing that might have been worth noticing in the original report:

Storage Driver: btrfs

is probably not the most tested one — well, except that the two of you now report reproducing this, and @TomSweeneyRedHat explicitly says “overlay”.

[mtrmac]

error pushing image "docker.io/library/alpine:latest" to "dir:/tmp/dan": error copying layers and metadata: Error writing blob: open /var/lib/containers/storage/overlay/73046094a9b835e443af1a9d736fcfc11a994107500e474d0abf399499ed280c/merged/bin/busybox: no such file or directory

What is weird is the file is still there.

/var/lib/containers/storage/overlay/fc28213940301dc3664236d2e2dd5b4599acafd186fd08138e9ecfce8724b505/merged/bin/busybox

The paths differ, though - does the file exist exactly at the failing path?

[mtrmac]

That having been said, this looks troubling:

?_state=...%3D%3D

versus

?_state=...%!D(MISSING)%!D(MISSING): ....

That’s just a formatting artifact during error reporting. https://github.com/projectatomic/buildah/blob/cff8d38a47353ea6e77cb434e73d0fa90acdc6cd/cmd/buildah/main.go#L123 should be Error, not Errorf.

Does a generic docker registry know how to handle the ?_state=* statement appended to the UUID? I'm not seeing that referenced here: https://docs.docker.com/registry/spec/api/#pushing-an-image.

That

Though the URI format (/v2//blobs/uploads/) for the Location header is specified,

is a lie; the ?_state= part is returned by the server, and only returned to it. c/image did not invent the contents:

clients should treat it as an opaque url and should never try to assemble it.

[mtrmac]

What does buildah actually do for a chunked upload here? Is it altering the contents of the directory or spinning up a new copy and mounting it for validation purposes?
Best I can tell, buildah is mapping the container to the filesystem to validate it but choking on the uuid+state, which I'm not sure the registry knows how to interpret.

The UUID/state is purely registry-side state, with no relationship to the contents of the uploaded data (which is being generated ~on the fly and may, in principle, not have its digests and the like known at this point yet). Anything happening at the registry-side is irrelevant to this failure.

This is all local, buildah / containers/storage unable to retrieve its own locally-managed data (export a layer as a tarball, to be more precise). The layer tarball hasn’t even been created, so we can’t even get to the point of asking whether it has been created correctly.

[kbaegis]

Thanks for the clarifications. I figured that blobs would consistently generate the same UUID if the contents and timestamp were identical and that was used to detect and prevent duplication.

Does this mean that when I push two tags of the same image it's taking up twice the space?

I had assumed there's a mechanism to prevent redundant blobs and superfluous pushes in the registry code. Is that typically the responsibility of the client to check before pushing? I suppose I need to look into this further. Thanks again for pointing me in the right direction. Docker registries always seemed kind of kludgy to me.

[mtrmac]

I figured that blobs would consistently generate the same UUID if the contents and timestamp were identical and that was used to detect and prevent duplication.

No, the UUIDs are entirely random for each blob upload.

Does this mean that when I push two tags of the same image it's taking up twice the space?

No; (until the optimizations I am working on happen) each blob is uploaded to the registry in full, but the registry notices the duplication and removes the uploaded duplicate. At most, the extra space is the size of the largest layer, and only during the push.

[steveb]

I'm seeing the same issue doing a skopeo copy containers-storage:... docker://... on a buildah built image.

My first thought was this was related to doing concurrent buildah calls on different images, but I'll keep testing and attempt to come up with a reproducer.

[kbaegis]

The skopeo copy solution seems to work fine for me. I added a --disable-registry flag to reagent (https://github.com/kbaegis/reagent) and manually pushing the first image and then doing a skopeo copy docker://<image>:<tag1> docker://<image>:<tag2> works fine.

I'll just need a little refactoring to how I'm tracking image tags to make that work out for me.