Another AB-INT, probably affecting only fedora43. Contrary to other fedora43 AB-INT, it looks like this one is not happening in all fedora43 builds. I believe only one occurrence has been seen so far. 2026-03-11 02:07:21,969 - oe-selftest - INFO - wic.Wic2.test_expand_mbr_image (subunit.RemotedTestCase) 2026-03-11 02:07:21,970 - oe-selftest - INFO - ... FAIL ... 2026-03-11 02:07:21,970 - oe-selftest - INFO - 11: 31/53 608/672 (36.31s) (2 failed) (wic.Wic2.test_expand_mbr_image) 2026-03-11 02:07:21,970 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/srv/pokybuild/yocto-worker/oe-selftest-fedora/build/layers/openembedded-core/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) File "/srv/pokybuild/yocto-worker/oe-selftest-fedora/build/layers/openembedded-core/meta/lib/oeqa/selftest/cases/wic.py", line 1842, in test_expand_mbr_image runCmd(cmd) ~~~~~~^^^^^ File "/srv/pokybuild/yocto-worker/oe-selftest-fedora/build/layers/openembedded-core/meta/lib/oeqa/utils/commands.py", line 214, in runCmd raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output)) AssertionError: Command 'wic write -n /srv/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3856264/tmp/work/x86-64-v3-poky-linux/wic-tools/1.0/recipe-sysroot-native --expand 1:0 /srv/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3856264/tmp/deploy/images/qemux86-64/core-image-minimal-qemux86-64.rootfs.wic /srv/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3856264/tmp/deploy/images/qemux86-64/tmpxrc_vfvo.wic.exp' returned non-zero exit status 1: INFO: copying unchanged partition 1 INFO: resizing ext partition 2 ERROR: _exec_cmd: /srv/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3856264/tmp/work/x86-64-v3-poky-linux/wic-tools/1.0/recipe-sysroot-native/sbin/e2fsck -pf /tmp/wic-part2-myv68msn returned '1' instead of 0 output: platform: Entry 'var' in / (2) has deleted/unused inode 734. CLEARED. platform: Entry 'games' in /usr (394) has deleted/unused inode 495. CLEARED. platform: Entry 'include' in /usr (394) has deleted/unused inode 496. CLEARED. platform: Entry 'lib' in /usr (394) has deleted/unused inode 497. CLEARED. ... platform: Entry 'unzip' in /usr/bin (395) has deleted/unused inode 478. CLEARED. platform: Inode 2 ref count is 18, should be 17. FIXED. platform: Inode 394 ref count is 9, should be 3. FIXED. platform: 444/6888 files (1.4% non-contiguous), 29756/55012 blocks And we have a similar error a bit later: 2026-03-11 02:24:42,330 - oe-selftest - INFO - wic.ModifyTests.test_wic_cp_ext (subunit.RemotedTestCase) 2026-03-11 02:24:42,330 - oe-selftest - INFO - ... FAIL ... 2026-03-11 02:24:42,332 - oe-selftest - INFO - 9: 73/77 663/672 (33.99s) (0 failed) (wic.ModifyTests.test_wic_cp_ext) 2026-03-11 02:24:42,339 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/srv/pokybuild/yocto-worker/oe-selftest-fedora/build/layers/openembedded-core/meta/lib/oeqa/selftest/cases/wic.py", line 2139, in test_wic_cp_ext self.assertNotIn("Ext2 inode is not a directory", result.output, ~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ msg="Regression detected (inode not a directory). Output:\n%s" % result.output) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib64/python3.14/unittest/case.py", line 1199, in assertNotIn self.fail(self._formatMessage(msg, standardMsg)) ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib64/python3.14/unittest/case.py", line 750, in fail raise self.failureException(msg) AssertionError: 'Ext2 inode is not a directory' unexpectedly found in 'debugfs 1.47.3 (8-Jul-2025)\n-l: Ext2 inode is not a directory' : Regression detected (inode not a directory). Output: debugfs 1.47.3 (8-Jul-2025) -l: Ext2 inode is not a directory oe-selftest-fedora fedora43-vk-2 master completed at 2026-03-11 02:32:31+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/48/builds/3267/steps/15/logs/stdio
Trevor, Do you have any idea why this is happening? Do you want to own the bug?
I have taken this bug. I have quite a bit of information to add regarding this issue which i will share in subsequent comments. I also have a work-around; but the work-around was not created as a result of digging into the issue and discovering the root cause, therefore it was rejected.
oe-selftest-fedora fedora43-vk-2 mathieu/master-next completed at 2026-03-12 09:39:01+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/48/builds/3278/steps/15/logs/stdio
Around the end of Dec 2025 / start of Jan 2026 I split wic out from oe-core. The moment I did that, and ran the wic oe-selftests, there were 2 tests that failed for me on my home build setup -- the same 2 that are reported here. At that time I investigated, but could not find why these 2 tests would not pass. After a while, it occurred to me to find out whether splitting out wic would cause these same tests to fail on the AB; perhaps it was just some strange quirk of my machine at home that caused these failures? So I sent an RFC patchset to the mailing list and asked if they could be run on the AB. Mathieu graciously offered to run them on the AB and reported they all passed. That suggested to me that my patchset was not causing any issues, there was simply something off about my home setup. My patchset went through several revisions, each time they would pass on the AB. Then I sent a v6 (I think) and Mathieu reported they did not pass: 2 of the tests failed, but only on the Fedora 43 worker. The 2 failing tests were the same 2 that were failing for me on my home machine for the same reasons -- running openSUSE Leap 16.0. This suggested to me that there was something wrong with my patches, even though the issue only showed up on openSUSE 16.0 and Fedora 43. Now that 2 of the tests were failing on the AB (though only on the Fedora 43 worker) I investigated more deeply. I never did find a root cause (yet), but I was able to create work-arounds so that all the tests would pass both at home and on all the AB workers. However, the work-arounds were rejected as solutions since the root cause was not discovered. It is extremely interesting, now, to find that these same 2 tests are now failing on the AB, on the Fedora 43 worker, but without the split-out-wic patches being merged. Up until this point I had assumed there was something funny about my split-out-wic patches that was causing the problem, but now that the problem can occur without the patchset, it suggests the patcheset has nothing to do with causing the failures, it suggests the patchset merely exacerbates the underlying issue. Which is a good thing since they will help me (or anyone else) investigate. Without the split-out-wic patches the issue has only been triggered once in... many many builds. But with the split-out-wic patches the issue is triggered every time (on openSUSE 16.0 and Fedora 43).
So what links openSUSE 16.0 and Fedora 43? The most important point is that both of them are the most recent releases of their respective distros. Which means both of them are (presumably) running the latest kernels, glibc, drivers, utilities, python, software, etc. all built with some of the latest toolchains. Also note that at this point none of the openSUSE builders have been upgraded to 16.0, so this issue could only be caught by the latest Fedora builder (43).
I have narrowed down this issue to the sparse_copy() function in scripts/lib/wic/filemap.py. If you are copying files (or parts of files) that consist mostly of holes (which is usually the case when it comes to files that contain images), you can save a considerable amount of time by only copying the parts that contain actual data, instead of wasting time copying the hole parts. That is the purpose of sparse_copy(): copy a file from src_fname to dst_fname but start by asking the kernel for the file extents first, then only copy those. With the current implementation of sparse_copy() in place, these 2 tests fail. If I replace the contents of sparse_copy() with logic that does a slow, basic, non-sparse copy of src_fname to dst_fname, the 2 tests succeed. See: https://git.yoctoproject.org/wic/tree/src/wic/filemap.py?h=testing/no-sparse-sparse-copy This is not a coincidence; both tests use sparse_copy() indirectly through _get_part_image() and _put_part_image(). Although these are not the only 2 tests to use sparse_copy(), they are the only 2 that use it on an ext2/3/4 filesystem, involving some sort of read/modify/write/verify cycle. These 2 failures are absolutely linked to the same issue which resolves around the sparse_copy() function in scripts/lib/wic/filemap.py.
Extensive testing by instrumenting up the sparse_copy() function shows the problem. FilemapSeek._get_ranges() is a generator. It calls os.lseek() on a raw file descriptor, then yields, then the caller, sparse_copy(), calls file.seek() + file.read() on a Python BufferedReader wrapping that same fd — then the generator resumes and calls os.lseek() again. This interleaving of raw os.lseek() and buffered I/O on the same fd is undefined behaviour from Python's perspective. The BufferedReader tracks its own idea of the fd's position and buffer contents; os.lseek() changes the position behind its back. This can corrupt its internal state and cause read() to return stale/zero data. This code has existed since wic was written. It happened to work because Python's BufferedReader.seek() would flush the read buffer and re-seek the raw fd, effectively recovering from the external position change. But nothing in Python's API guarantees this — it's an implementation detail, not a contract. On kernel 5.15, SEEK_HOLE on tmpfs apparently leaves page cache state alone, so the subsequent buffered read() returns correct data from cache. On kernel 6.12, something changed in how lseek(SEEK_DATA/SEEK_HOLE) interacts with the page cache on tmpfs — possibly page eviction, cache invalidation, or read-ahead behavior during the hole scan. This causes the BufferedReader to return stale zeros for pages that were valid before the lseek(). The fact that the corruption is intermittent (167 blocks on one call, 0 on the next, 1 on the third — same file, same parameters) is consistent with a cache timing sensitivity. The kernel change didn't introduce a new bug so much as tighten a race window that the code was always on the wrong side of. In short: the code was relying on behaviour that was never guaranteed, and kernel 6.12 stopped providing it. The wic code has always been unsafe, and a kernel change exposed it. This was confirmed by data-verification instrumentation: on kernel 6.12 with tmpfs, FilemapSeek intermittently returns zeroed blocks for data within mapped ranges. A fresh read of the same source file returns the correct data. FilemapFiemap (which uses the fiemap ioctl, not lseek) is never affected (i.e. non-tmpfs locations). This is fixed by opening a second file object in FilemapSeek.__init__() dedicated to SEEK_DATA/SEEK_HOLE probes, leaving the data-reading handle (self._f_image) untouched.
Created attachment 5192 [details] hole verification for wic.ModifyTests.test_wic_cp_ext succeeds Checking the contents of holes before and after updates shows no issues.
Created attachment 5193 [details] hole verification for wic.Wic2.test_expand_mbr_image succeeds Checking hole data before and after writing succeeds.
Created attachment 5194 [details] data verification for wic.ModifyTests.test_wic_cp_ext fails Checking the data contents before and after writing shows discrepancies.
Created attachment 5195 [details] data verification for wic.Wic2.test_expand_mbr_image fails Data verification before and after writing shows a discrepancy.
Comparing the two logs, the key difference emerges: on the failing machine, when the source is a file on /tmp (which is tmpfs), the filemap falls back to FilemapSeek because tmpfs doesn't support FIEMAP. On the working machine, /tmp is on a regular filesystem where FIEMAP works fine.
The bug is isolated to one place. Only FilemapSeek has the bug — three call sites in filemap.py, all in the FilemapSeek class: | Line| Method | Issue | |-----|-------------------|----------------------------| | 247 | block_is_mapped() | _lseek(self._f_image, ...) | | 268 | _get_ranges() | _lseek(self._f_image, ...) | | 272 | _get_ranges() | _lseek(self._f_image, ...) | FilemapFiemap is safe — it uses fcntl.ioctl(self._f_image, ...) at line 372, which does not change the fd position. No other occurrences anywhere in OE-core or bitbake. The other .fileno() uses are all os.ftruncate(), os.fstat(), os.fsync(), or mmap — none of which change the fd position and conflict with buffered reads. Bitbake's own code doesn't use os.lseek at all. So the single patch fixes the only instance of this bug in the entire codebase.
The kernel angle sounds good on paper, but doesn't quite add up. On the same openSUSE Leap 16.0 system i can reliably reproduce the bug every time these 2 oe-selftess are run when wic is split out, but the bug goes away (on the exact same machine) when wic is part of oe-core. In both cases: - the linux kernel is the same - the /tmp is on tmpfs In other words, several of the things that were theorized to be the possible culprits are not changing between failed and successful runs. It is a good thing that the same machine can both fail and succeed. The difference is whether or not wic is split out. It would be tidy to be able to say it's a result of the splitting-out process. Perhaps something went wrong when wic was split out that is causing the bug? That was a strong contender, until the bug showed up on the Fedora 43 machine in the AB that was not using the split-out wic.
Created attachment 5196 [details] some details of the AB runners This file provides some relevant details of the AB runners: - instance - the filesystem of /tmp (stat -f -c %T /tmp) - the kernel version (uname -r) - python version (python3 --version)
Created attachment 5197 [details] data verification for wic.ModifyTests.test_wic_cp_ext with extra instrumentation Same as previous data verification but with more instrumentation (as a result of further analysis).
Created attachment 5198 [details] data verification for wic.Wic2.test_expand_mbr_image with extra instrumentation Same as previous data verification but with more instrumentation (as a result of more analysis).
Created attachment 5199 [details] data verification for wic.ModifyTests.test_wic_cp_ext with extra instrumentation non-split-out Same as previous data verification instrumentation in the case where wic is not split-out.
Created attachment 5200 [details] data verification for wic.Wic2.test_expand_mbr_image with extra instrumentation non-split-out Same as previous data verification, with extra instrumentation, for the case when wic is not split out.
The moment I split wic out, 2 oe-selftests always failed with 100% reproducibility: - wic.ModifyTests.test_wic_cp_ext - wic.Wic2.test_expand_mbr_image wic.ModifyTests.test_wic_cp_ext tests the "wic cp" command to copy files into an already-built image; this test was recently expanded to cover recursively copying directories and files in one go rather than having to call "wic cp" multiple times. After performing a couple "wic cp"'s into an image, this test would fail with: AssertionError: 'Ext2 inode is not a directory' test_expand_mbr_image builds an ~200MB image with 2 partitions (boot vfat and ext4 rootfs). Then it creates a 1GB sparse file, uses "wic write --expand" to copy the image into the sparse file, uses e2fsck to verify the copy succeeded, then uses resize2fs to expand the image to fill the sparse file, verifies various things worked, then boots the expanded image in qemu to verify everything boots. Unfortunately a bug is triggered so that when the e2fsck occurs, it finds a filesystem with lots of inode problems: platform: Entry 'var' in / (2) has deleted/unused inode 3021. CLEARED. platform: Entry 'games' in /usr (187) has deleted/unused inode 442. CLEARED. platform: Entry 'include' in /usr (187) has deleted/unused inode 443. CLEARED. platform: Entry 'lib' in /usr (187) has deleted/unused inode 444. CLEARED. platform: Entry 'libexec' in /usr (187) has deleted/unused inode 1361. CLEARED. platform: Entry 'sbin' in /usr (187) has deleted/unused inode 1365. CLEARED. platform: Entry 'share' in /usr (187) has deleted/unused inode 1461. CLEARED. platform: Entry 'src' in /usr (187) has deleted/unused inode 3020. CLEARED. platform: Entry 'touch' in /usr/bin (188) has deleted/unused inode 408. CLEARED. platform: Entry 'usleep' in /usr/bin (188) has deleted/unused inode 428. CLEARED. platform: Entry 'systemd-vpick' in /usr/bin (188) has deleted/unused inode 397. CLEARED. platform: Entry 'systemd-mute-console' in /usr/bin (188) has deleted/unused inode 385. CLEARED. platform: Entry 'top' in /usr/bin (188) has deleted/unused inode 407. CLEARED. platform: Entry 'uptime' in /usr/bin (188) has deleted/unused inode 425. CLEARED. platform: Entry 'time' in /usr/bin (188) has deleted/unused inode 405. CLEARED. platform: Entry 'varlinkctl' in /usr/bin (188) has deleted/unused inode 429. CLEARED. platform: Entry 'tee' in /usr/bin (188) has deleted/unused inode 401. CLEARED. platform: Entry 'systemd-stdio-bridge' in /usr/bin (188) has deleted/unused inode 392. CLEARED. platform: Entry 'vlock' in /usr/bin (188) has deleted/unused inode 431. CLEARED. platform: Entry 'which' in /usr/bin (188) has deleted/unused inode 435. CLEARED. platform: Entry 'update-mime-database' in /usr/bin (188) has deleted/unused inode 424. CLEARED. platform: Entry 'systemd-resolve' in /usr/bin (188) has deleted/unused inode 389. CLEARED. platform: Entry 'systemd-mount' in /usr/bin (188) has deleted/unused inode 384. CLEARED. platform: Entry 'unzip' in /usr/bin (188) has deleted/unused inode 422. CLEARED. platform: Entry 'systemd-umount' in /usr/bin (188) has deleted/unused inode 396. CLEARED. platform: Entry 'users' in /usr/bin (188) has deleted/unused inode 427. CLEARED. platform: Entry 'unlink' in /usr/bin (188) has deleted/unused inode 421. CLEARED. platform: Entry 'systemd-tmpfiles' in /usr/bin (188) has deleted/unused inode 394. CLEARED. platform: Entry 'uname' in /usr/bin (188) has deleted/unused inode 417. CLEARED. platform: Entry 'systemd-detect-virt' in /usr/bin (188) has deleted/unused inode 377. CLEARED. platform: Entry 'test' in /usr/bin (188) has deleted/unused inode 403. CLEARED. platform: Entry 'who' in /usr/bin (188) has deleted/unused inode 436. CLEARED. platform: Entry 'systemd-machine-id-setup' in /usr/bin (188) has deleted/unused inode 383. CLEARED. platform: Entry 'systemd-creds' in /usr/bin (188) has deleted/unused inode 375. CLEARED. platform: Entry 'userdbctl' in /usr/bin (188) has deleted/unused inode 426. CLEARED. platform: Entry 'systemd-cat' in /usr/bin (188) has deleted/unused inode 372. CLEARED. platform: Entry 'traceroute' in /usr/bin (188) has deleted/unused inode 410. CLEARED. platform: Entry 'tar' in /usr/bin (188) has deleted/unused inode 399. CLEARED. platform: Entry 'systemd-pty-forward' in /usr/bin (188) has deleted/unused inode 388. CLEARED. platform: Entry 'tail' in /usr/bin (188) has deleted/unused inode 398. CLEARED. platform: Entry 'unicode_stop' in /usr/bin (188) has deleted/unused inode 419. CLEARED. platform: Entry 'systemd-cgls' in /usr/bin (188) has deleted/unused inode 373. CLEARED. platform: Entry 'unicode_start' in /usr/bin (188) has deleted/unused inode 418. CLEARED. platform: Entry 'systemd-path' in /usr/bin (188) has deleted/unused inode 387. CLEARED. platform: Entry 'whoami' in /usr/bin (188) has deleted/unused inode 437. CLEARED. platform: Entry 'zcat' in /usr/bin (188) has deleted/unused inode 441. CLEARED. platform: Entry 'systemd-notify' in /usr/bin (188) has deleted/unused inode 386. CLEARED. platform: Entry 'tar.tar' in /usr/bin (188) has deleted/unused inode 400. CLEARED. platform: Entry 'update-alternatives' in /usr/bin (188) has deleted/unused inode 423. CLEARED. platform: Entry 'umount' in /usr/bin (188) has deleted/unused inode 415. CLEARED. platform: Entry 'true' in /usr/bin (188) has deleted/unused inode 411. CLEARED. platform: Entry 'yes' in /usr/bin (188) has deleted/unused inode 440. CLEARED. platform: Entry 'systemd-sysusers' in /usr/bin (188) has deleted/unused inode 393. CLEARED. platform: Entry 'tftp' in /usr/bin (188) has deleted/unused inode 404. CLEARED. platform: Entry 'systemd-tty-ask-password-agent' in /usr/bin (188) has deleted/unused inode 395. CLEARED. platform: Entry 'systemd-escape' in /usr/bin (188) has deleted/unused inode 379. CLEARED. platform: Entry 'systemd-id128' in /usr/bin (188) has deleted/unused inode 381. CLEARED. platform: Entry 'telnet' in /usr/bin (188) has deleted/unused inode 402. CLEARED. platform: Entry 'wc' in /usr/bin (188) has deleted/unused inode 433. CLEARED. platform: Entry 'systemctl' in /usr/bin (188) has deleted/unused inode 369. CLEARED. platform: Entry 'systemd-inhibit' in /usr/bin (188) has deleted/unused inode 382. CLEARED. platform: Entry 'xzcat' in /usr/bin (188) has deleted/unused inode 439. CLEARED. platform: Entry 'systemd-cgtop' in /usr/bin (188) has deleted/unused inode 374. CLEARED. platform: Entry 'systemd-socket-activate' in /usr/bin (188) has deleted/unused inode 391. CLEARED. platform: Entry 'xargs' in /usr/bin (188) has deleted/unused inode 438. CLEARED. platform: Entry 'timedatectl' in /usr/bin (188) has deleted/unused inode 406. CLEARED. platform: Entry 'umount.util-linux' in /usr/bin (188) has deleted/unused inode 416. CLEARED. platform: Entry 'systemd-run' in /usr/bin (188) has deleted/unused inode 390. CLEARED. platform: Entry 'uniq' in /usr/bin (188) has deleted/unused inode 420. CLEARED. platform: Entry 'watch' in /usr/bin (188) has deleted/unused inode 432. CLEARED. platform: Entry 'systemd-hwdb' in /usr/bin (188) has deleted/unused inode 380. CLEARED. platform: Entry 'systemd-ac-power' in /usr/bin (188) has deleted/unused inode 370. CLEARED. platform: Entry 'systemd-dissect' in /usr/bin (188) has deleted/unused inode 378. CLEARED. platform: Entry 'vi' in /usr/bin (188) has deleted/unused inode 430. CLEARED. platform: Entry 'ts' in /usr/bin (188) has deleted/unused inode 412. CLEARED. platform: Entry 'tty' in /usr/bin (188) has deleted/unused inode 413. CLEARED. platform: Entry 'tr' in /usr/bin (188) has deleted/unused inode 409. CLEARED. platform: Entry 'systemd-delta' in /usr/bin (188) has deleted/unused inode 376. CLEARED. platform: Entry 'udevadm' in /usr/bin (188) has deleted/unused inode 414. CLEARED. platform: Entry 'systemd-ask-password' in /usr/bin (188) has deleted/unused inode 371. CLEARED. platform: Entry 'wget' in /usr/bin (188) has deleted/unused inode 434. CLEARED. platform: Inode 2 ref count is 17, should be 16. FIXED. platform: Inode 187 ref count is 10, should be 3. FIXED. platform: 368/22352 files (0.5% non-contiguous), 28572/178596 blocks
In both cases the symptom is the same: the filesystem has inode tables that are completely zeroed out. Both issues are linked together to the same underlying fault. wic's filemap.py contains a function, sparse_copy(), which performs optimized (image) file copies. Beneath the covers, the guts of sparse_copy() are implemented via one of three internal classes. These classes attempt to take advantage of the fact that most images are sparse: they contain large holes which do not need to be explicitly copied. The Linux kernel provides two mechanisms to discover a file's "extents" (the list of hole vs data regions for a given file): 1. the FIEMAP ioctl 2. lseek()'s SEEK_HOLE/SEEK_DATA extensions The FIEMAP ioctl is the more sophisticated tool. With 2 ioctl() calls the kernel returns a complete list of all data and hole extents of a file object (one call to obtain the number of extents, then a second call to retrieve all the extents). This functionality is implemented in wic's filemap.py's FilemapFiemap class. Unfortunately not all filesystems support extent mapping via the FIEMAP ioctl(). The tmpfs filesystem, for example, is a virtual, memory-based filesystem that does not map files to physical, contiguous disk blocks. Therefore it can not provide a list of block extents for a file object. As a result, wic's filemap.py provides a fall-back class, FilemapSeek, for this purpose. SEEK_HOLE/SEEK_DATA are extensions to the lseek() system call that allow a user to map the sparse layout of a file one region at at time, by stepping through all regions sequentially. If the above two are not possible, wic's filemap.py provides one last fall-back, FilemapNobmap, which simply copies the file in its entirety, including all holes, from its start, to its length, and every byte explicitly in between, in a non-optimized way. The first clue to solving this bug was by noticing that if I disabled the optimized copies and always had sparse_copy() use the FilemapNobmap class, all the tests would succeed and the bug went away. Further instrumentation indicated that the problem only occurred when the tmpfs was involved. In other words the bug seems to be contained to the FilemapSeek class. FilemapSeek._get_ranges() is a generator. Due to the nature of finding each hole/data extent one at a time using the lseek() system call, it calls os.lseek() on a raw file descriptor, then yields, then the caller, sparse_copy(), calls file.seek() + file.read() on a Python BufferedReader wrapping that same fd — then the generator resumes and calls os.lseek() again. This interleaving of raw os.lseek() and buffered I/O on the same fd is undefined behaviour from Python's perspective. The BufferedReader tracks its own idea of the fd's position and buffer contents; os.lseek() changes the position behind its back. This can corrupt its internal state and cause read() to return stale/zero data. This code, however, has existed in wic since it was written, so why was it not noticed before? It turns out this bug was being masked by a number of implementation details that changed, especially when wic was split out for oe-core. These changes conspired together to cause the bug to be triggered. wic is a python application. Curiously, when wic is part of oe-core, most of the wic invocations from the oe-selftests run with the host system's Python interpreter. However, when wic is split out from oe-core, the oe-selftest invocations are always called with the Python interpreter from oe-core's sysroot. NOTE: openSUSE Leap 16.0: python 3.13.11 oe-core: python 3.14.3 Fedora 43: python 3.14.3 One of the root causes of this bug is that Python 3.14 increased the default buffer size from 8KB to 128KB[1], creating a much larger window where BufferedReader.seek() can take the fast-path after the raw file descriptor has already been repositioned by os.lseek() in the generator. With the smaller buffer, this window was too narrow to hit in practice. This explains why the corruption is deterministic and tied to specific block boundaries, why it only manifests with the split-out version using Python 3.14, and why using a separate file descriptor for reading bypasses the issue entirely. Instrumenting the code with extremely detailed logs of every extent's details, including content, revealed deterministic, repeatable clues. The corrupting sparse_copy call reads from /tmp/wic-part* (tmpfs, FilemapSeek) with these ranges: range[0]: blocks 0..69 bytes 0..286719 (286720 bytes) range[1]: blocks 73..262 bytes 299008..1077247 (778240 bytes) Step by step: 1. seek(0) — buffer empty, raw seek, fd at 0. 2. read(286720) — internally, BufferedReader reads in 131072-byte fills: - Fill 1: raw read [0, 131072), returns 131072, buffer drained. - Fill 2: raw read [131072, 262144), returns 131072, buffer drained. - Fill 3: raw read [262144, 393216) into buffer (131072 bytes). Returns the remaining 24576 bytes (286720 - 262144). Buffer retains 106496 bytes covering [286720, 393216). 3. Generator resumes — calls os.lseek(fd, 286720, SEEK_HOLE) then os.lseek(fd, ..., SEEK_DATA), etc. The raw fd ends up somewhere around 1077248. BufferedReader doesn't know. 4. seek(299008) — is 299008 within the buffer range [286720, 393216)? Yes. Fast-path: buffer pointer adjusted, raw fd NOT corrected. Still at ~1077248. 5. read(778240): - Returns 94208 bytes from buffer (393216 - 299008). These are correct. - Needs 684032 more bytes (778240 - 94208). Reads directly from raw fd. - Raw fd is at ~1077248 (hole region), reads 684032 bytes of zeros. - 684032 / 4096 = 167 blocks of corruption, starting at byte 393216 = block 96. With 8 KB buffers, read(286720) either goes through the direct-read path (286720 >> 8192) leaving the buffer empty, or if it fills in 8KB chunks: 286720 = 35 x 8192 exactly, so the buffer is fully drained. Either way, after range[0], the buffer is empty. The seek to 299008 does a real raw seek. No fast path. No corruption. This is fixed by opening a second file object in FilemapSeek.__init__() dedicated to SEEK_DATA/SEEK_HOLE probes, leaving the data-reading handle (self._f_image) untouched. In summary this latent bug was always in wic's codebase but needed a specific set of conditions to become visible: 1. The host system's /tmp has to be on a tmpfs filesystem since the bug is in wic's Filemap's FilemapSeek class which is only used if the underlying filesystem does not support the FIEMAP ioctl(). 2. Python 3.14 increased its buffer size from 8K to 128K. 3. Splitting out wic from oe-core. The code needs to run on Python 3.14 or newer either because the split-out version uses oe-core's Python (which is 3.14) or because the host system's Python is at 3.14 or later (which is the case for Fedora 43). 3. The interleaving of raw os.leek() and buffered I/O on the same file descriptor with a buffer size that is not fully emptied after each call, causing the fast-path to be used with an fd pointing to the wrong data (due to this interleaving being undefined behaviour). 4. The wic.ModifyTests.test_wic_cp_ext was updated to contain more data which causes the range buffer overflow. [1] https://github.com/python/cpython/commit/b1b4f9625c5f2a6b2c32bc5ee91c9fef3894b5e6 b1b4f9625c5f ("gh-117151: IO performance improvement, increase io.DEFAULT_BUFFER_SIZE to 128k (GH-118144)")
Created attachment 5201 [details] self-contained python reproducer This small, self-contained, python reproducer isolates the problem investigated in this bugzilla issue and demonstrates the failure in detail. The reproducer tweaks various parameters and conditions so it will always fail; it does not need to be run on a system running Python 3.14 or greater (it adjusts the I/O buffer size to match Python 3.14's increased buffer size) and it does not need to use a tmpfile in a tmpfs filesystem (it uses the lseek() mechanism regardless of the underlying filesystem). This reproducer was AI-Generated: codex/claude-opus-4.6 (xhigh)
patch submitted: https://lists.openembedded.org/g/openembedded-core/topic/patch_wic_filemap_use/118339543
patch v2 submitted (updates code comments to align with new understandings): https://lists.openembedded.org/g/openembedded-core/topic/patch_v2_wic_filemap_use/118345484
Created attachment 5204 [details] stand-alone susceptibility test Run this stand-alone Python program on a system to investigate whether or not it might hit this bug or whether the bug might hide on. $ python3 wic_susceptibility_test.py --help usage: wic_susceptibility_test.py [-h] [--tmpdir TMPDIR] [--iterations ITERATIONS] Test whether this machine is susceptible to the wic sparse_copy corruption bug. options: -h, --help show this help message and exit --tmpdir TMPDIR directory for test files (default: /tmp) --iterations ITERATIONS iterations per buffer-size test (default: 200) when run on a system that will show the bug: Machine susceptibility test for wic sparse_copy bug ======================================================= python : 3.13.11 kernel : 6.12.0-160000.9-default io.DEFAULT_BUFFER_SIZE : 8192 tmpdir : /tmp iterations : 200 Filesystem checks on /tmp: SEEK_HOLE/SEEK_DATA : supported (real) FIEMAP ioctl : not supported FIEMAP is NOT supported but SEEK_HOLE is. Real wic would use FilemapSeek for files here. This is the configuration that can trigger the bug. Test 1: default buffer size (8192 bytes, 200 iterations) PASS: no corruption in 200 iterations Test 2: 128 KB buffer / Python 3.14 (131072 bytes, 200 iterations) FAIL: 200/200 iterations corrupted first bad block: 96 (offset 393216) worst case: 167/25025 data blocks zeroed ======================================================= RESULT: NOT susceptible with current Python (3.13.11, buffer=8192). SUSCEPTIBLE if wic runs with Python >= 3.14 (buffer=131072). wic would hit this bug on /tmp with Python 3.14. when run on a system that would not demonstrate this bug (because /tmp is not tmpfs): $ python3 wic_susceptibility_test.py Machine susceptibility test for wic sparse_copy bug ======================================================= python : 3.10.12 kernel : 5.15.0-131-generic io.DEFAULT_BUFFER_SIZE : 8192 tmpdir : /tmp iterations : 200 Filesystem checks on /tmp: SEEK_HOLE/SEEK_DATA : supported (real) FIEMAP ioctl : supported FIEMAP is supported on /tmp. Real wic would use FilemapFiemap (ioctl, no fd movement) for files here. The bug only triggers with FilemapSeek. wic would NOT be affected for temp files on this filesystem. Test 1: default buffer size (8192 bytes, 200 iterations) PASS: no corruption in 200 iterations Test 2: 128 KB buffer / Python 3.14 (131072 bytes, 200 iterations) FAIL: 200/200 iterations corrupted first bad block: 96 (offset 393216) worst case: 167/25025 data blocks zeroed ======================================================= RESULT: NOT susceptible with current Python (3.10.12, buffer=8192). SUSCEPTIBLE if wic runs with Python >= 3.14 (buffer=131072). However, wic uses FIEMAP on /tmp, so temp files here would not trigger it even with Python 3.14.
Created attachment 5205 [details] instrumentation for non-split-out wic in oe-core to give diagnostics 1. apply this patch to oe-core 2. make sure conf/local.conf does not contain any wic configurations 3. do add the following to conf/local.conf so qemu works: EXTRA_IMAGE_FEATURES ?= "empty-root-password allow-empty-password allow-root-login post-install-logging" 4. run the first oe-selftest (from the build directory): $ oe-selftest --keep-builddir -v -r wic.Wic2.test_expand_mbr_image 5. collect the log file from ../build-st/sparse_copy.log (save to new name) $ mv ../build-st/sparse_copy.log ../sparse_copy_wic2.log 6. delete the ../build-st directory (and contents) $ rm -fr ../build-st 7. run the other oe-selftest $ oe-selftest --keep-builddir -v -r wic.ModifyTests.test_wic_cp_ext 8. save its log file $ mv ../build-st/sparse_copy.log ../sparse_copy_Modify.log 9. check the logs for the string "MISMATCH", e.g. VERIFY DATA: *** MISMATCH at partition offset 393216 (block 96, MAPPED region) ***
(In reply to Trevor Woerner from comment #25) > Created attachment 5204 [details] > stand-alone susceptibility test > > Run this stand-alone Python program on a system to investigate whether or > not it might hit this bug or whether the bug might hide on. > I ran this on fedora43-vk-2: $ python3 wic_susceptibility_test.py Machine susceptibility test for wic sparse_copy bug ======================================================= python : 3.14.3 kernel : 6.18.16-200.fc43.x86_64 io.DEFAULT_BUFFER_SIZE : 131072 tmpdir : /tmp iterations : 200 Filesystem checks on /tmp: SEEK_HOLE/SEEK_DATA : supported (real) FIEMAP ioctl : not supported FIEMAP is NOT supported but SEEK_HOLE is. Real wic would use FilemapSeek for files here. This is the configuration that can trigger the bug. Test 1: default buffer size (131072 bytes, 200 iterations) FAIL: 200/200 iterations corrupted first bad block: 96 (offset 393216) worst case: 167/25025 data blocks zeroed Test 2: skipped (default is already 131072) ======================================================= RESULT: SUSCEPTIBLE with current Python (3.14.3, buffer=131072). wic will hit this bug for temp files on /tmp.
A v2 patch was sent which was merged into oe-core: https://lists.openembedded.org/g/openembedded-core/topic/patch_v2_wic_filemap_use/118345484