`broken pipe` on fetches still #1204

cgwalters · 2025-03-14T14:10:40Z

We still see
ERROR Switching: Pulling: Importing: Parsing layer blob sha256:43373869bc293673e2dfc59a04c626501893eed1f7c1ec98004f2e7c0e41a245: failed to invoke method FinishPipe: failed to invoke method FinishPipe: write |1: broken pipe occasionally at least in CI runs though I haven't seen it myself personally/interactively.

Previously: ostreedev/ostree-rs-ext#657

cc also #963 where this seems to happen with zstd:chunked

The text was updated successfully, but these errors were encountered:

jeckersb · 2025-03-17T20:36:39Z

I've been running the previous reproducer in a loop for a while on the latest code, and for better or worse I don't see any broken pipes. So at the very least I don't think we've regressed on that particular fix.

Next I'll look at the zstd:chunked case and see how that plays into things.

jeckersb · 2025-03-18T14:56:01Z

Ok verified that ztd:chunked is consistently broken:

# ostree --repo=repo refs --delete ostree/container; ./bootc internals ostree-container image pull --quiet repo ostree-unverified-registry:quay.io/jeckersb/fedora:zstdchunked
layers already present: 0; layers needed: 1 (60.9 MB)
ERROR Importing: Parsing layer blob sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960: failed to invoke method FinishPipe: failed to invoke method FinishPipe: write |1: broken pipe

Aside, I wasted entirely too much time this morning trying to debug podman before I realized I was hitting containers/storage#2055. I had to remove podman-machine from the loop entirely and do the compression directly on my host with 64GB in order for it to actually push 😭

jeckersb · 2025-03-18T18:10:09Z

Debug output from skopeo, once I realized I had to rebuild ostree_ext pointing at git head for containers-image-proxy because we never released a new version that contains containers/containers-image-proxy-rs#70 (TODO!)

# ostree --repo=repo refs --delete ostree/container; CONTAINERS_IMAGE_PROXY_DEBUG=1 ./bootc internals ostree-container image pull --quiet --insecure-skip-tls-verification repo ostree-unverified-registry:localhost:5000/zstdchunked
DEBU[0000] Executing method Initialize
DEBU[0000] Using SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite
DEBU[0000] Sending reply: err=<nil> value=0.2.6 pipeid=0
DEBU[0000] Executing method OpenImage
DEBU[0000] Using registries.d directory /etc/containers/registries.d
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf"
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf.d/000-shortnames.conf"
DEBU[0000] Trying to access "localhost:5000/zstdchunked:latest"
DEBU[0000] Returning credentials for localhost:5000/zstdchunked from DockerAuthConfig
DEBU[0000]  No signature storage configuration found for localhost:5000/zstdchunked:latest, using built-in default file:///var/lib/containers/sigstore
DEBU[0000] Looking for TLS certificates and private keys in /etc/docker/certs.d/localhost:5000
DEBU[0000] GET https://localhost:5000/v2/
DEBU[0000] Ping https://localhost:5000/v2/ err Get "https://localhost:5000/v2/": http: server gave HTTP response to HTTPS client (&url.Error{Op:"Get", URL:"https://localhost:5000/v2/", Err:(*errors.errorString)(0x55fb097c1890)})
DEBU[0000] GET http://localhost:5000/v2/
DEBU[0000] Ping http://localhost:5000/v2/ status 200
DEBU[0000] GET http://localhost:5000/v2/zstdchunked/manifests/latest
DEBU[0000] Content-Type from manifest GET is "application/vnd.oci.image.manifest.v1+json"
DEBU[0000] IsRunningImageAllowed for image docker:localhost:5000/zstdchunked:latest
DEBU[0000]  Using default policy section
DEBU[0000]  Requirement 0: allowed
DEBU[0000] Overall: allowed
DEBU[0000] Sending reply: err=<nil> value=1 pipeid=0
DEBU[0000] Executing method GetManifest
DEBU[0000] Sending reply: err=<nil> value=sha256:7f82360ee7198cad6685c7429672d21540c268c54baf0d6a5e3a04743bdb1e9c pipeid=7
DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
DEBU[0000] Executing method GetFullConfig
DEBU[0000] Downloading /v2/zstdchunked/blobs/sha256:9f3411e5c4ba5e876f6ca8b3db96f536973b410a6a425ec30b9bd7445d984008
DEBU[0000] GET http://localhost:5000/v2/zstdchunked/blobs/sha256:9f3411e5c4ba5e876f6ca8b3db96f536973b410a6a425ec30b9bd7445d984008
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=7
DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
layers already present: 0; layers needed: 1 (60.9 MB)
DEBU[0000] Executing method GetLayerInfo
DEBU[0000] Sending reply: err=<nil> value=[{sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960 60947386 application/vnd.oci.image.layer.v1.tar+zstd}] pipeid=0
DEBU[0000] Executing method GetBlob
DEBU[0000] Downloading /v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] GET http://localhost:5000/v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] Sending reply: err=<nil> value=60947386 pipeid=7
DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=write |1: broken pipe value=<nil> pipeid=0
ERROR Importing: Parsing layer blob sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960: failed to invoke method FinishPipe: failed to invoke method FinishPipe: write |1: broken pipe

cgwalters · 2025-03-18T19:38:56Z

I'd probably add env RUST_LOG=debug here too (or maybe scoped to just the ostree-ext stack)

jeckersb · 2025-03-18T22:10:34Z

I'd probably add env RUST_LOG=debug here too (or maybe scoped to just the ostree-ext stack)

Here's the relevant bit which includes some thus-far unsuccessful attempts to fix this. Most notably I tried reapplying this patch because this feels like it's at least in the ballpark of the problem.

DEBUG get_blob: fetching blob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386
TRACE get_blob:impl_request: sending request GetBlob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386 self=ImageProxy method="GetBlob"
DEBU[0000] Executing method GetBlob
DEBU[0000] Downloading /v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] GET http://localhost:5000/v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] Sending reply: err=<nil> value=60947386 pipeid=7
TRACE get_blob:impl_request: completed request self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386 self=ImageProxy method="GetBlob"
TRACE write_tar: Spawned ostree child process
DEBUG write_tar: Waiting on child process
DEBUG finish_pipe: closing pipe self=ImageProxy pipeid=7
TRACE finish_pipe:impl_request: sending request FinishPipe self=ImageProxy pipeid=7 self=ImageProxy method="FinishPipe"
DEBUG Filtering tar; config=TarImportConfig { allow_nonusr: true, remap_factory_var: false }
DEBU[0000] Executing method FinishPipe
DEBU[0002] Completed pipe goroutine
DEBU[0002] Sending reply: err=write |1: broken pipe value=<nil> pipeid=0
TRACE write_tar: tar written successfully
TRACE join_fetch: worker Ok but driver Err
ERROR Importing: Parsing layer blob sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960: failed to invoke method FinishPipe: failed to invoke method FinishPipe: write |1: broken pipe

I'm thinking we might need to revisit ostreedev/ostree-rs-ext#672

cgwalters · 2025-03-19T00:18:04Z

I'm thinking we might need to revisit ostreedev/ostree-rs-ext#672

Right, seeing EPIPE on both sides which definitely implies we need to hold open one side of the pipe longer. It's really interesting though that zstd:chunked would somehow always trigger this.

jeckersb · 2025-03-19T16:14:25Z

So the problem seems to be in here:

bootc/ostree-ext/src/container/store.rs

Lines 930 to 957 in 244c1a0

    
           let (blob, driver, media_type) = super::unencapsulate::fetch_layer( 
        
               &proxy, 
        
               &proxy_img, 
        
               &import.manifest, 
        
               &layer.layer, 
        
               self.layer_byte_progress.as_ref(), 
        
               des_layers.as_ref(), 
        
               self.imgref.imgref.transport, 
        
           ) 
        
           .await?; 
        
           // An important aspect of this is that we SELinux label the derived layers using 
        
           // the base policy. 
        
           let opts = crate::tar::WriteTarOptions { 
        
               base: base_commit.clone(), 
        
               selinux: true, 
        
               allow_nonusr: root_is_transient, 
        
               retain_var: self.ostree_v2024_3, 
        
           }; 
        
           let r = crate::tar::write_tar( 
        
               &self.repo, 
        
               blob, 
        
               media_type, 
        
               layer.ostree_ref.as_str(), 
        
               Some(opts), 
        
           ); 
        
           let r = super::unencapsulate::join_fetch(r, driver) 
        
               .await 
        
               .with_context(|| format!("Parsing layer blob {}", layer.layer.digest()))?;

Specifically, we have blob which ultimately contains the read side of the pipe. That gets moved into write_tar and then into filter_tar_async, and then we drop it explicitly here:

bootc/ostree-ext/src/tar/write.rs

Line 382 in 244c1a0

drop(src);

The problem is that can get dropped before the join_fetch in import completes, which will close the read end out from the driver.

jeckersb · 2025-03-20T18:46:13Z

Worth noting that it's not all zstd:chunked images that are broken. I've created a FROM scratch container with just a /empty.txt file, and that pulls successfully.

Compare working from the empty image:

TRACE Processing layer ManifestLayerState { layer: Descriptor { media_type: ImageLayerZstd, digest: Digest { algorithm: Sha256, value: "sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a", split: 6 }, size: 556, urls: None, annotations: Some({"io.github.containers.zstd-chunked.manifest-position": "93:172:199:1", "io.github.containers.zstd-chunked.manifest-checksum": "sha256:8218f4d406a4acb2cf5304081a28bacd82dba32325f84093c86a6d6413527b4c", "io.github.containers.zstd-chunked.tarsplit-position": "273:211:2184"}), platform: None, artifact_type: None, data: None }, ostree_ref: "ostree/container/blob/sha256_3A_a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a", commit: None }
DEBUG fetching sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a
DEBUG get_blob: fetching blob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a", split: 6 } size=556
TRACE get_blob:impl_request: sending request GetBlob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a", split: 6 } size=556 self=ImageProxy method="GetBlob"
DEBU[0000] Executing method GetBlob
DEBU[0000] Downloading /v2/empty/blobs/sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a
DEBU[0000] GET http://localhost:5000/v2/empty/blobs/sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a
DEBU[0000] Sending reply: err=<nil> value=556 pipeid=7
TRACE get_blob:impl_request: completed request self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:a3a9c9811a925c13b0f88b0e110fb868cade9dfe9d00363b1f953879196c864a", split: 6 } size=556 self=ImageProxy method="GetBlob"
TRACE write_tar: Spawned ostree child process
DEBUG write_tar: Waiting on child process
DEBUG finish_pipe: closing pipe self=ImageProxy pipeid=7
TRACE finish_pipe:impl_request: sending request FinishPipe self=ImageProxy pipeid=7 self=ImageProxy method="FinishPipe"
DEBUG Filtering tar; config=TarImportConfig { allow_nonusr: true, remap_factory_var: false }
DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
TRACE finish_pipe:impl_request: completed request self=ImageProxy pipeid=7 self=ImageProxy method="FinishPipe"
TRACE write_tar: tar written successfully
DEBUG No filtered content
DEBUG close_image: closing image self=ImageProxy img=OpenedImage(1)
TRACE close_image:impl_request: sending request CloseImage self=ImageProxy img=OpenedImage(1) self=ImageProxy method="CloseImage"
DEBU[0000] Executing method CloseImage
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
TRACE close_image:impl_request: completed request self=ImageProxy img=OpenedImage(1) self=ImageProxy method="CloseImage"
DEBUG finalize: sent shutdown request self=ImageProxy
DEBU[0000] Executing method Shutdown
DEBU[0000] terminating
DEBUG finalize: proxy exited successfully self=ImageProxy
DEBUG finalized proxy
DEBUG labeling from merged tree
DEBUG Images found: 1
DEBUG Referenced layers: 1
DEBUG Found layers: 1
DEBUG pruned 0 layers
DEBUG Wrote merge commit e6f658a80fc94caf66fade933613213364ed44b4cf9b54d3b0a314d1c7a5c58e
Wrote: ostree-unverified-registry:localhost:5000/empty => e6f658a80fc94caf66fade933613213364ed44b4cf9b54d3b0a314d1c7a5c58e

To the failing image (local copy of quay.io/fedora/fedora:41 converted to zstd:chunked):

TRACE Processing layer ManifestLayerState { layer: Descriptor { media_type: ImageLayerZstd, digest: Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 }, size: 60947386, urls: None, annotations: Some({"io.github.containers.zstd-chunked.manifest-position": "60107260:525006:2674205:1", "io.github.containers.zstd-chunked.manifest-checksum": "sha256:2d91e30da6b167e0619c6306428822cd7cea333ac5127f31d96245b68d2eef6c", "io.github.containers.zstd-chunked.tarsplit-position": "60632274:315040:7787924"}), platform: None, artifact_type: None, data: None }, ostree_ref: "ostree/container/blob/sha256_3A_f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", commit: None }
DEBUG fetching sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBUG get_blob: fetching blob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386
TRACE get_blob:impl_request: sending request GetBlob self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386 self=ImageProxy method="GetBlob"
DEBU[0000] Executing method GetBlob
DEBU[0000] Downloading /v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] GET http://localhost:5000/v2/zstdchunked/blobs/sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960
DEBU[0000] Sending reply: err=<nil> value=60947386 pipeid=7
TRACE get_blob:impl_request: completed request self=ImageProxy img=OpenedImage(1) digest=Digest { algorithm: Sha256, value: "sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960", split: 6 } size=60947386 self=ImageProxy method="GetBlob"
TRACE write_tar: Spawned ostree child process
DEBUG write_tar: Waiting on child process
DEBUG finish_pipe: closing pipe self=ImageProxy pipeid=7
TRACE finish_pipe:impl_request: sending request FinishPipe self=ImageProxy pipeid=7 self=ImageProxy method="FinishPipe"
DEBUG Filtering tar; config=TarImportConfig { allow_nonusr: true, remap_factory_var: false }
DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=write |1: broken pipe value=<nil> pipeid=0
TRACE write_tar: tar written successfully
ERROR Importing: Parsing layer blob sha256:f5d3e8e90d538ff16bd4d8719929cbeebee96473d79529975ef602c472256960: failed to invoke method FinishPipe: failed to invoke method FinishPipe: write |1: broken pipe

jeckersb · 2025-03-20T18:56:19Z

I generated two more FROM scratch containers, populating with random data. One is 50MB, the other is 200MB.

The 50MB one pulls successfully.

The 200MB one fails.

🫠

cgwalters · 2025-03-20T20:01:05Z

curious if this reproduces if pulling from oci: or dir:
Does this reproduce if just using raw containers-image-proxy? We have an example fetcher in there

jeckersb · 2025-03-21T13:46:21Z

curious if this reproduces if pulling from oci: or dir:

Nope, doesn't seem to change anything.

Does this reproduce if just using raw containers-image-proxy? We have an example fetcher in there

We did this together live yesterday, but for the permanent record, no it doesn't reproduce with just containers-image-proxy.

jeckersb · 2025-03-21T14:15:23Z

Also another tidbit, I tried inserting a tokio::time::sleep(Duration::from_millis(1000)).await; immediately before we drop(src) in filter_tar_async, and that also doesn't help.

When it fails, it fails like:

DEBU[0000] Executing method FinishPipe
TRACE write_tar: Sleeping before dropping src
TRACE write_tar: After dropping src
DEBU[0001] Completed pipe goroutine
DEBU[0001] Sending reply: err=write |1: broken pipe value=<nil> pipeid=0
TRACE write_tar: tar written successfully

or

DEBU[0000] Executing method FinishPipe
TRACE write_tar: Sleeping before dropping src
DEBU[0001] Completed pipe goroutine
TRACE write_tar: After dropping src
DEBU[0001] Sending reply: err=write |1: broken pipe value=<nil> pipeid=0
TRACE write_tar: tar written successfully

When it works:

DEBU[0000] Executing method FinishPipe
DEBU[0000] Completed pipe goroutine
TRACE write_tar: Sleeping before dropping src
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
TRACE finish_pipe:impl_request: completed request self=ImageProxy pipeid=8 self=ImageProxy method="FinishPipe"
TRACE write_tar: After dropping src
TRACE write_tar: tar written successfully

or

DEBU[0000] Executing method FinishPipe
TRACE write_tar: Sleeping before dropping src
DEBU[0000] Completed pipe goroutine
DEBU[0000] Sending reply: err=<nil> value=<nil> pipeid=0
TRACE finish_pipe:impl_request: completed request self=ImageProxy pipeid=8 self=ImageProxy method="FinishPipe"
TRACE write_tar: After dropping src
TRACE write_tar: tar written successfully

I don't think that really helps clarify anything though.

jeckersb · 2025-03-25T14:34:01Z

I have a hunch, based on the following observations:

On the client side, we consume the entire tar stream and shove it into ostree successfully
On the proxy side, we're still blocked trying to write the entire blob over the pipe

Based on that, what I think is happening is that there's extra zstd metadata/skippable frames/etc at the very end of the stream. Then we get into a situation where there's some racing depending on order of futures or buffering or timing of how much we read out of the pipe. Sometimes, the zstd decompressor is able to slurp up the entire stream. Sometimes, we finish the blob future while there's still trailing data in the pipe, and this causes everything to break (or hang, if you don't drop the read end of the pipe prematurely).

jeckersb · 2025-03-25T15:08:11Z

That's 100% the problem, everything works after fixing that. I'll do some cleanup and post the PR shortly.

We need to read anything past the tar stream, otherwise we'll deadlock via skopeo in FinishPipe. Also remove the bit where we hold the pipe open longer, we shouldn't need to do that anymore because we've ensured we've read everything out of it by this point. Resolves: bootc-dev#1204 Signed-off-by: John Eckersberg <jeckersb@redhat.com>

cgwalters added area/client bug labels Mar 14, 2025

This was referenced Mar 14, 2025

lint: Add an api-base-directories lint #1200

Merged

test flakes tracker #579

Closed

cgwalters assigned jeckersb Mar 17, 2025

jeckersb mentioned this issue Mar 25, 2025

ostree-ext/docs: container image import flow diagram #1220

Merged

jeckersb mentioned this issue Mar 25, 2025

ostree-ext/filter_tar_async: flush decompressor stream #1228

Merged

cgwalters closed this as completed in #1228 Mar 25, 2025

cgwalters closed this as completed in c3e0ba6 Mar 25, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`broken pipe` on fetches still #1204

`broken pipe` on fetches still #1204

cgwalters commented Mar 14, 2025

jeckersb commented Mar 17, 2025

jeckersb commented Mar 18, 2025

jeckersb commented Mar 18, 2025

cgwalters commented Mar 18, 2025

jeckersb commented Mar 18, 2025

cgwalters commented Mar 19, 2025

jeckersb commented Mar 19, 2025

jeckersb commented Mar 20, 2025

jeckersb commented Mar 20, 2025

cgwalters commented Mar 20, 2025

jeckersb commented Mar 21, 2025

jeckersb commented Mar 21, 2025

jeckersb commented Mar 25, 2025

jeckersb commented Mar 25, 2025

broken pipe on fetches still #1204

broken pipe on fetches still #1204

Comments

cgwalters commented Mar 14, 2025

jeckersb commented Mar 17, 2025

jeckersb commented Mar 18, 2025

jeckersb commented Mar 18, 2025

cgwalters commented Mar 18, 2025

jeckersb commented Mar 18, 2025

cgwalters commented Mar 19, 2025

jeckersb commented Mar 19, 2025

jeckersb commented Mar 20, 2025

jeckersb commented Mar 20, 2025

cgwalters commented Mar 20, 2025

jeckersb commented Mar 21, 2025

jeckersb commented Mar 21, 2025

jeckersb commented Mar 25, 2025

jeckersb commented Mar 25, 2025

`broken pipe` on fetches still #1204

`broken pipe` on fetches still #1204