15428 2024-03-07 15:06:10 +0000 postinstall failures with opkg in systemd enabled images 2024-03-30 22:34:44 +0000 1 1 11 Runtime System Startup system-startup unspecified x86 Multiple RESOLVED FIXED High normal 5.0 M4 1 richard.purdie tim.orling alexandre.belloni changqing.li joaomarcos.costa kevin.tian Qi.Chen randy.macleod ross.burton tim.orling --- --- No (bug/feature does not impact docs) oldest_to_newest 98404 0 richard.purdie 2024-03-07 15:06:10 +0000 We're seeing an issue where opkg sometimes fails trying to run-postinsts. This only seems to happen in systemd based images. The postinstall.log file contains: Traceback (most recent call last): File "/home/pokybuild/yocto-worker/qemux86-64-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) File "/home/pokybuild/yocto-worker/qemux86-64-alt/build/meta/lib/oeqa/runtime/cases/parselogs.py", line 185, in test_parselogs self.assertEqual(errcount, 0, msg=self.msg) AssertionError: 1 != 0 : Log: /home/pokybuild/yocto-worker/qemux86-64-alt/build/build/tmp/work/qemux86_64-poky-linux/core-image-full-cmdline/1.0/target_logs/postinstall.log ----------------------- Central error: * opkg_cmd_exec: Command failed to capture privilege lock: Resource temporarily unavailable. *********************** * opkg_lock: Could not lock /run/opkg.lock: Resource temporarily unavailable. * opkg_cmd_exec: Command failed to capture privilege lock: Resource temporarily unavailable. *********************** 1 errors found in logs. https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7500/steps/14/logs/stdio (core-image-full-cmdline, alma9-ty-2, qemux86-64-alt) https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7406/steps/14/logs/stdio (core-image-full-cmdline, fedora39-ty-2, qemux86-alt) https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7496/steps/13/logs/stdio (core-image-full-cmdline, fedora38-ty-3, qemux86-64-alt) 98412 1 randy.macleod 2024-03-07 15:17:15 +0000 Added Qi and Changqing in case they have some idea of how systemd could be involved in this opkg lock problem. We (WR) don't use opkg but we can help if we have an idea of what the underlying problem is. 98421 2 tim.orling 2024-03-07 16:04:40 +0000 RP suggested putting a wrapper around the opkg calls to emit what it is trying to install/do. His instinct/hunch is also that it is systemd related. 98430 3 richard.purdie 2024-03-07 23:16:12 +0000 Two failures in https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7411/steps/14/logs/stdio core-image-full-cmdline and core-image-sato-sdk 98431 4 tim.orling 2024-03-08 00:02:33 +0000 That build was Worker: alma9-ty-2 98432 5 Qi.Chen 2024-03-08 02:26:45 +0000 Hi All, If this is only failing for systemd, then my guess is that the problem might be related to the 'DefaultDependencies=no' setting in meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service. Both sysvinit and systemd are only running 'run-postinsts', but sysvinit is using 'INITSCRIPT_PARAMS = "start 99 S ."', this means the script is run as the last script in /etc/rcS.d. Regards, Qi 98433 6 Qi.Chen 2024-03-08 02:46:44 +0000 Sorry about the noise. Giving it a second thought, I found my above comment useless. 98434 7 tim.orling 2024-03-08 05:52:08 +0000 Each of the /var/lib/opkg/info/${PN}.postinst scripts has `set -e` in it, so I thought let's try removing that. Hoping to catch failures as they happen. I'm trying a couple builds with only that commit now to see if they fail. The run-postinst.service has no retry or timeout capability, so I thought let us try adding that. I tried a couple builds with both commits and they did not fail. https://git.yoctoproject.org/poky-contrib/log/?h=timo/opkg_postinst_15428 In my attempts, I am trying to only test on the combinations that have previously failed: qemux86-64-alt, qemux86-alt alma9-ty-2, fedora39-ty-2, fedora38-ty-3 If there is an "easy" way to script staging builds (and then basically looping them) it would help a lot. I suppose this is a case for a custom branch of yocto-autobuilder-helper... I locally tested the culprit image targets in loops of 100 and 50 and they did not fail (sadly, not 100% confident I am replicating the test configuration). These loops were not with the above branch... just with master-next. I have no reason to suspect host distro is a factor, but my host is ubuntu-22.04 on AMD x86-64. So far the failures are on "rpm" based distros. I'd like to loop on the AB (once a build finishes, run it again for N runs with the same configuration on the same worker) to try to get some statistics on how frequent the failure is (and while also trying to further instrument the failure). Back a few years ago when we had intermittent (and much rarer) failures, Randy Witt would loop in docker containers for something like 100,000 runs over a weekend to get a reliable fingerprint of the culprit. As I recall that failure (something rare in bitbake) was about a 0.3% failure rate... 98435 8 tim.orling 2024-03-08 06:04:09 +0000 I just realized `set -e` is "Exit immediately if a command exits with a non-zero status." which is probably what we want. Turning that off will probably give us bizarre delayed errors, if any (like we have now?). When I am less brain fogged I will take another look at better instrumentation of the opkg run-postinsts. Probably `set -x` "Print commands and their arguments as they are executed." will help, but that will be more code, adding a "def add_set_x_to_scriptlets(pkg):" or maybe just replace all instances of `set -e` with `set -x` in all the scriptlets to make it "easy". https://git.yoctoproject.org/poky/tree/meta/lib/oe/packagedata.py#n209 98443 9 tim.orling 2024-03-09 04:01:08 +0000 Trying a new testing branch (set -e -x for opkg postinsts): https://git.yoctoproject.org/poky-contrib/tree/?h=timo/opkg_postinst_debug alma-9-ty-2, qemux86-64-alt 98445 10 tim.orling 2024-03-09 18:51:05 +0000 Related query on the mailing list: https://lore.kernel.org/all/CAMKF1spKdnjMFpD=Qf_1vCzOeAN-Xg5GqQJviNLPXRq6md-tbQ@mail.gmail.com/T/ 98478 11 tim.orling 2024-03-14 15:09:45 +0000 RP's idea was to replace opkg binary with a script that appends the opkg call/arguments, process number, dump the process tree at the time. Trying to figure out if two things are running at the same time. 98479 12 tim.orling 2024-03-14 15:15:44 +0000 Re-running https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7411/steps/14/logs/stdio did not fail https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7446 98500 13 richard.purdie 2024-03-16 17:07:19 +0000 I had a look at an opkg created core-image-full-cmdline and what is interesting is that run-postinsts is removed at the end of rootfs construction as there are no deferred postinsts in the image. I checked a failed build on the autobuilder and confirmed that a failed image did not have any deferred postinsts and did not have run-postinsts installed. I also confirmed the systemd logs do show a run-postinsts service being added/removed in the failed build. What this tells us is that it is likely the opkg test case itself: oeqa/runtime/cases/opkg.py: self.pkg('remove run-postinsts-dev') oeqa/runtime/cases/opkg.py: self.pkg('install run-postinsts-dev') is the thing which is installing/running the postinsts package and perhaps the package manager itself racing against the systemd service running. 98501 14 richard.purdie 2024-03-16 17:08:29 +0000 I'd also note you can log opkg activity both during rootfs construction and on target with: diff --git a/meta/recipes-devtools/opkg/opkg/wrapper b/meta/recipes-devtools/opkg/opkg/wrapper new file mode 100644 index 00000000000..0e8902771f0 --- /dev/null +++ b/meta/recipes-devtools/opkg/opkg/wrapper @@ -0,0 +1,8 @@ +#!/bin/bash +realpath=`readlink -fn $0` +realdir=`dirname $realpath` +echo "New call $$" >> /tmp/opkglog +date >> /tmp/opkglog +ps >> /tmp/opkglog +echo "$@" >> /tmp/opkglog +exec -a $realdir/opkg $realdir/opkg.real "$@" diff --git a/meta/recipes-devtools/opkg/opkg_0.6.3.bb b/meta/recipes-devtools/opkg/opkg_0.6.3.bb index 9592ffc5d6d..7f42b8ed7bc 100644 --- a/meta/recipes-devtools/opkg/opkg_0.6.3.bb +++ b/meta/recipes-devtools/opkg/opkg_0.6.3.bb @@ -17,6 +17,7 @@ SRC_URI = "http://downloads.yoctoproject.org/releases/${BPN}/${BPN}-${PV}.tar.gz file://0001-opkg_conf-create-opkg.lock-in-run-instead-of-var-run.patch \ file://0001-libopkg-Use-libgen.h-to-provide-basename-API.patch \ file://run-ptest \ + file://wrapper \ " SRC_URI[sha256sum] = "f3938e359646b406c40d5d442a1467c7e72357f91ab822e442697529641e06de" @@ -54,6 +55,8 @@ do_install:append () { # We need to create the lock directory install -d ${D}${OPKGLIBDIR}/opkg + mv ${D}${bindir}/opkg ${D}${bindir}/opkg.real + install -m 0755 ${WORKDIR}/wrapper ${D}${bindir}/opkg } do_install_ptest () { @@ -70,7 +73,7 @@ def qa_check_solver_deprecation (pn, d, messages): oe.qa.handle_error("internal-solver-deprecation", "The opkg internal solver will be deprecated in future opkg releases. Consider enabling \"libsolv\" in PACKAGECONFIG.", d) -RDEPENDS:${PN} = "${VIRTUAL-RUNTIME_update-alternatives} opkg-arch-config libarchive" +RDEPENDS:${PN} = "${VIRTUAL-RUNTIME_update-alternatives} opkg-arch-config libarchive bash" RDEPENDS:${PN}:class-native = "" RDEPENDS:${PN}:class-nativesdk = "" RDEPENDS:${PN}-ptest += "make binutils python3-core python3-compression bash python3-crypt python3-io" 98504 15 richard.purdie 2024-03-16 21:23:03 +0000 The on target command sequence triggered by the tests is: opkg update opkg remove run-postinsts-dev opkg install run-postinsts-dev configure where configure is being run by run-postinsts 98505 16 richard.purdie 2024-03-16 21:48:36 +0000 Which leads to a reproducer: diff --git a/meta/classes-recipe/systemd.bbclass b/meta/classes-recipe/systemd.bbclass index 48b364c1d4d..3bb28442bd1 100644 --- a/meta/classes-recipe/systemd.bbclass +++ b/meta/classes-recipe/systemd.bbclass @@ -49,6 +49,7 @@ if systemctl >/dev/null 2>/dev/null; then if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then systemctl --no-block restart ${SYSTEMD_SERVICE_ESCAPED} fi + sleep 5 fi fi } then bitbake core-image-full-cmdline -c testimage 98560 17 tim.orling 2024-03-21 14:49:18 +0000 *** Bug 15450 has been marked as a duplicate of this bug. *** 98569 18 tim.orling 2024-03-21 16:49:08 +0000 Looks like a do-while loop in opkg_lock() is working: https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7578 https://git.yoctoproject.org/poky-contrib/commit/?h=timo/opkg_postinst_debug&id=10786c2391e3272db4231de93c706f82239c7965 Patch submitted to upstream opkg: https://lists.yoctoproject.org/g/opkg/message/60 Patch submitted for interim fix: https://patchwork.yoctoproject.org/project/oe-core/patch/20240321164744.3007283-1-tim.orling@konsulko.com/ 98574 19 tim.orling 2024-03-21 20:36:38 +0000 Working in parallel on the other approach (flock in run-postinsts itself): https://git.yoctoproject.org/poky-contrib/log/?h=timo/opkg_lock_flock_run-postinsts Brings up an interesting failure that I saw on target when trying to manually run the opkg oeqa runtime test steps previously: Traceback (most recent call last): File ".../workspace-upgrades/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) File ".../workspace-upgrades/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) [Previous line repeated 1 more time] File ".../workspace-upgrades/poky/meta/lib/oeqa/runtime/cases/opkg.py", line 59, in test_opkg_install_from_repo self.pkg('install run-postinsts-dev') File ".../workspace-upgrades/poky/meta/lib/oeqa/runtime/cases/opkg.py", line 19, in pkg self.assertEqual(status, expected, message) AssertionError: 255 != 0 : opkg install run-postinsts-dev * opkg_prepare_url_for_install: Couldn't find anything to satisfy 'run-postinsts-dev'. I assume it needs an ipk package-feed to work in this case (after removing the run-postinsts-dev package, it tries to install the same package and then run configure)? 98578 20 Qi.Chen 2024-03-22 03:01:51 +0000 I just found a related issue. We're using the same SYSTEMD_AUTO_ENABLE variable to control two different actions: enable & start/restart after target installation. The related codes are: systemd_postinst() { if systemctl >/dev/null 2>/dev/null; then OPTS="" if [ -n "$D" ]; then OPTS="--root=$D" fi if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then for service in ${SYSTEMD_SERVICE_ESCAPED}; do systemctl ${OPTS} enable "$service" done fi if [ -z "$D" ]; then systemctl daemon-reload systemctl preset ${SYSTEMD_SERVICE_ESCAPED} if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then systemctl --no-block restart ${SYSTEMD_SERVICE_ESCAPED} fi fi fi } A new variable seems needed. Not sure its suitable name. SYSTEMD_AUTO_START_AFTER_TARGET_INSTALLATION? The run-postinsts script is not run when installed on sysvinit targets, but it's run on systemd targets. It seems that this service should be enabled but not immediately started/restarted when installed on target. 98589 21 joaomarcos.costa 2024-03-22 16:15:57 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7572/steps/14/logs/stdio qemux86-64-alt debian11-ty-1 Traceback (most recent call last): File "/home/pokybuild/yocto-worker/qemux86-64-alt/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) File "/home/pokybuild/yocto-worker/qemux86-64-alt/build/meta/lib/oeqa/runtime/cases/parselogs.py", line 185, in test_parselogs self.assertEqual(errcount, 0, msg=self.msg) AssertionError: 1 != 0 : Log: /home/pokybuild/yocto-worker/qemux86-64-alt/build/build/tmp/work/qemux86_64-poky-linux/core-image-full-cmdline/1.0/target_logs/postinstall.log ----------------------- Central error: * opkg_cmd_exec: Command failed to capture privilege lock: Resource temporarily unavailable. *********************** * opkg_lock: Could not lock /run/opkg.lock: Resource temporarily unavailable. * opkg_cmd_exec: Command failed to capture privilege lock: Resource temporarily unavailable. *********************** 1 errors found in logs. 98596 22 tim.orling 2024-03-22 20:17:44 +0000 (In reply to Chen Qi from comment #20) > I just found a related issue. > We're using the same SYSTEMD_AUTO_ENABLE variable to control two different > actions: enable & start/restart after target installation. restart is clearly the problem :) > > The related codes are: > systemd_postinst() { > if systemctl >/dev/null 2>/dev/null; then > OPTS="" > > if [ -n "$D" ]; then > OPTS="--root=$D" > fi > > if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then > for service in ${SYSTEMD_SERVICE_ESCAPED}; do > systemctl ${OPTS} enable "$service" > done > fi > > if [ -z "$D" ]; then > systemctl daemon-reload > systemctl preset ${SYSTEMD_SERVICE_ESCAPED} > > if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then > systemctl --no-block restart > ${SYSTEMD_SERVICE_ESCAPED} > fi > fi > fi > } > > A new variable seems needed. Not sure its suitable name. > SYSTEMD_AUTO_START_AFTER_TARGET_INSTALLATION? Interesting idea. I somehow think some kind of "smarter" systemd service dependencies/rules would help. I did try a little bit of investigation into the service itself, although I am not claiming to be fully understanding all the nuances of this bug. diff --git a/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service b/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service index b6b81d5c1a1..19331d656a5 100644 --- a/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service +++ b/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service @@ -1,6 +1,7 @@ [Unit] Description=Run pending postinsts DefaultDependencies=no +StartLimitIntervalSec=5 After=systemd-remount-fs.service systemd-tmpfiles-setup.service tmp.mount ldconfig.service Before=sysinit.target @@ -9,7 +10,10 @@ Type=oneshot ExecStart=#SBINDIR#/run-postinsts ExecStartPost=#BASE_BINDIR#/systemctl --no-reload disable run-postinsts.service RemainAfterExit=yes -TimeoutSec=0 +TimeoutSec=1 +Restart=on-failure +RestartSec=1 +StartLimitBurst=3 [Install] WantedBy=sysinit.target > > The run-postinsts script is not run when installed on sysvinit targets, but > it's run on systemd targets. It seems that this service should be enabled > but not immediately started/restarted when installed on target. As I understand it, the rust-postinsts script _is_ run for sysvinit? https://git.yoctoproject.org/poky/tree/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.init #!/bin/sh run-postinsts 98601 23 Qi.Chen 2024-03-25 05:48:07 +0000 (In reply to Tim Orling from comment #22) > (In reply to Chen Qi from comment #20) > > I just found a related issue. > > We're using the same SYSTEMD_AUTO_ENABLE variable to control two different > > actions: enable & start/restart after target installation. > > restart is clearly the problem :) > > > > > The related codes are: > > systemd_postinst() { > > if systemctl >/dev/null 2>/dev/null; then > > OPTS="" > > > > if [ -n "$D" ]; then > > OPTS="--root=$D" > > fi > > > > if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then > > for service in ${SYSTEMD_SERVICE_ESCAPED}; do > > systemctl ${OPTS} enable "$service" > > done > > fi > > > > if [ -z "$D" ]; then > > systemctl daemon-reload > > systemctl preset ${SYSTEMD_SERVICE_ESCAPED} > > > > if [ "${SYSTEMD_AUTO_ENABLE}" = "enable" ]; then > > systemctl --no-block restart > > ${SYSTEMD_SERVICE_ESCAPED} > > fi > > fi > > fi > > } > > > > A new variable seems needed. Not sure its suitable name. > > SYSTEMD_AUTO_START_AFTER_TARGET_INSTALLATION? > > Interesting idea. I somehow think some kind of "smarter" systemd service > dependencies/rules would help. > > I did try a little bit of investigation into the service itself, although > I am not claiming to be fully understanding all the nuances of this bug. > > diff --git > a/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service > b/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service > index b6b81d5c1a1..19331d656a5 100644 > --- a/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service > +++ b/meta/recipes-devtools/run-postinsts/run-postinsts/run-postinsts.service > @@ -1,6 +1,7 @@ > [Unit] > Description=Run pending postinsts > DefaultDependencies=no > +StartLimitIntervalSec=5 > After=systemd-remount-fs.service systemd-tmpfiles-setup.service tmp.mount > ldconfig.service > Before=sysinit.target > > @@ -9,7 +10,10 @@ Type=oneshot > ExecStart=#SBINDIR#/run-postinsts > ExecStartPost=#BASE_BINDIR#/systemctl --no-reload disable > run-postinsts.service > RemainAfterExit=yes > -TimeoutSec=0 > +TimeoutSec=1 > +Restart=on-failure > +RestartSec=1 > +StartLimitBurst=3 > > [Install] > WantedBy=sysinit.target > > > > > The run-postinsts script is not run when installed on sysvinit targets, but > > it's run on systemd targets. It seems that this service should be enabled > > but not immediately started/restarted when installed on target. > > As I understand it, the rust-postinsts script _is_ run for sysvinit? > https://git.yoctoproject.org/poky/tree/meta/recipes-devtools/run-postinsts/ > run-postinsts/run-postinsts.init > > #!/bin/sh > > run-postinsts For target installation, this run-postinsts.init script is installed and then enabled by update-rc.d, but it's not run immediately after the installation. This difference makes this bug systemd specific, as it's run immediately after installation in systemd systems. 98628 24 alexandre.belloni 2024-03-27 19:35:45 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7487 qemux86-alt fedora38-ty-6 98630 25 alexandre.belloni 2024-03-27 20:19:43 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7502/steps/14/logs/stdio qemux86-alt fedora38-ty-3 98636 26 alexandre.belloni 2024-03-27 21:31:25 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7496/steps/13/logs/stdio qemux86-64-alt fedora38-ty-3 98643 27 alexandre.belloni 2024-03-27 21:56:46 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7554/steps/14/logs/stdio qemux86-64-alt debian12-ty-1 98645 28 alexandre.belloni 2024-03-27 22:01:47 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7500/steps/14/logs/stdio qemux86-64-alt alma9-ty-2 98649 29 alexandre.belloni 2024-03-27 22:31:45 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7451/steps/15/logs/stdio qemux86-alt opensuse154-ty-3 98679 30 richard.purdie 2024-03-30 22:34:44 +0000 I think there may be a better way to do this with opkg support but for now, work around it: https://git.yoctoproject.org/poky/commit/?id=7c916d8f1bfd6b8036311d534a08b2f71464a3cd