`broken pipe` on fetches still

[cgwalters]

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

[jeckersb]

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]

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]

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]

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

[jeckersb]

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]

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]

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]

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]

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]

• 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