Bug 14551

Summary: runtime_test.TestImage.test_testimage_virgl_headless failure
Product: [QA/Testing] Functional (self) Testing Reporter: Alexandre Belloni <alexandre.belloni>
Component: oe-selftestAssignee: Michael Halstead <mhalstead>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium+ CC: alex.kanavin, oobitots, richard.purdie
Version: 3.4   
Target Milestone: 3.4 M4   
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 Alexandre Belloni 2021-09-16 14:32:50 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/1587/steps/14/logs/stdio
oe-selftest opensuse152-ty-1

2021-09-11 05:47:06,595 - oe-selftest - INFO - runtime_test.TestImage.test_testimage_virgl_headless (subunit.RemotedTestCase)
2021-09-11 05:47:06,596 - oe-selftest - INFO -  ... FAIL

runqemu - INFO - Acquiring lockfile /tmp/qemu-tap-locks/tap0.lock failed: [Errno 11] Resource temporarily unavailable
runqemu - INFO - Using preconfigured tap device tap1
runqemu - INFO - If this is not intended, touch /tmp/qemu-tap-locks/tap1.skip to make runqemu skip tap1.
runqemu - INFO - Network configuration: ip=192.168.7.4::192.168.7.3:255.255.255.0
runqemu - INFO - Copying rootfs to /home/pokybuild/tmp/core-image-minimal-qemux86-64.ext4.33457
runqemu - INFO - Copy done in 0.03253006935119629 seconds
runqemu - INFO - Running /home/pokybuild/yocto-worker/oe-selftest/build/build-st-34047/tmp/work/x86_64-linux/qemu-helper-native/1.0-r1/recipe-sysroot-native/usr/bin/qemu-system-x86_64 -device virtio-net-pci,netdev=net0,mac=52:54:00:12:34:04 -netdev tap,id=net0,ifname=tap1,script=no,downscript=no -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -drive file=/home/pokybuild/tmp/core-image-minimal-qemux86-64.ext4.33457,if=virtio,format=raw -usb -device usb-tablet   -cpu IvyBridge -machine q35 -smp 4 -enable-kvm -m 256 -serial tcp:127.0.0.1:55065 -serial tcp:127.0.0.1:46957  -pidfile /home/pokybuild/yocto-worker/oe-selftest/build/build-st-34047/pidfile_32973  -S -qmp unix:./.ce0t9x2n,server,wait -qmp unix:./.b3t9ridb,server,nowait -serial mon:vc -vga virtio -display egl-headless,show-cursor=on  -kernel /home/pokybuild/yocto-worker/oe-selftest/build/build-st-34047/tmp/deploy/images/qemux86-64/bzImage--5.13.12+git0+c38435a3ca_49ec738aa7-r0-qemux86-64-20210910150548.bin -append 'root=/dev/vda rw  mem=256M ip=192.168.7.4::192.168.7.3:255.255.255.0 console=ttyS0 console=ttyS1 oprofile.timer=1 tsc=reliable no_timer_check rcupdate.rcu_expedited=1  printk.time=1'
runqemu - ERROR - Failed to run qemu: qemu-system-x86_64: -qmp unix:./.ce0t9x2n,server,wait: info: QEMU waiting for connection on: disconnected:unix:./.ce0t9x2n,server=on
qemu-system-x86_64: egl: no drm render node available
qemu-system-x86_64: egl: render node init failed
runqemu - INFO - Cleaning up
runqemu - INFO - Removing /home/pokybuild/tmp/core-image-minimal-qemux86-64.ext4.33457
tput: No value for $TERM and no -T specified
Comment 1 Alexandre Belloni 2021-09-16 14:34:16 UTC
Couldn't login into serial console as root using blank password
The output:
root
Password: 
Login timed out after 60 seconds.
Poky (Yocto Project Reference Distro) 3.3+snapshot-ad0ffb6f9f85bd0068b7807658a3a13243ee39d7 qemux86-64 /dev/ttyS1
qemux86-64 login: <<< run_serial(): command timed out after 120 seconds without output >>>
Comment 2 Alexandre Belloni 2021-09-16 14:34:56 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/1581/steps/14/logs/stdio
oe-selftest opensuse152-ty-1
Comment 3 Richard Purdie 2021-09-16 14:46:27 UTC
Alex: Any idea whether this is an opensuse specific issue?
Comment 4 Alexander Kanavin 2021-09-16 15:34:15 UTC
Quite likely incorrect permissions on /dev/dri/renderD* on that host (there was a similar issue in ubuntu hosts). I can't log in and check until tomorrow evening.
Comment 5 Alexander Kanavin 2021-09-17 21:09:00 UTC
Yep, wrong permissions:

pokybuild@opensuse152-ty-1:~> groups
pokybuild kvm
pokybuild@opensuse152-ty-1:~> ls -l /dev/dri
total 0
drwxr-xr-x 2 root root       100 Sep 17 20:37 by-path
crw-rw---- 1 root video 226,   0 Sep 17 20:37 card0
crw-rw---- 1 root video 226,   1 Sep 17 20:37 card1
crw-rw---- 1 root video 226, 128 Sep 17 20:37 renderD128


Assigning to mhalstead.

I guess we could send a patch to qemu to report lack of needed permissions specifically as well.
Comment 6 Michael Halstead 2021-09-23 23:07:26 UTC
opensuse152 doesn't have a render group and Ansible was trying to add pokybuild to both the video and render group so it failed completely on that worker. I've updated the config so openSUSE 15.2 will only assign kvm and video groups to pokybuild which I expect to resolve the error.
Comment 7 Oleksiy Obitotskyy 2021-09-25 07:07:24 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/1601

2021-09-25 04:22:50,634 - oe-selftest - INFO - runtime_test.TestImage.test_testimage_virgl_headless (subunit.RemotedTestCase)
2021-09-25 04:22:50,635 - oe-selftest - INFO -  ... FAIL
...
Waiting at most 1000 seconds for login banner (09/25/21 03:34:35)
Connection from 127.0.0.1:38784
Reached login banner in 4.067016839981079 seconds (09/25/21 03:34:39)
Logged as root in serial console
2021-09-25 04:22:50,635 - oe-selftest - INFO - 13: 20/20 417/443 (65.70s) (runtime_test.TestImage.test_testimage_virgl_headless)
2021-09-25 04:22:50,635 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last):
  File "/home/pokybuild/yocto-worker/oe-selftest/build/meta/lib/oeqa/selftest/cases/runtime_test.py", line 237, in test_testimage_virgl_headless
    bitbake('-c testimage core-image-minimal')
  File "/home/pokybuild/yocto-worker/oe-selftest/build/meta/lib/oeqa/utils/commands.py", line 229, in bitbake
    return runCmd(cmd, ignore_status, timeout, output_log=output_log, **options)
  File "/home/pokybuild/yocto-worker/oe-selftest/build/meta/lib/oeqa/utils/commands.py", line 207, in runCmd
    raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output))
AssertionError: Command 'bitbake  -c testimage core-image-minimal' returned non-zero exit status 1:
...
runqemu - ERROR - Failed to run qemu: qemu-system-x86_64: -qmp unix:./.1ujg67lq,server,wait: info: QEMU waiting for connection on: disconnected:unix:./.1ujg67lq,server=on
qemu-system-x86_64: egl: no drm render node available
qemu-system-x86_64: egl: render node init failed

runqemu - INFO - Cleaning up
runqemu - INFO - Removing /home/pokybuild/tmp/core-image-minimal-qemux86-64.ext4.39171
tput: No value for $TERM and no -T specified

ERROR: core-image-minimal-1.0-r0 do_testimage: Error executing a python function in exec_func_python() autogenerated:

The stack trace of python calls that resulted in this exception/failure was:
File: 'exec_func_python() autogenerated', lineno: 2, function: <module>
     0001:
 *** 0002:do_testimage(d)
     0003:
File: '/home/pokybuild/yocto-worker/oe-selftest/build/meta/classes/testimage.bbclass', lineno: 135, function: do_testimage
     0131:    dump-guest-memory {"paging":false,"protocol":"file:%s.img"}
     0132:}
     0133:
     0134:python do_testimage() {
 *** 0135:    testimage_main(d)
     0136:}
     0137:
     0138:addtask testimage
     0139:do_testimage[nostamp] = "1"
File: '/home/pokybuild/yocto-worker/oe-selftest/build/meta/classes/testimage.bbclass', lineno: 382, function: testimage_main
     0378:    orig_sigterm_handler = signal.signal(signal.SIGTERM, sigterm_exception)
     0379:    try:
     0380:        # We need to check if runqemu ends unexpectedly
     0381:        # or if the worker send us a SIGTERM
 *** 0382:        tc.target.start(params=d.getVar("TEST_QEMUPARAMS"), runqemuparams=d.getVar("TEST_RUNQEMUPARAMS"))
     0383:        import threading
     0384:        try:
     0385:            threading.Timer(int(d.getVar("TEST_OVERALL_TIMEOUT")), handle_test_timeout, (int(d.getVar("TEST_OVERALL_TIMEOUT")),)).start()
     0386:        except ValueError:
File: '/home/pokybuild/yocto-worker/oe-selftest/build/meta/lib/oeqa/core/target/qemu.py', lineno: 102, function: start
     0098:            except (subprocess.CalledProcessError, subprocess.TimeoutExpired, FileNotFoundError) as err:
     0099:                msg += "Error running command: %s\n%s\n" % (blcmd, err)
     0100:            msg += "\n\n===== end: snippet =====\n"
     0101:
 *** 0102:            raise RuntimeError("FAILED to start qemu - check the task log and the boot log %s" % (msg))
     0103:
     0104:    def stop(self):
     0105:        self.runner.stop()
Exception: RuntimeError: FAILED to start qemu - check the task log and the boot log
Comment 8 Alexandre Belloni 2021-09-25 08:43:44 UTC
pokybuild seems to be in the proper groups now and it still failed:


pokybuild@opensuse152-ty-1:~> id
uid=6000(pokybuild) gid=6000(pokybuild) groups=6000(pokybuild),485(video),488(kvm)
Comment 9 Alexander Kanavin 2021-09-25 11:19:07 UTC
I just run the test manually and it passed:

pokybuild@opensuse152-ty-1:~/akanavin/poky/build> oe-selftest -r runtime_test.TestImage.test_testimage_virgl_headless
2021-09-25 10:40:30,069 - oe-selftest - INFO - Adding layer libraries:
2021-09-25 10:40:30,069 - oe-selftest - INFO - 	/home/pokybuild/akanavin/poky/meta/lib
2021-09-25 10:40:30,069 - oe-selftest - INFO - 	/home/pokybuild/akanavin/poky/meta-yocto-bsp/lib
2021-09-25 10:40:30,069 - oe-selftest - INFO - 	/home/pokybuild/akanavin/poky/meta-selftest/lib
2021-09-25 10:40:30,071 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable
2021-09-25 10:40:34,065 - oe-selftest - INFO - Adding: "include selftest.inc" in /home/pokybuild/akanavin/poky/build-st/conf/local.conf
2021-09-25 10:40:34,066 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf
2021-09-25 10:40:34,066 - oe-selftest - INFO - test_testimage_virgl_headless (runtime_test.TestImage)
2021-09-25 11:16:32,643 - oe-selftest - INFO -  ... ok
2021-09-25 11:16:32,847 - oe-selftest - INFO - ----------------------------------------------------------------------
2021-09-25 11:16:32,847 - oe-selftest - INFO - Ran 1 test in 2160.892s
2021-09-25 11:16:32,847 - oe-selftest - INFO - OK
2021-09-25 11:16:39,462 - oe-selftest - INFO - RESULTS:
2021-09-25 11:16:39,463 - oe-selftest - INFO - RESULTS - runtime_test.TestImage.test_testimage_virgl_headless: PASSED (2158.70s)
2021-09-25 11:16:39,463 - oe-selftest - INFO - SUMMARY:
2021-09-25 11:16:39,464 - oe-selftest - INFO - oe-selftest () - Ran 1 test in 2160.893s
2021-09-25 11:16:39,464 - oe-selftest - INFO - oe-selftest - OK - All required tests passed (successes=1, skipped=0, failures=0, errors=0)


Was the failing run somehow before the correct group assignment?
Comment 10 Alexandre Belloni 2021-09-25 11:22:03 UTC
No, it was specifically done after
Comment 11 Alexander Kanavin 2021-09-25 14:14:06 UTC
The process that starts those builds has not been restarted, and isn't in the group, I suspect that may be the reason?

    1  4763  4762  4762 ?           -1 Sl    6000   9:33 /usr/bin/python3 /usr/bin/buildbot-worker start /home/pokybuild/yocto-worker
Comment 12 Alexandre Belloni 2021-09-27 13:29:30 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/56/builds/1604

It just finished successfully. Thanks all