bib-cp.md

manifest - finished successfully
cp: error writing '/output/image/./disk.raw': Resource temporarily unavailable
Traceback (most recent call last):
  File "/usr/bin/osbuild", line 33, in <module>
    sys.exit(load_entry_point('osbuild==119', 'console_scripts', 'osbuild')())
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/osbuild/main_cli.py", line 197, in osbuild_cli
    export(pid, output_directory, object_store, manifest)
  File "/usr/lib/python3.12/site-packages/osbuild/main_cli.py", line 62, in export
    obj.export(dest, skip_preserve_owner=skip_preserve_owner)
  File "/usr/lib/python3.12/site-packages/osbuild/objectstore.py", line 260, in export
    subprocess.run(cp_cmd, check=True)
  File "/usr/lib64/python3.12/subprocess.py", line 571, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['cp', '--reflink=auto', '-a', '--no-preserve=ownership', '/store/stage/uuid-bad2b75a0b7741ae8876fa001001acd7/data/tree/.', '/output/image']' returned non-zero exit status 1.
Error: cannot run osbuild: running osbuild failed: exit status 1
2024/06/05 17:33:25 error: cannot run osbuild: running osbuild failed: exit status 1
error: command exited with non-zero code `podman run --rm --privileged -v /var/lib/containers/storage:/var/lib/containers/storage --security-opt label=type:unconfined_t -v /var/home/walters/src/github/containers/bootc/target/testvm:/output localhost/bib --type raw --local localhost/bootc`: 1

What's super annoying here is that of course wrapping it in strace makes it work.

I'm suspecting this has something to do with 9p mounts; would be helpful to cross-compare with virtiofs. Would also be helpful to try patching podman to default to setting up virtiofs mounts too.

OK using perf trace, I see the failing syscall:

 98791.636 ( 0.075 ms): cp/12530 write(fd: 5, buf: 0x7fa4a397f000, count: 262144)                      = 262144
 98791.730 ( 0.048 ms): cp/12530 write(fd: 5, buf: 0x7fa4a397f000, count: 262144)                      = 110592
 98791.780 ( 0.028 ms): cp/12530 write(fd: 5, buf: 0x7fa4a399a000, count: 151552)                      = -1 EAGAIN (Resource temporarily unavailable)

We see a lot of successful writes, and then a "short write". Which implies to me this is something like a buffer filling up.

I can easily reproduce this now outside of bib with

# make a temporary large random file
$ dd if=/dev/urandom of=/tmp/disk bs=1M count=4024
$ cp /tmp/disk /output/disk

OK, I've narrowed in at least for me on this range:

A block size of 64k for dd works pretty reliably:

[root@afdc558c8fef output]# dd bs=64k status=progress if=/tmp/disk of=/output/disk
3784769536 bytes (3.8 GB, 3.5 GiB) copied, 2 s, 1.9 GB/s
64384+0 records in
64384+0 records out
4219469824 bytes (4.2 GB, 3.9 GiB) copied, 2.58506 s, 1.6 GB/s
[root@afdc558c8fef output]# dd bs=64k status=progress if=/tmp/disk of=/output/disk
3699179520 bytes (3.7 GB, 3.4 GiB) copied, 2 s, 1.8 GB/s
64384+0 records in
64384+0 records out
4219469824 bytes (4.2 GB, 3.9 GiB) copied, 2.6249 s, 1.6 GB/s
[root@afdc558c8fef output]# dd bs=64k status=progress if=/tmp/disk of=/output/disk
3630432256 bytes (3.6 GB, 3.4 GiB) copied, 2 s, 1.8 GB/s
64384+0 records in
64384+0 records out
4219469824 bytes (4.2 GB, 3.9 GiB) copied, 2.58852 s, 1.6 GB/s
[root@afdc558c8fef output]# dd bs=64k status=progress if=/tmp/disk of=/output/disk
3649830912 bytes (3.6 GB, 3.4 GiB) copied, 2 s, 1.8 GB/s
64384+0 records in
64384+0 records out
4219469824 bytes (4.2 GB, 3.9 GiB) copied, 2.64212 s, 1.6 GB/s
[root@afdc558c8fef output]# 

Yet going to 128k reliably dies:

[root@afdc558c8fef output]# dd bs=128k status=progress if=/tmp/disk of=/output/disk
dd: error writing '/output/disk': Resource temporarily unavailable
12941+0 records in
12940+0 records out
1696071680 bytes (1.7 GB, 1.6 GiB) copied, 1.07034 s, 1.6 GB/s
[root@afdc558c8fef output]# dd bs=128k status=progress if=/tmp/disk of=/output/disk
dd: error writing '/output/disk': Resource temporarily unavailable
12954+0 records in
12953+0 records out
1697775616 bytes (1.7 GB, 1.6 GiB) copied, 1.08184 s, 1.6 GB/s
[root@afdc558c8fef output]# dd bs=128k status=progress if=/tmp/disk of=/output/disk
dd: error writing '/output/disk': Resource temporarily unavailable
11410+0 records in
11409+0 records out
1495400448 bytes (1.5 GB, 1.4 GiB) copied, 1.02551 s, 1.5 GB/s
[root@afdc558c8fef output]# 

Using oflag=direct is much slower, but works reliably.

xref coreos/coreos-assembler#1812

xref containers/podman#22920