Bug 14183

Summary: psuedo path mismatch during image build
Product: [Build System, Metadata & Runtime] OE-Core Reporter: Ross Burton <ross.burton>
Component: coreAssignee: Richard Purdie <richard.purdie>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium+ CC: meta.mr.watcher, meta.watcher, randy.macleod, richard.purdie, ross.burton
Version: 3.4   
Target Milestone: 3.3 M3   
Hardware: x86   
OS: Multiple   
Whiteboard: AB-INT
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)

Description Ross Burton 2021-01-11 12:46:31 UTC
Building an image failed:

ERROR: core-image-sato-1.0-r0 do_rootfs: Unable to update the package index files. Command '['/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/recipe-sysroot-native/usr/bin/apt-get', 'update']' returned -6:
Get:1 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ InRelease
Ign:1 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ InRelease
Get:2 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/core2-32 ./ InRelease
Ign:2 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/core2-32 ./ InRelease
Get:3 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/all ./ InRelease
Ign:3 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/all ./ InRelease
Get:4 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ Release [1,219 B]
Get:5 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/core2-32 ./ Release [1,220 B]
Get:6 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/all ./ Release [1,215 B]
Get:4 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ Release [1,219 B]
Get:7 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ Release.gpg
Ign:7 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/qemux86 ./ Release.gpg
Get:5 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/core2-32 ./ Release [1,220 B]
Get:6 file:/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/oe-rootfs-repo/all ./ Release [1,215 B]
abort()ing pseudo client by server request. See https://wiki.yoctoproject.org/wiki/Pseudo_Abort for more details on this.
Check logfile: /home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/pseudo//pseudo.log

The pseudo.log has the following path mismatches:

path mismatch [1 link]: ino 143525936 db '/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_pkgman-non-rpm_build_build_tmp_work_qemux86-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_qemux86_._Release.CBFzPd' req '/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_pkgman-non-rpm_build_build_tmp_work_qemux86-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_qemux86_._Release'.

This happened more than once, the other build had the same error:

path mismatch [1 link]: ino 27666766 db '/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_pkgman-non-rpm_build_build_tmp_work_qemux86-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_all_._Release.RpRzHw' req '/home/pokybuild/yocto-worker/pkgman-non-rpm/build/build/tmp/work/qemux86-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_pkgman-non-rpm_build_build_tmp_work_qemux86-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_all_._Release'
Comment 1 Randy MacLeod 2021-01-14 15:45:46 UTC
RP: Looks like mkstemp is racing with pseudo occasionally.
Encounterd when using apt but likely happening elsewhere from time to time.
Comment 2 Richard Purdie 2021-01-29 21:52:12 UTC
There was a recent fix in pseudo for rename() handling. We may want to audit the apt codepaths to see if that rename issue could have caused this. The worry is the rename()+fstat() issue should reproduce all the time and this does not.
Comment 3 Richard Purdie 2021-02-10 14:46:59 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/1341/steps/14/logs/stdio

pid 959642 [parent 959629], doing new pid setup and server start
Setup complete, sending SIGUSR1 to pid 959629.
path mismatch [1 link]: ino 88221442 db '/home/pokybuild/yocto-worker/oe-selftest/build/build-st-2079038/reproducibleB/tmp/work/qemux86_64-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_oe-selftest_build_build-st-2079038_reproducibleB_tmp_work_qemux86%5f64-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_all_._Release.oY00En' req '/home/pokybuild/yocto-worker/oe-selftest/build/build-st-2079038/reproducibleB/tmp/work/qemux86_64-poky-linux/core-image-sato/1.0-r0/apt/lists/partial/_home_pokybuild_yocto-worker_oe-selftest_build_build-st-2079038_reproducibleB_tmp_work_qemux86%5f64-poky-linux_core-image-sato_1.0-r0_oe-rootfs-repo_all_._Release'.
db cleanup for server shutdown, 03:04:13.117
memory-to-file backup complete, 03:04:13.118.
db cleanup finished, 03:04:13.118
pseudo.log (END)

so definitely still present
Comment 4 Richard Purdie 2021-02-10 23:17:38 UTC
I suspect what is is happening is that in between pseudo calling real_rename() and then running OP_RENAME on the pseudo database, something is calling something like stat() on the newpath.

This stat call would have the same inode as oldpath and oldpath would still be in the database but isn't marked as MAY_UNLINK so this abort triggers.

The fix is likely to mark oldpath as MAY_UNLINK in the database before real_rename call.