* Build failure with parallel build and opkg @ 2018-09-11 22:49 Stefan Agner 2018-09-26 9:34 ` Stefan Agner 0 siblings, 1 reply; 6+ messages in thread From: Stefan Agner @ 2018-09-11 22:49 UTC (permalink / raw) To: openembedded-core; +Cc: Brandon Shibley, samuel.bissig, ricardo Hi, We experience build errors as follows every now and then: ... ERROR: full-container-image-0.1-r0 do_populate_sdk: Unable to install packages. Command '/workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/recipe-sysroot-native/usr/bin/opkg --volatile-cache -f /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/opkg.conf -t /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/temp/ipktemp/ -o /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi --force_postinstall --prefer-arch-to-version install 96boards-tools aktualizr aktualizr-host-tools aktualizr-runtime-prov base-passwd coreutils cpufrequtils docker gptfdisk haveged hostapd htop iptables kernel-modules ldd less lmp-device-register networkmanager networkmanager-nmtui openssh-sftp-server os-release ostree packagegroup-base-extended packagegroup-core-boot packagegroup-core-full-cmdline-extended packagegroup-core-full-cmdline-multiuser packagegroup-core-full-cmdline-utils packagegroup-core-ssh-openssh packagegroup-core-standalone-sdk-target pciutils python3-compression python3-distutils python3-docker python3-docker-compose python3-json python3-netclient python3-pkgutil python3-shell python3-unixadmin rsync run-postinsts shadow sshfs-fuse strace sudo target-sdk-provides-dummy tcpdump vim-tiny' returned 255: ... Downloading file:/workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/nss_3.38-r0_armv7at2hf-neon.ipk. Removing corrupt package file /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi//var/cache/opkg/volatile/8e392ecd3611e24a6a49a8b22ad6e1ff_nss_3.38-r0_armv7at2hf-neon.ipk. ... Installing pam-plugin-faildelay (1.3.0) on root Downloading file:/workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/pam-plugin-faildelay_1.3.0-r5_armv7at2hf-neon.ipk. Removing corrupt package file /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi//var/cache/opkg/volatile/0df6a8bc594a581f6ca3bcfa55e860e2_pam-plugin-faildelay_1.3.0-r5_armv7at2hf-neon.ipk. ... Collected errors: * opkg_install_pkg: Failed to download nss. Perhaps you need to run 'opkg update'? * opkg_install_pkg: Failed to download pam-plugin-faildelay. Perhaps you need to run 'opkg update'? . ... We build our own OpenEmbedded core based distribution currently based on a recent master state. But we have seen this on and off back since rocko. We build the image using Jenkins with multiple builders running in parallel and sharing sstate. I think the fact that we run similar images in parallel is the culprit: Looking closer at the failed build directory reveals that the tmp-glibc/deploy/ipk/armv7at2hf-neon/Packages has a different MD5Sum than the actual package. We start with two builders simultaneously building an image, and it seems that they build the same package around the same time. I assume that the two builders somehow have a race between when the package get assembled and when the Package index gets built... We start with a clean sstate, and this typically only happens for the very first builds, when the sstate is cold. I guess there is some race/asynchronous operation going on around building index/getting package from sstate/pushing package to sstate. It seems an issue others have seen in the past too: https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 Any idea? -- Stefan ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Build failure with parallel build and opkg 2018-09-11 22:49 Build failure with parallel build and opkg Stefan Agner @ 2018-09-26 9:34 ` Stefan Agner 2018-10-02 8:46 ` Stefan Agner 0 siblings, 1 reply; 6+ messages in thread From: Stefan Agner @ 2018-09-26 9:34 UTC (permalink / raw) To: openembedded-core, richard.purdie; +Cc: Brandon Shibley, samuel.bissig, ricardo Hi, On 12.09.2018 00:49, Stefan Agner wrote: > Hi, > > We experience build errors as follows every now and then: > > ... > ERROR: full-container-image-0.1-r0 do_populate_sdk: Unable to install > packages. Command > '/workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/recipe-sysroot-native/usr/bin/opkg > --volatile-cache -f > /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/opkg.conf > -t > /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/temp/ipktemp/ > -o > /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi > --force_postinstall --prefer-arch-to-version install 96boards-tools > aktualizr aktualizr-host-tools aktualizr-runtime-prov base-passwd > coreutils cpufrequtils docker gptfdisk haveged hostapd htop iptables > kernel-modules ldd less lmp-device-register networkmanager > networkmanager-nmtui openssh-sftp-server os-release ostree > packagegroup-base-extended packagegroup-core-boot > packagegroup-core-full-cmdline-extended > packagegroup-core-full-cmdline-multiuser > packagegroup-core-full-cmdline-utils packagegroup-core-ssh-openssh > packagegroup-core-standalone-sdk-target pciutils python3-compression > python3-distutils python3-docker python3-docker-compose python3-json > python3-netclient python3-pkgutil python3-shell python3-unixadmin rsync > run-postinsts shadow sshfs-fuse strace sudo target-sdk-provides-dummy > tcpdump vim-tiny' returned 255: > ... > Downloading > file:/workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/nss_3.38-r0_armv7at2hf-neon.ipk. > Removing corrupt package file > /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi//var/cache/opkg/volatile/8e392ecd3611e24a6a49a8b22ad6e1ff_nss_3.38-r0_armv7at2hf-neon.ipk. > ... > Installing pam-plugin-faildelay (1.3.0) on root > Downloading > file:/workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/pam-plugin-faildelay_1.3.0-r5_armv7at2hf-neon.ipk. > Removing corrupt package file > /workdir/oe/tmp/work/colibri_imx7-lmp-linux-gnueabi/full-container-image/0.1-r0/sdk/image/usr/local/tordy-x86_64/sysroots/armv7at2hf-neon-lmp-linux-gnueabi//var/cache/opkg/volatile/0df6a8bc594a581f6ca3bcfa55e860e2_pam-plugin-faildelay_1.3.0-r5_armv7at2hf-neon.ipk. > ... > Collected errors: > * opkg_install_pkg: Failed to download nss. Perhaps you need to run > 'opkg update'? > * opkg_install_pkg: Failed to download pam-plugin-faildelay. Perhaps > you need to run 'opkg update'? > . > ... > > We build our own OpenEmbedded core based distribution currently based on > a recent master state. But we have seen this on and off back since > rocko. > > We build the image using Jenkins with multiple builders running in > parallel and sharing sstate. I think the fact that we run similar images > in parallel is the culprit: Looking closer at the failed build directory > reveals that the tmp-glibc/deploy/ipk/armv7at2hf-neon/Packages has a > different MD5Sum than the actual package. We start with two builders > simultaneously building an image, and it seems that they build the same > package around the same time. I assume that the two builders somehow > have a race between when the package get assembled and when the Package > index gets built... > > We start with a clean sstate, and this typically only happens for the > very first builds, when the sstate is cold. We discussed the issue at Linaro Connect a bit. To recap, we do build in two steps: 1. bitbake full-container-image 2. bitbake -c populate_sdk full-container-image The issue always happens in the second step. We also see that in the second step, the do_package_write_ipk_setscene task for every recipe is executed. The current assumption is I tried to reproduce by building a recipe using openembedded-core master only in two build directories with shared sstate manually: 1. build1 $ bitbake eudev 2. build2 $ bitbake -c cleansstate eudev 3. build2 $ bitbake eudev 4. build1 $ bitbake core-image-minimal This sequence seems not to have triggered a do_package_write_ipk_setscene for eudev. I then tried 5. build1 $ bitbake -c populate_sdk core-image-minimal Which did trigger a do_package_write_ipk_setscene. However, the issue did not appear... I even tried to rebuild and replace the file manually, and run bitbake -c populate_sdk -f core-image-minimal, but it just seems not to appear. Last time I have seen it was with oe-core f6634581fa0a81c4d68dc9179a755ad7b9d99357, I will revert to this version again to see whether that helps reproducing the issue. -- Stefan > > I guess there is some race/asynchronous operation going on around > building index/getting package from sstate/pushing package to sstate. > > It seems an issue others have seen in the past too: > https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 > > Any idea? > > -- > Stefan ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Build failure with parallel build and opkg 2018-09-26 9:34 ` Stefan Agner @ 2018-10-02 8:46 ` Stefan Agner 2018-10-02 13:12 ` Stefan Agner 0 siblings, 1 reply; 6+ messages in thread From: Stefan Agner @ 2018-10-02 8:46 UTC (permalink / raw) To: openembedded-core, richard.purdie, Max Krummenacher Cc: Brandon Shibley, samuel.bissig, ricardo On 26.09.2018 11:34, Stefan Agner wrote: > Hi, > > On 12.09.2018 00:49, Stefan Agner wrote: <snip> > We discussed the issue at Linaro Connect a bit. > > To recap, we do build in two steps: > > 1. bitbake full-container-image > 2. bitbake -c populate_sdk full-container-image > > The issue always happens in the second step. > > We also see that in the second step, the do_package_write_ipk_setscene > task for every recipe is executed. > > The current assumption is > > I tried to reproduce by building a recipe using openembedded-core master > only in two build directories with shared sstate manually: > > 1. build1 $ bitbake eudev > 2. build2 $ bitbake -c cleansstate eudev > 3. build2 $ bitbake eudev > 4. build1 $ bitbake core-image-minimal > > This sequence seems not to have triggered a > do_package_write_ipk_setscene for eudev. > > I then tried > 5. build1 $ bitbake -c populate_sdk core-image-minimal > > Which did trigger a do_package_write_ipk_setscene. However, the issue > did not appear... > > I even tried to rebuild and replace the file manually, and run bitbake > -c populate_sdk -f core-image-minimal, but it just seems not to appear. > > Last time I have seen it was with oe-core > f6634581fa0a81c4d68dc9179a755ad7b9d99357, I will revert to this version > again to see whether that helps reproducing the issue. Using the older OE version did not make a difference. So Max and I discussed a bit further. We realized that when OE rebuilds, the opkg package index is refreshed for a package only if the mtime (in seconds) is different between the previous file and the file on disk currently (see opkg-make-index). Can it be that two simultaneously started builds create two ipk with same mtime? So I built two core-image-minimal builds (on the same machine) at the *very* same time. First try did not cause a collision, but already on the second try I managed to reproduce multiple collision. This output shows all the packages with the same unix mtime stamp according to the Packages.stamps file (generated by opkg-make-index): $ comm -1 -2 <(sort build1/tmp-glibc/deploy/ipk/i586/Packages.stamps) <(sort build2/tmp-glibc/deploy/ipk/i586/Packages.stamps) kages.stamps) 1538424250 glibc-binary-localedata-de-it_2.27-r0_i586.ipk 1538425082 libreadline-staticdev_7.0-r0_i586.ipk 1538425162 bash-bashbug_4.4.18-r0_i586.ipk 1538425162 bash-completion_2.8-r0_i586.ipk 1538425162 bash-completion-dbg_2.8-r0_i586.ipk 1538425162 bash-completion-dev_2.8-r0_i586.ipk 1538425162 bash-loadable_4.4.18-r0_i586.ipk 1538425163 bash_4.4.18-r0_i586.ipk 1538425163 bash-completion-extra_2.8-r0_i586.ipk 1538425164 bash-doc_4.4.18-r0_i586.ipk 1538425167 bash-dbg_4.4.18-r0_i586.ipk 1538425233 util-linux-locale-hr_2.32-r0_i586.ipk 1538425233 util-linux-locale-id_2.32-r0_i586.ipk 1538425233 util-linux-locale-it_2.32-r0_i586.ipk 1538425233 util-linux-locale-sl_2.32-r0_i586.ipk 1538425233 util-linux-locale-zh-tw_2.32-r0_i586.ipk 1538425234 util-linux-dev_2.32-r0_i586.ipk 1538425234 util-linux-findfs_2.32-r0_i586.ipk 1538425234 util-linux-ionice_2.32-r0_i586.ipk 1538425234 util-linux-locale-ca_2.32-r0_i586.ipk 1538425234 util-linux-locale-pl_2.32-r0_i586.ipk 1538425234 util-linux-locale-pt-br_2.32-r0_i586.ipk 1538425234 util-linux-locale-ru_2.32-r0_i586.ipk 1538425234 util-linux-locale-sv_2.32-r0_i586.ipk 1538425234 util-linux-locale-tr_2.32-r0_i586.ipk 1538425234 util-linux-locale-vi_2.32-r0_i586.ipk 1538425234 util-linux-locale-zh-cn_2.32-r0_i586.ipk 1538425234 util-linux-mountpoint_2.32-r0_i586.ipk 1538425235 util-linux-locale-fr_2.32-r0_i586.ipk 1538425236 util-linux-blkid_2.32-r0_i586.ipk 1538425236 util-linux-fsck_2.32-r0_i586.ipk 1538425236 util-linux-fsck.cramfs_2.32-r0_i586.ipk 1538425236 util-linux-fstrim_2.32-r0_i586.ipk 1538425236 util-linux-lscpu_2.32-r0_i586.ipk 1538425236 util-linux-mkfs_2.32-r0_i586.ipk 1538425236 util-linux-mount_2.32-r0_i586.ipk 1538425236 util-linux-partx_2.32-r0_i586.ipk 1538425236 util-linux-readprofile_2.32-r0_i586.ipk 1538425236 util-linux-umount_2.32-r0_i586.ipk 1538425237 libblkid1_2.32-r0_i586.ipk 1538425237 libfdisk1_2.32-r0_i586.ipk 1538425237 libmount1_2.32-r0_i586.ipk 1538425238 util-linux_2.32-r0_i586.ipk 1538425240 util-linux-staticdev_2.32-r0_i586.ipk Indeed, the two ipk files have the same mtime (at least, on second level): $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk Size: 136612 Blocks: 272 IO Block: 4096 regular file Device: fd00h/64768d Inode: 2627769381 Links: 2 Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) Context: unconfined_u:object_r:home_root_t:s0 Access: 2018-10-01 22:28:37.464716076 +0200 Modify: 2018-10-01 22:20:37.930653796 +0200 Change: 2018-10-01 22:20:50.998205339 +0200 Birth: - File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk Size: 136692 Blocks: 272 IO Block: 4096 regular file Device: fd00h/64768d Inode: 2608876057 Links: 2 Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) Context: unconfined_u:object_r:home_root_t:s0 Access: 2018-10-01 22:28:47.145119532 +0200 Modify: 2018-10-01 22:20:37.358629653 +0200 Change: 2018-10-01 22:20:50.727193901 +0200 Birth: - But different md5sums! $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk 91608ae2b109e3f4af0379c634fad9c0 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk In that case, libblkid1_2.32-r0_i586.ipk of build1 managed to make it into the sstate. On our production system, the SDK builds called later always fetch the packages from sstate again (do_package_write_ipk_setscene). For some reason that did not happen in my synthetic test. However, I simulated the fetch from sstate by removing libblkid1_2.32-r0_i586.ipk (part of util-linux) from build2: build2 $ bitbake -c clean util-linux And rebuild the image: build2 $ bitbake -f -c populate_sdk core-image-minimal Which indeed showed the issues we are seeing in production: ... Downloading file:/home/ags/oe-core/build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk. Removing corrupt package file /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/sdk/image/usr/local/oecore-x86_64/sysroots/i586-oe-linux//var/cache/opkg/volatile/edad620216e689cf8778354f4ac2ff7e_libblkid1_2.32-r0_i586.ipk. ... Collected errors: * opkg_install_pkg: Failed to download libblkid1. Perhaps you need to run 'opkg update'? ... ERROR: core-image-minimal-1.0-r0 do_populate_sdk: Function failed: do_populate_sdk ERROR: Logfile of failure stored in: /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/temp/log.do_populate_sdk.49541 ERROR: Task (/home/ags/oe-core/meta/recipes-core/images/core-image-minimal.bb:do_populate_sdk) failed with exit code '1' It really seems that using mtime only in opkg-make-index is not safe enough in our setup. We probably should use the inode (or using the inode in addition to the time stamp). Is it guaranteed that the inode changes when ipk are fetched from sstate? -- Stefan > >> >> I guess there is some race/asynchronous operation going on around >> building index/getting package from sstate/pushing package to sstate. >> >> It seems an issue others have seen in the past too: >> https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 >> >> Any idea? >> >> -- >> Stefan ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Build failure with parallel build and opkg 2018-10-02 8:46 ` Stefan Agner @ 2018-10-02 13:12 ` Stefan Agner 2018-10-02 19:03 ` Khem Raj 2018-10-11 9:32 ` Stefan Agner 0 siblings, 2 replies; 6+ messages in thread From: Stefan Agner @ 2018-10-02 13:12 UTC (permalink / raw) To: openembedded-core, richard.purdie, Max Krummenacher Cc: Brandon Shibley, samuel.bissig, ricardo On 02.10.2018 10:46, Stefan Agner wrote: > On 26.09.2018 11:34, Stefan Agner wrote: >> Hi, >> >> On 12.09.2018 00:49, Stefan Agner wrote: > <snip> >> We discussed the issue at Linaro Connect a bit. >> >> To recap, we do build in two steps: >> >> 1. bitbake full-container-image >> 2. bitbake -c populate_sdk full-container-image >> >> The issue always happens in the second step. >> >> We also see that in the second step, the do_package_write_ipk_setscene >> task for every recipe is executed. >> >> The current assumption is >> >> I tried to reproduce by building a recipe using openembedded-core master >> only in two build directories with shared sstate manually: >> >> 1. build1 $ bitbake eudev >> 2. build2 $ bitbake -c cleansstate eudev >> 3. build2 $ bitbake eudev >> 4. build1 $ bitbake core-image-minimal >> >> This sequence seems not to have triggered a >> do_package_write_ipk_setscene for eudev. >> >> I then tried >> 5. build1 $ bitbake -c populate_sdk core-image-minimal >> >> Which did trigger a do_package_write_ipk_setscene. However, the issue >> did not appear... >> >> I even tried to rebuild and replace the file manually, and run bitbake >> -c populate_sdk -f core-image-minimal, but it just seems not to appear. >> >> Last time I have seen it was with oe-core >> f6634581fa0a81c4d68dc9179a755ad7b9d99357, I will revert to this version >> again to see whether that helps reproducing the issue. > > Using the older OE version did not make a difference. > > > So Max and I discussed a bit further. We realized that when OE rebuilds, > the opkg package index is refreshed for a package only if the mtime (in > seconds) is different between the previous file and the file on disk > currently (see opkg-make-index). Can it be that two simultaneously > started builds create two ipk with same mtime? > > So I built two core-image-minimal builds (on the same machine) at the > *very* same time. First try did not cause a collision, but already on > the second try I managed to reproduce multiple collision. This output > shows all the packages with the same unix mtime stamp according to the > Packages.stamps file (generated by opkg-make-index): > > $ comm -1 -2 <(sort build1/tmp-glibc/deploy/ipk/i586/Packages.stamps) <(sort build2/tmp-glibc/deploy/ipk/i586/Packages.stamps) > kages.stamps) > 1538424250 glibc-binary-localedata-de-it_2.27-r0_i586.ipk > 1538425082 libreadline-staticdev_7.0-r0_i586.ipk > 1538425162 bash-bashbug_4.4.18-r0_i586.ipk > 1538425162 bash-completion_2.8-r0_i586.ipk > 1538425162 bash-completion-dbg_2.8-r0_i586.ipk > 1538425162 bash-completion-dev_2.8-r0_i586.ipk > 1538425162 bash-loadable_4.4.18-r0_i586.ipk > 1538425163 bash_4.4.18-r0_i586.ipk > 1538425163 bash-completion-extra_2.8-r0_i586.ipk > 1538425164 bash-doc_4.4.18-r0_i586.ipk > 1538425167 bash-dbg_4.4.18-r0_i586.ipk > 1538425233 util-linux-locale-hr_2.32-r0_i586.ipk > 1538425233 util-linux-locale-id_2.32-r0_i586.ipk > 1538425233 util-linux-locale-it_2.32-r0_i586.ipk > 1538425233 util-linux-locale-sl_2.32-r0_i586.ipk > 1538425233 util-linux-locale-zh-tw_2.32-r0_i586.ipk > 1538425234 util-linux-dev_2.32-r0_i586.ipk > 1538425234 util-linux-findfs_2.32-r0_i586.ipk > 1538425234 util-linux-ionice_2.32-r0_i586.ipk > 1538425234 util-linux-locale-ca_2.32-r0_i586.ipk > 1538425234 util-linux-locale-pl_2.32-r0_i586.ipk > 1538425234 util-linux-locale-pt-br_2.32-r0_i586.ipk > 1538425234 util-linux-locale-ru_2.32-r0_i586.ipk > 1538425234 util-linux-locale-sv_2.32-r0_i586.ipk > 1538425234 util-linux-locale-tr_2.32-r0_i586.ipk > 1538425234 util-linux-locale-vi_2.32-r0_i586.ipk > 1538425234 util-linux-locale-zh-cn_2.32-r0_i586.ipk > 1538425234 util-linux-mountpoint_2.32-r0_i586.ipk > 1538425235 util-linux-locale-fr_2.32-r0_i586.ipk > 1538425236 util-linux-blkid_2.32-r0_i586.ipk > 1538425236 util-linux-fsck_2.32-r0_i586.ipk > 1538425236 util-linux-fsck.cramfs_2.32-r0_i586.ipk > 1538425236 util-linux-fstrim_2.32-r0_i586.ipk > 1538425236 util-linux-lscpu_2.32-r0_i586.ipk > 1538425236 util-linux-mkfs_2.32-r0_i586.ipk > 1538425236 util-linux-mount_2.32-r0_i586.ipk > 1538425236 util-linux-partx_2.32-r0_i586.ipk > 1538425236 util-linux-readprofile_2.32-r0_i586.ipk > 1538425236 util-linux-umount_2.32-r0_i586.ipk > 1538425237 libblkid1_2.32-r0_i586.ipk > 1538425237 libfdisk1_2.32-r0_i586.ipk > 1538425237 libmount1_2.32-r0_i586.ipk > 1538425238 util-linux_2.32-r0_i586.ipk > 1538425240 util-linux-staticdev_2.32-r0_i586.ipk > > Indeed, the two ipk files have the same mtime (at least, on second level): > > $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136612 Blocks: 272 IO Block: 4096 regular file > Device: fd00h/64768d Inode: 2627769381 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-01 22:28:37.464716076 +0200 > Modify: 2018-10-01 22:20:37.930653796 +0200 > Change: 2018-10-01 22:20:50.998205339 +0200 > Birth: - > File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136692 Blocks: 272 IO Block: 4096 regular file > Device: fd00h/64768d Inode: 2608876057 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-01 22:28:47.145119532 +0200 > Modify: 2018-10-01 22:20:37.358629653 +0200 > Change: 2018-10-01 22:20:50.727193901 +0200 > Birth: - > > But different md5sums! > > $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > 91608ae2b109e3f4af0379c634fad9c0 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > In that case, libblkid1_2.32-r0_i586.ipk of build1 managed to make it into the sstate. > > On our production system, the SDK builds called later always fetch the packages > from sstate again (do_package_write_ipk_setscene). For some reason that did not > happen in my synthetic test. However, I simulated the fetch from sstate by > removing libblkid1_2.32-r0_i586.ipk (part of util-linux) from build2: > > build2 $ bitbake -c clean util-linux > > And rebuild the image: > > build2 $ bitbake -f -c populate_sdk core-image-minimal > Note that after this command, the packages in the feed looks like this: $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk Size: 136612 Blocks: 272 IO Block: 4096 regular file Device: fd00h/64768d Inode: 2627769381 Links: 2 Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) Context: unconfined_u:object_r:home_root_t:s0 Access: 2018-10-01 22:28:37.464716076 +0200 Modify: 2018-10-01 22:20:37.930653796 +0200 Change: 2018-10-01 22:20:50.998205339 +0200 Birth: - File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk Size: 136612 Blocks: 272 IO Block: 4096 regular file Device: fd00h/64768d Inode: 2315301423 Links: 2 Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) Context: unconfined_u:object_r:home_root_t:s0 Access: 2018-10-02 09:27:07.750888458 +0200 Modify: 2018-10-01 22:20:37.000000000 +0200 Change: 2018-10-02 09:26:47.308004397 +0200 Birth: - Note that the package in build2 the mtime has no nanosecond accuracy. Presumably the tarball from sstate does not preserve sub second timestamps. $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk bb8ffd4443e84fede943ccc3292dc657 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk Will send out a patch which uses inodes instead of mtime in opkg-make-index. -- Stefan > Which indeed showed the issues we are seeing in production: > ... > Downloading file:/home/ags/oe-core/build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk. > Removing corrupt package file /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/sdk/image/usr/local/oecore-x86_64/sysroots/i586-oe-linux//var/cache/opkg/volatile/edad620216e689cf8778354f4ac2ff7e_libblkid1_2.32-r0_i586.ipk. > ... > Collected errors: > * opkg_install_pkg: Failed to download libblkid1. Perhaps you need to run 'opkg update'? > ... > ERROR: core-image-minimal-1.0-r0 do_populate_sdk: Function failed: do_populate_sdk > ERROR: Logfile of failure stored in: /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/temp/log.do_populate_sdk.49541 > ERROR: Task (/home/ags/oe-core/meta/recipes-core/images/core-image-minimal.bb:do_populate_sdk) failed with exit code '1' > > > It really seems that using mtime only in opkg-make-index is not safe enough > in our setup. We probably should use the inode (or using the inode in addition > to the time stamp). > > Is it guaranteed that the inode changes when ipk are fetched from sstate? > > -- > Stefan > > >> >>> >>> I guess there is some race/asynchronous operation going on around >>> building index/getting package from sstate/pushing package to sstate. >>> >>> It seems an issue others have seen in the past too: >>> https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 >>> >>> Any idea? >>> >>> -- >>> Stefan ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Build failure with parallel build and opkg 2018-10-02 13:12 ` Stefan Agner @ 2018-10-02 19:03 ` Khem Raj 2018-10-11 9:32 ` Stefan Agner 1 sibling, 0 replies; 6+ messages in thread From: Khem Raj @ 2018-10-02 19:03 UTC (permalink / raw) To: Stefan Agner Cc: Patches and discussions about the oe-core layer, Brandon Shibley, samuel.bissig, ricardo On Tue, Oct 2, 2018 at 6:13 AM Stefan Agner <stefan@agner.ch> wrote: > > On 02.10.2018 10:46, Stefan Agner wrote: > > On 26.09.2018 11:34, Stefan Agner wrote: > >> Hi, > >> > >> On 12.09.2018 00:49, Stefan Agner wrote: > > <snip> > >> We discussed the issue at Linaro Connect a bit. > >> > >> To recap, we do build in two steps: > >> > >> 1. bitbake full-container-image > >> 2. bitbake -c populate_sdk full-container-image > >> > >> The issue always happens in the second step. > >> > >> We also see that in the second step, the do_package_write_ipk_setscene > >> task for every recipe is executed. > >> > >> The current assumption is > >> > >> I tried to reproduce by building a recipe using openembedded-core master > >> only in two build directories with shared sstate manually: > >> > >> 1. build1 $ bitbake eudev > >> 2. build2 $ bitbake -c cleansstate eudev > >> 3. build2 $ bitbake eudev > >> 4. build1 $ bitbake core-image-minimal > >> > >> This sequence seems not to have triggered a > >> do_package_write_ipk_setscene for eudev. > >> > >> I then tried > >> 5. build1 $ bitbake -c populate_sdk core-image-minimal > >> > >> Which did trigger a do_package_write_ipk_setscene. However, the issue > >> did not appear... > >> > >> I even tried to rebuild and replace the file manually, and run bitbake > >> -c populate_sdk -f core-image-minimal, but it just seems not to appear. > >> > >> Last time I have seen it was with oe-core > >> f6634581fa0a81c4d68dc9179a755ad7b9d99357, I will revert to this version > >> again to see whether that helps reproducing the issue. > > > > Using the older OE version did not make a difference. > > > > > > So Max and I discussed a bit further. We realized that when OE rebuilds, > > the opkg package index is refreshed for a package only if the mtime (in > > seconds) is different between the previous file and the file on disk > > currently (see opkg-make-index). Can it be that two simultaneously > > started builds create two ipk with same mtime? > > > > So I built two core-image-minimal builds (on the same machine) at the > > *very* same time. First try did not cause a collision, but already on > > the second try I managed to reproduce multiple collision. This output > > shows all the packages with the same unix mtime stamp according to the > > Packages.stamps file (generated by opkg-make-index): > > > > $ comm -1 -2 <(sort build1/tmp-glibc/deploy/ipk/i586/Packages.stamps) <(sort build2/tmp-glibc/deploy/ipk/i586/Packages.stamps) > > kages.stamps) > > 1538424250 glibc-binary-localedata-de-it_2.27-r0_i586.ipk > > 1538425082 libreadline-staticdev_7.0-r0_i586.ipk > > 1538425162 bash-bashbug_4.4.18-r0_i586.ipk > > 1538425162 bash-completion_2.8-r0_i586.ipk > > 1538425162 bash-completion-dbg_2.8-r0_i586.ipk > > 1538425162 bash-completion-dev_2.8-r0_i586.ipk > > 1538425162 bash-loadable_4.4.18-r0_i586.ipk > > 1538425163 bash_4.4.18-r0_i586.ipk > > 1538425163 bash-completion-extra_2.8-r0_i586.ipk > > 1538425164 bash-doc_4.4.18-r0_i586.ipk > > 1538425167 bash-dbg_4.4.18-r0_i586.ipk > > 1538425233 util-linux-locale-hr_2.32-r0_i586.ipk > > 1538425233 util-linux-locale-id_2.32-r0_i586.ipk > > 1538425233 util-linux-locale-it_2.32-r0_i586.ipk > > 1538425233 util-linux-locale-sl_2.32-r0_i586.ipk > > 1538425233 util-linux-locale-zh-tw_2.32-r0_i586.ipk > > 1538425234 util-linux-dev_2.32-r0_i586.ipk > > 1538425234 util-linux-findfs_2.32-r0_i586.ipk > > 1538425234 util-linux-ionice_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-ca_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-pl_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-pt-br_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-ru_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-sv_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-tr_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-vi_2.32-r0_i586.ipk > > 1538425234 util-linux-locale-zh-cn_2.32-r0_i586.ipk > > 1538425234 util-linux-mountpoint_2.32-r0_i586.ipk > > 1538425235 util-linux-locale-fr_2.32-r0_i586.ipk > > 1538425236 util-linux-blkid_2.32-r0_i586.ipk > > 1538425236 util-linux-fsck_2.32-r0_i586.ipk > > 1538425236 util-linux-fsck.cramfs_2.32-r0_i586.ipk > > 1538425236 util-linux-fstrim_2.32-r0_i586.ipk > > 1538425236 util-linux-lscpu_2.32-r0_i586.ipk > > 1538425236 util-linux-mkfs_2.32-r0_i586.ipk > > 1538425236 util-linux-mount_2.32-r0_i586.ipk > > 1538425236 util-linux-partx_2.32-r0_i586.ipk > > 1538425236 util-linux-readprofile_2.32-r0_i586.ipk > > 1538425236 util-linux-umount_2.32-r0_i586.ipk > > 1538425237 libblkid1_2.32-r0_i586.ipk > > 1538425237 libfdisk1_2.32-r0_i586.ipk > > 1538425237 libmount1_2.32-r0_i586.ipk > > 1538425238 util-linux_2.32-r0_i586.ipk > > 1538425240 util-linux-staticdev_2.32-r0_i586.ipk > > > > Indeed, the two ipk files have the same mtime (at least, on second level): > > > > $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > Size: 136612 Blocks: 272 IO Block: 4096 regular file > > Device: fd00h/64768d Inode: 2627769381 Links: 2 > > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > > Context: unconfined_u:object_r:home_root_t:s0 > > Access: 2018-10-01 22:28:37.464716076 +0200 > > Modify: 2018-10-01 22:20:37.930653796 +0200 > > Change: 2018-10-01 22:20:50.998205339 +0200 > > Birth: - > > File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > Size: 136692 Blocks: 272 IO Block: 4096 regular file > > Device: fd00h/64768d Inode: 2608876057 Links: 2 > > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > > Context: unconfined_u:object_r:home_root_t:s0 > > Access: 2018-10-01 22:28:47.145119532 +0200 > > Modify: 2018-10-01 22:20:37.358629653 +0200 > > Change: 2018-10-01 22:20:50.727193901 +0200 > > Birth: - > > > > But different md5sums! > > > > $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > 91608ae2b109e3f4af0379c634fad9c0 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > > > In that case, libblkid1_2.32-r0_i586.ipk of build1 managed to make it into the sstate. > > > > On our production system, the SDK builds called later always fetch the packages > > from sstate again (do_package_write_ipk_setscene). For some reason that did not > > happen in my synthetic test. However, I simulated the fetch from sstate by > > removing libblkid1_2.32-r0_i586.ipk (part of util-linux) from build2: > > > > build2 $ bitbake -c clean util-linux > > > > And rebuild the image: > > > > build2 $ bitbake -f -c populate_sdk core-image-minimal > > > > Note that after this command, the packages in the feed looks like this: > > $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136612 Blocks: 272 IO Block: 4096 regular file > Device: fd00h/64768d Inode: 2627769381 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-01 22:28:37.464716076 +0200 > Modify: 2018-10-01 22:20:37.930653796 +0200 > Change: 2018-10-01 22:20:50.998205339 +0200 > Birth: - > File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136612 Blocks: 272 IO Block: 4096 regular file > Device: fd00h/64768d Inode: 2315301423 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-02 09:27:07.750888458 +0200 > Modify: 2018-10-01 22:20:37.000000000 +0200 > Change: 2018-10-02 09:26:47.308004397 +0200 > Birth: - > > Note that the package in build2 the mtime has no nanosecond accuracy. Presumably > the tarball from sstate does not preserve sub second timestamps. > > $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > bb8ffd4443e84fede943ccc3292dc657 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > Will send out a patch which uses inodes instead of mtime in opkg-make-index. > Thats a good find Stefan, How about using ctime instead of mtime. > -- > Stefan > > > > Which indeed showed the issues we are seeing in production: > > ... > > Downloading file:/home/ags/oe-core/build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk. > > Removing corrupt package file /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/sdk/image/usr/local/oecore-x86_64/sysroots/i586-oe-linux//var/cache/opkg/volatile/edad620216e689cf8778354f4ac2ff7e_libblkid1_2.32-r0_i586.ipk. > > ... > > Collected errors: > > * opkg_install_pkg: Failed to download libblkid1. Perhaps you need to run 'opkg update'? > > ... > > ERROR: core-image-minimal-1.0-r0 do_populate_sdk: Function failed: do_populate_sdk > > ERROR: Logfile of failure stored in: /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/temp/log.do_populate_sdk.49541 > > ERROR: Task (/home/ags/oe-core/meta/recipes-core/images/core-image-minimal.bb:do_populate_sdk) failed with exit code '1' > > > > > > It really seems that using mtime only in opkg-make-index is not safe enough > > in our setup. We probably should use the inode (or using the inode in addition > > to the time stamp). > > > > Is it guaranteed that the inode changes when ipk are fetched from sstate? > > > > -- > > Stefan > > > > > >> > >>> > >>> I guess there is some race/asynchronous operation going on around > >>> building index/getting package from sstate/pushing package to sstate. > >>> > >>> It seems an issue others have seen in the past too: > >>> https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 > >>> > >>> Any idea? > >>> > >>> -- > >>> Stefan > -- > _______________________________________________ > Openembedded-core mailing list > Openembedded-core@lists.openembedded.org > http://lists.openembedded.org/mailman/listinfo/openembedded-core ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Build failure with parallel build and opkg 2018-10-02 13:12 ` Stefan Agner 2018-10-02 19:03 ` Khem Raj @ 2018-10-11 9:32 ` Stefan Agner 1 sibling, 0 replies; 6+ messages in thread From: Stefan Agner @ 2018-10-11 9:32 UTC (permalink / raw) To: openembedded-core, richard.purdie, Max Krummenacher Cc: Brandon Shibley, samuel.bissig, ricardo On 02.10.2018 15:12, Stefan Agner wrote: > On 02.10.2018 10:46, Stefan Agner wrote: >> On 26.09.2018 11:34, Stefan Agner wrote: >>> Hi, >>> >>> On 12.09.2018 00:49, Stefan Agner wrote: >> <snip> >>> We discussed the issue at Linaro Connect a bit. >>> >>> To recap, we do build in two steps: >>> >>> 1. bitbake full-container-image >>> 2. bitbake -c populate_sdk full-container-image >>> >>> The issue always happens in the second step. >>> >>> We also see that in the second step, the do_package_write_ipk_setscene >>> task for every recipe is executed. >>> >>> The current assumption is >>> >>> I tried to reproduce by building a recipe using openembedded-core master >>> only in two build directories with shared sstate manually: >>> >>> 1. build1 $ bitbake eudev >>> 2. build2 $ bitbake -c cleansstate eudev >>> 3. build2 $ bitbake eudev >>> 4. build1 $ bitbake core-image-minimal >>> >>> This sequence seems not to have triggered a >>> do_package_write_ipk_setscene for eudev. >>> >>> I then tried >>> 5. build1 $ bitbake -c populate_sdk core-image-minimal >>> >>> Which did trigger a do_package_write_ipk_setscene. However, the issue >>> did not appear... >>> >>> I even tried to rebuild and replace the file manually, and run bitbake >>> -c populate_sdk -f core-image-minimal, but it just seems not to appear. >>> >>> Last time I have seen it was with oe-core >>> f6634581fa0a81c4d68dc9179a755ad7b9d99357, I will revert to this version >>> again to see whether that helps reproducing the issue. >> >> Using the older OE version did not make a difference. >> >> >> So Max and I discussed a bit further. We realized that when OE rebuilds, >> the opkg package index is refreshed for a package only if the mtime (in >> seconds) is different between the previous file and the file on disk >> currently (see opkg-make-index). Can it be that two simultaneously >> started builds create two ipk with same mtime? >> >> So I built two core-image-minimal builds (on the same machine) at the >> *very* same time. First try did not cause a collision, but already on >> the second try I managed to reproduce multiple collision. This output >> shows all the packages with the same unix mtime stamp according to the >> Packages.stamps file (generated by opkg-make-index): >> >> $ comm -1 -2 <(sort build1/tmp-glibc/deploy/ipk/i586/Packages.stamps) <(sort build2/tmp-glibc/deploy/ipk/i586/Packages.stamps) >> kages.stamps) >> 1538424250 glibc-binary-localedata-de-it_2.27-r0_i586.ipk >> 1538425082 libreadline-staticdev_7.0-r0_i586.ipk >> 1538425162 bash-bashbug_4.4.18-r0_i586.ipk >> 1538425162 bash-completion_2.8-r0_i586.ipk >> 1538425162 bash-completion-dbg_2.8-r0_i586.ipk >> 1538425162 bash-completion-dev_2.8-r0_i586.ipk >> 1538425162 bash-loadable_4.4.18-r0_i586.ipk >> 1538425163 bash_4.4.18-r0_i586.ipk >> 1538425163 bash-completion-extra_2.8-r0_i586.ipk >> 1538425164 bash-doc_4.4.18-r0_i586.ipk >> 1538425167 bash-dbg_4.4.18-r0_i586.ipk >> 1538425233 util-linux-locale-hr_2.32-r0_i586.ipk >> 1538425233 util-linux-locale-id_2.32-r0_i586.ipk >> 1538425233 util-linux-locale-it_2.32-r0_i586.ipk >> 1538425233 util-linux-locale-sl_2.32-r0_i586.ipk >> 1538425233 util-linux-locale-zh-tw_2.32-r0_i586.ipk >> 1538425234 util-linux-dev_2.32-r0_i586.ipk >> 1538425234 util-linux-findfs_2.32-r0_i586.ipk >> 1538425234 util-linux-ionice_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-ca_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-pl_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-pt-br_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-ru_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-sv_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-tr_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-vi_2.32-r0_i586.ipk >> 1538425234 util-linux-locale-zh-cn_2.32-r0_i586.ipk >> 1538425234 util-linux-mountpoint_2.32-r0_i586.ipk >> 1538425235 util-linux-locale-fr_2.32-r0_i586.ipk >> 1538425236 util-linux-blkid_2.32-r0_i586.ipk >> 1538425236 util-linux-fsck_2.32-r0_i586.ipk >> 1538425236 util-linux-fsck.cramfs_2.32-r0_i586.ipk >> 1538425236 util-linux-fstrim_2.32-r0_i586.ipk >> 1538425236 util-linux-lscpu_2.32-r0_i586.ipk >> 1538425236 util-linux-mkfs_2.32-r0_i586.ipk >> 1538425236 util-linux-mount_2.32-r0_i586.ipk >> 1538425236 util-linux-partx_2.32-r0_i586.ipk >> 1538425236 util-linux-readprofile_2.32-r0_i586.ipk >> 1538425236 util-linux-umount_2.32-r0_i586.ipk >> 1538425237 libblkid1_2.32-r0_i586.ipk >> 1538425237 libfdisk1_2.32-r0_i586.ipk >> 1538425237 libmount1_2.32-r0_i586.ipk >> 1538425238 util-linux_2.32-r0_i586.ipk >> 1538425240 util-linux-staticdev_2.32-r0_i586.ipk >> >> Indeed, the two ipk files have the same mtime (at least, on second level): >> >> $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> Size: 136612 Blocks: 272 IO Block: 4096 regular file >> Device: fd00h/64768d Inode: 2627769381 Links: 2 >> Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) >> Context: unconfined_u:object_r:home_root_t:s0 >> Access: 2018-10-01 22:28:37.464716076 +0200 >> Modify: 2018-10-01 22:20:37.930653796 +0200 >> Change: 2018-10-01 22:20:50.998205339 +0200 >> Birth: - >> File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> Size: 136692 Blocks: 272 IO Block: 4096 regular file >> Device: fd00h/64768d Inode: 2608876057 Links: 2 >> Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ ags) >> Context: unconfined_u:object_r:home_root_t:s0 >> Access: 2018-10-01 22:28:47.145119532 +0200 >> Modify: 2018-10-01 22:20:37.358629653 +0200 >> Change: 2018-10-01 22:20:50.727193901 +0200 >> Birth: - >> >> But different md5sums! >> >> $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> bb8ffd4443e84fede943ccc3292dc657 ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> 91608ae2b109e3f4af0379c634fad9c0 ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk >> >> In that case, libblkid1_2.32-r0_i586.ipk of build1 managed to make it into the sstate. >> >> On our production system, the SDK builds called later always fetch the packages >> from sstate again (do_package_write_ipk_setscene). For some reason that did not >> happen in my synthetic test. However, I simulated the fetch from sstate by >> removing libblkid1_2.32-r0_i586.ipk (part of util-linux) from build2: >> >> build2 $ bitbake -c clean util-linux >> >> And rebuild the image: >> >> build2 $ bitbake -f -c populate_sdk core-image-minimal >> > > Note that after this command, the packages in the feed looks like this: > > $ stat ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > File: ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136612 Blocks: 272 IO Block: 4096 regular > file > Device: fd00h/64768d Inode: 2627769381 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ > ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-01 22:28:37.464716076 +0200 > Modify: 2018-10-01 22:20:37.930653796 +0200 > Change: 2018-10-01 22:20:50.998205339 +0200 > Birth: - > File: ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > Size: 136612 Blocks: 272 IO Block: 4096 regular > file > Device: fd00h/64768d Inode: 2315301423 Links: 2 > Access: (0644/-rw-r--r--) Uid: ( 1002/ ags) Gid: ( 1002/ > ags) > Context: unconfined_u:object_r:home_root_t:s0 > Access: 2018-10-02 09:27:07.750888458 +0200 > Modify: 2018-10-01 22:20:37.000000000 +0200 > Change: 2018-10-02 09:26:47.308004397 +0200 > Birth: - > > Note that the package in build2 the mtime has no nanosecond accuracy. Presumably > the tarball from sstate does not preserve sub second timestamps. > > $ md5sum ./build*/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > bb8ffd4443e84fede943ccc3292dc657 > ./build1/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > bb8ffd4443e84fede943ccc3292dc657 > ./build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk > > Will send out a patch which uses inodes instead of mtime in opkg-make-index. > > -- > Stefan > > >> Which indeed showed the issues we are seeing in production: >> ... >> Downloading file:/home/ags/oe-core/build2/tmp-glibc/deploy/ipk/i586/libblkid1_2.32-r0_i586.ipk. >> Removing corrupt package file /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/sdk/image/usr/local/oecore-x86_64/sysroots/i586-oe-linux//var/cache/opkg/volatile/edad620216e689cf8778354f4ac2ff7e_libblkid1_2.32-r0_i586.ipk. >> ... >> Collected errors: >> * opkg_install_pkg: Failed to download libblkid1. Perhaps you need to run 'opkg update'? >> ... >> ERROR: core-image-minimal-1.0-r0 do_populate_sdk: Function failed: do_populate_sdk >> ERROR: Logfile of failure stored in: /home/ags/oe-core/build2/tmp-glibc/work/qemux86-oe-linux/core-image-minimal/1.0-r0/temp/log.do_populate_sdk.49541 >> ERROR: Task (/home/ags/oe-core/meta/recipes-core/images/core-image-minimal.bb:do_populate_sdk) failed with exit code '1' >> >> >> It really seems that using mtime only in opkg-make-index is not safe enough >> in our setup. We probably should use the inode (or using the inode in addition >> to the time stamp). >> >> Is it guaranteed that the inode changes when ipk are fetched from sstate? Unfortunately, testing with inodes instead of mtime as Packages.stamps turned out to be equally unreliable. It seems that when the package is fetched from sstate, inode is preserved: In a particular case: $ stat /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/libbz2-1_1.0.6-r5_armv7at2hf-neon.ipk File: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/libbz2-1_1.0.6-r5_armv7at2hf-neon.ipk Size: 26144 Blocks: 56 IO Block: 4096 regular file Device: 801h/2049d Inode: 151929072 Links: 2 Access: (0644/-rw-r--r--) Uid: ( 1003/ yocto) Gid: ( 1003/ yocto) Access: 2018-10-10 10:14:37.022012933 +0000 Modify: 2018-10-10 08:43:51.000000000 +0000 Change: 2018-10-10 10:12:54.026508198 +0000 Birth: - (modification time ns is 0 -> file has been fetched from sstate). I recorded Inode on every opkg-make-index invocation, and it seems that inode was always 151929072. The log.do_package_write_ipk_setscene from that package shows: DEBUG: Executing python function do_package_write_ipk_setscene DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/bzip2_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/bzip2-doc_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/bzip2-staticdev_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/bzip2-dbg_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/bzip2-dev_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/libbz2-1_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Removing manifest: /workdir/oe/tmp/deploy/ipk/armv7at2hf-neon/ DEBUG: SITE files ['endian-little', 'bit-32', 'arm-common', 'arm-32', 'common-linux', 'common-glibc', 'arm-linux', 'arm-linux-gnueabi', 'common'] DEBUG: Executing shell function sstate_unpack_package deploy-ipks/ deploy-ipks/armv7at2hf-neon/ deploy-ipks/armv7at2hf-neon/bzip2_1.0.6-r5_armv7at2hf-neon.ipk deploy-ipks/armv7at2hf-neon/bzip2-doc_1.0.6-r5_armv7at2hf-neon.ipk deploy-ipks/armv7at2hf-neon/bzip2-staticdev_1.0.6-r5_armv7at2hf-neon.ipk deploy-ipks/armv7at2hf-neon/bzip2-dbg_1.0.6-r5_armv7at2hf-neon.ipk deploy-ipks/armv7at2hf-neon/bzip2-dev_1.0.6-r5_armv7at2hf-neon.ipk deploy-ipks/armv7at2hf-neon/libbz2-1_1.0.6-r5_armv7at2hf-neon.ipk DEBUG: Shell function sstate_unpack_package finished DEBUG: Executing python function sstate_hardcode_path_unpack DEBUG: Python function sstate_hardcode_path_unpack finished DEBUG: Executing python function buildhistory_emit_outputsigs DEBUG: Python function buildhistory_emit_outputsigs finished DEBUG: Staging files from /workdir/oe/tmp/work/armv7at2hf-neon-lmp-linux-gnueabi/bzip2/1.0.6-r5/deploy-ipks to /workdir/oe/tmp/deploy/ipk DEBUG: Executing python function buildhistory_emit_pkghistory DEBUG: Python function buildhistory_emit_pkghistory finished DEBUG: Python function do_package_write_ipk_setscene finished So I guess the "Staging files" step preserves the target files inode number... It seems that ctime is modified though, so our best chance is probably ctime. I will run some tests suing ctime. -- Stefan >> >> -- >> Stefan >> >> >>> >>>> >>>> I guess there is some race/asynchronous operation going on around >>>> building index/getting package from sstate/pushing package to sstate. >>>> >>>> It seems an issue others have seen in the past too: >>>> https://www.yoctoproject.org/irc/%23yocto.2018-07-05.log.html#t2018-07-05T10:07:25 >>>> >>>> Any idea? >>>> >>>> -- >>>> Stefan ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2018-10-11 9:32 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2018-09-11 22:49 Build failure with parallel build and opkg Stefan Agner 2018-09-26 9:34 ` Stefan Agner 2018-10-02 8:46 ` Stefan Agner 2018-10-02 13:12 ` Stefan Agner 2018-10-02 19:03 ` Khem Raj 2018-10-11 9:32 ` Stefan Agner
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.