Bug 13999

Summary: do_packagedata setscene file race
Product: [Build System, Metadata & Runtime] OE-Core Reporter: Richard Purdie <richard.purdie>
Component: coreAssignee: Ross Burton <ross.burton>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium CC: alexandre.belloni, meta.mr.watcher, meta.watcher, randy.macleod, ross.burton
Version: 3.2   
Target Milestone: 3.4   
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 Richard Purdie 2020-08-10 10:09:44 UTC 
https://autobuilder.yoctoproject.org/typhoon/#/builders/72/builds/2304

NOTE: Running setscene task 3380 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-graphics/xorg-lib/libsm_1.2.3.bb:do_packagedata_setscene)
NOTE: recipe npth-1.6-r0: task do_packagedata_setscene: Started
NOTE: recipe popt-1.18-r0: task do_packagedata_setscene: Started
NOTE: recipe libpcre2-10.35-r0: task do_packagedata_setscene: Started
NOTE: recipe libxrender-1_0.9.10-r0: task do_packagedata_setscene: Started
NOTE: recipe freetype-2.10.2-r0: task do_packagedata_setscene: Succeeded
NOTE: Running setscene task 3386 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-core/expat/expat_2.2.9.bb:do_packagedata_setscene)
NOTE: recipe libpciaccess-0.16-r0: task do_packagedata_setscene: Succeeded
NOTE: recipe libsm-1_1.2.3-r0: task do_packagedata_setscene: Started
NOTE: recipe fribidi-1.0.10-r0: task do_packagedata_setscene: Succeeded
NOTE: Running setscene task 3391 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-connectivity/openssl/openssl_1.1.1g.bb:do_packagedata_setscene)
NOTE: Running setscene task 3392 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-core/readline/readline_8.0.bb:do_packagedata_setscene)
ERROR: libxtst-1_1.2.3-r0 do_packagedata_setscene: Error executing a python function in exec_python_func() autogenerated:

The stack trace of python calls that resulted in this exception/failure was:
File: 'exec_python_func() autogenerated', lineno: 2, function: <module>
     0001:
 *** 0002:do_packagedata_setscene(d)
     0003:
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/classes/package.bbclass', lineno: 2423, function: do_packagedata_setscene
     2419:do_packagedata[sstate-outputdirs] = "${PKGDATA_DIR}"
     2420:do_packagedata[stamp-extra-info] = "${MACHINE_ARCH}"
     2421:
     2422:python do_packagedata_setscene () {
 *** 2423:    sstate_setscene(d)
     2424:}
     2425:addtask do_packagedata_setscene
     2426:
     2427:#
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/classes/sstate.bbclass', lineno: 747, function: sstate_setscene
     0743:            pass
     0744:
     0745:def sstate_setscene(d):
     0746:    shared_state = sstate_state_fromvars(d)
 *** 0747:    accelerate = sstate_installpkg(shared_state, d)
     0748:    if not accelerate:
     0749:        bb.fatal("No suitable staging package found")
     0750:
     0751:python sstate_task_prefunc () {
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/classes/sstate.bbclass', lineno: 378, function: sstate_installpkg
     0374:    for f in (d.getVar('SSTATEPREINSTFUNCS') or '').split() + ['sstate_unpack_package']:
     0375:        # All hooks should run in the SSTATE_INSTDIR
     0376:        bb.build.exec_func(f, d, (sstateinst,))
     0377:
 *** 0378:    return sstate_installpkgdir(ss, d)
     0379:
     0380:def sstate_installpkgdir(ss, d):
     0381:    import oe.path
     0382:    import subprocess
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/classes/sstate.bbclass', lineno: 401, function: sstate_installpkgdir
     0397:
     0398:    for state in ss['dirs']:
     0399:        prepdir(state[1])
     0400:        os.rename(sstateinst + state[0], state[1])
 *** 0401:    sstate_install(ss, d)
     0402:
     0403:    for plain in ss['plaindirs']:
     0404:        workdir = d.getVar('WORKDIR')
     0405:        sharedworkdir = os.path.join(d.getVar('TMPDIR'), "work-shared")
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/classes/sstate.bbclass', lineno: 326, function: sstate_install
     0322:
     0323:    # Run the actual file install
     0324:    for state in ss['dirs']:
     0325:        if os.path.exists(state[1]):
 *** 0326:            oe.path.copyhardlinktree(state[1], state[2])
     0327:
     0328:    for postinst in (d.getVar('SSTATEPOSTINSTFUNCS') or '').split():
     0329:        # All hooks should run in the SSTATE_INSTDIR
     0330:        bb.build.exec_func(postinst, d, (sstateinst,))
File: '/home/pokybuild/yocto-worker/qa-extras2/build/meta/lib/oe/path.py', lineno: 132, function: copyhardlinktree
     0128:        else:
     0129:            source = src
     0130:            s_dir = os.getcwd()
     0131:        cmd = 'cp -afl --preserve=xattr %s %s' % (source, os.path.realpath(dst))
 *** 0132:        subprocess.check_output(cmd, shell=True, cwd=s_dir, stderr=subprocess.STDOUT)
     0133:    else:
     0134:        copytree(src, dst)
     0135:
     0136:def copyhardlink(src, dst):
File: '/home/pokybuild/yocto-worker/qa-extras2/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/subprocess.py', lineno: 411, function: check_output
     0407:        # Explicitly passing input=None was previously equivalent to passing an
     0408:        # empty string. That is maintained here for backwards compatibility.
     0409:        kwargs['input'] = '' if kwargs.get('universal_newlines', False) else b''
     0410:
 *** 0411:    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
     0412:               **kwargs).stdout
     0413:
     0414:
     0415:class CompletedProcess(object):
File: '/home/pokybuild/yocto-worker/qa-extras2/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/subprocess.py', lineno: 512, function: run
     0508:            # We don't call process.wait() as .__exit__ does that for us.
     0509:            raise
     0510:        retcode = process.poll()
     0511:        if check and retcode:
 *** 0512:            raise CalledProcessError(retcode, process.args,
     0513:                                     output=stdout, stderr=stderr)
     0514:    return CompletedProcess(process.args, retcode, stdout, stderr)
     0515:
     0516:
Exception: subprocess.CalledProcessError: Command 'cp -afl --preserve=xattr ./* /home/pokybuild/yocto-worker/qa-extras2/build/build/tmp/pkgdata/qemux86-64' returned non-zero exit status 1.

Subprocess output:
cp: cannot create hard link ‘/home/pokybuild/yocto-worker/qa-extras2/build/build/tmp/pkgdata/qemux86-64/runtime-rprovides/(=1.2.3)/libxtst’ to ‘./runtime-rprovides/(=1.2.3)/libxtst’: No such file or directory
cp: preserving times for ‘/home/pokybuild/yocto-worker/qa-extras2/build/build/tmp/pkgdata/qemux86-64/runtime-rprovides/(=1.2.3)’: No such file or directory

ERROR: Logfile of failure stored in: /home/pokybuild/yocto-worker/qa-extras2/build/build/tmp/work/core2-64-poky-linux/libxtst/1_1.2.3-r0/temp/log.do_packagedata_setscene.16698
NOTE: recipe libxtst-1_1.2.3-r0: task do_packagedata_setscene: Failed
WARNING: Setscene task (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-graphics/xorg-lib/libxtst_1.2.3.bb:do_packagedata_setscene) failed with exit code '1' - real task will be run instead
NOTE: recipe icu-67.1-r0: task do_packagedata_setscene: Succeeded
NOTE: recipe npth-1.6-r0: task do_packagedata_setscene: Succeeded
NOTE: Running setscene task 3395 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-core/libxcrypt/libxcrypt_4.4.16.bb:do_packagedata_setscene)
NOTE: Running setscene task 3396 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-extended/libnsl/libnsl2_git.bb:do_packagedata_setscene)
NOTE: Running setscene task 3397 of 3484 (/home/pokybuild/yocto-worker/qa-extras2/build/meta/recipes-extended/xz/xz_5.2.5.bb:do_packagedata_setscene)
NOTE: recipe libxrender-1_0.9.10-r0: task do_packagedata_setscene: Succeeded
Comment 1 Richard Purdie 2020-08-11 03:52:04 UTC 
Its interesting that libsm also has version 1.2.3 running at the same time?
Comment 2 Randy MacLeod 2020-08-13 07:38:07 UTC 
Likely, something weird going on with the dependencies according to Richard.
Comment 3 Ross Burton 2020-08-13 07:41:51 UTC 
cp: cannot create hard link ‘/home/pokybuild/yocto-worker/qa-extras2/build/build/tmp/pkgdata/qemux86-64/runtime-rprovides/(=1.2.3)/libxtst’

Note that /runtime-rprovides/ should contain names not versions.  However, in my tiny build I currently also have the following unusual directories:

(=10.1.0)
(=2.31+git0+1094741224)
rtld(GNU_HASH)

Looks like either quoting issues, or versions appearing in provides where otherwise not expected.
Comment 4 Ross Burton 2020-08-13 08:33:18 UTC 
$ ls runtime-rprovides/*=* -d
'runtime-rprovides/(=0.16)'     'runtime-rprovides/(=1.2.3)'                 'runtime-rprovides/(=2.36.0)'
'runtime-rprovides/(=0.40.0)'   'runtime-rprovides/(=1.2.6)'                 'runtime-rprovides/(=2.40.0)'
'runtime-rprovides/(=0.4.5)'    'runtime-rprovides/(=1.3)'                   'runtime-rprovides/(=2.4.102)'
'runtime-rprovides/(=0.7.10)'   'runtime-rprovides/(=1.3.0)'                 'runtime-rprovides/(=2.4.48)'
'runtime-rprovides/(=0.9.10)'   'runtime-rprovides/(=1.3.4)'                 'runtime-rprovides/(=2.64.4)'
'runtime-rprovides/(=1.0.10)'   'runtime-rprovides/(=1.5.2)'                 'runtime-rprovides/(=2.6.8)'
'runtime-rprovides/(=10.1.0)'   'runtime-rprovides/(=1.5.4)'                 'runtime-rprovides/(=3.24.21)'
'runtime-rprovides/(=1.0.8)'    'runtime-rprovides/(=1.6.37)'                'runtime-rprovides/(=3.3)'
'runtime-rprovides/(=1.0.9)'    'runtime-rprovides/(=1.6.9)'                 'runtime-rprovides/(=3.32.3)'
'runtime-rprovides/(=1.1.1g)'   'runtime-rprovides/(=1.7.10)'                'runtime-rprovides/(=3.8.5)'
'runtime-rprovides/(=1.12.20)'  'runtime-rprovides/(=20.1.4)'                'runtime-rprovides/(=4.4.16)'
'runtime-rprovides/(=1.1.3)'    'runtime-rprovides/(=2.0.5)'                 'runtime-rprovides/(=5.0.3)'
'runtime-rprovides/(=1.1.4)'    'runtime-rprovides/(=2.10.2)'                'runtime-rprovides/(=5.2.5)'
'runtime-rprovides/(=1.14)'     'runtime-rprovides/(=2.13.1)'                'runtime-rprovides/(=6.2)'
'runtime-rprovides/(=1.1.5)'    'runtime-rprovides/(=2.2.9)'                 'runtime-rprovides/(=67.1)'
'runtime-rprovides/(=1.16.0)'   'runtime-rprovides/(=2.31+git0+1094741224)'  'runtime-rprovides/(=8.0)'
'runtime-rprovides/(=1.18.1)'   'runtime-rprovides/(=2.3.3)'                 'runtime-rprovides/(=8.44)'
'runtime-rprovides/(=1.2.0)'    'runtime-rprovides/(=2.34.2)'
'runtime-rprovides/(=1.2.11)'   'runtime-rprovides/(=2.35.2)'

Looks like the code isn't handling versions at all, and there's just a good old fashioned race over genuinely racing files.

The code that is populating those files should be handling the RPROVIDES string containing versions, surely.
Comment 5 Ross Burton 2020-08-27 05:15:32 UTC 
I just posted a patch to the list to run the RPROVIDES list through explode_deps() so that directories such as (=1.2.3) are no longer created.

However the race still exists, if two packages (foo and bar) RPROVIDE the same name (flob) then they'll want to create pkgdata/runtime-rprovides/flob/(foo|bar).  If the stars align, foo can be running sstate_clean_manifest (thus deleting flob) whilst bar is in copyhardlinktree, in between the tar (to create the directories) and the cp (to put links into the directories).