Bug 15428

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.

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.

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

That build was Worker: alma9-ty-2

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

Sorry about the noise. Giving it a second thought, I found my above comment useless.

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...

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

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

Related query on the mailing list:
https://lore.kernel.org/all/CAMKF1spKdnjMFpD=Qf_1vCzOeAN-Xg5GqQJviNLPXRq6md-tbQ@mail.gmail.com/T/

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.

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

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.

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"

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

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

*** Bug 15450 has been marked as a duplicate of this bug. ***

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/

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)?

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.

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.

(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

(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.

https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7487

qemux86-alt fedora38-ty-6

https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7502/steps/14/logs/stdio

qemux86-alt fedora38-ty-3

https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7496/steps/13/logs/stdio

qemux86-64-alt fedora38-ty-3

https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7554/steps/14/logs/stdio

qemux86-64-alt debian12-ty-1

https://autobuilder.yoctoproject.org/typhoon/#/builders/109/builds/7500/steps/14/logs/stdio

qemux86-64-alt alma9-ty-2

https://autobuilder.yoctoproject.org/typhoon/#/builders/101/builds/7451/steps/15/logs/stdio
qemux86-alt opensuse154-ty-3

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