Bug 13986

Summary: qemumips boot failures under heavy system load (master)
Product: [QA/Testing] Runtime Testing Reporter: Richard Purdie <richard.purdie>
Component: testimageAssignee: Bruce Ashfield <bruce.ashfield>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium+ CC: aaron.chun.yew.chan, alex.kanavin, randy.macleod
Version: unspecified   
Target Milestone: 3.2 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)
Attachments:
Description Flags
Logs of another failure none

Description Richard Purdie 2020-07-18 03:02:00 UTC 
https://autobuilder.yoctoproject.org/typhoon/#/builders/60/builds/2185

qemumips is known to be the slowest platform. This is the second time we've see this in the last week.

ore-image-sato sdk (poky-glibc-i686-core-image-sato-mips32r2-qemumips-toolchain-3.1+snapshot.sh:environment-setup-mips32r2-poky-linux) - Ran 12 tests in 207.148s
core-image-sato sdk - OK - All required tests passed (successes=11, skipped=1, failures=0, errors=0)
NOTE: recipe core-image-sato-1.0-r0: task do_testsdk: Succeeded
Started HTTPService on 0.0.0.0:33762
WARNING: core-image-sato-1.0-r0 do_testimage: Target didn't reach login banner in 1500 seconds (07/18/20 03:12:42)
WARNING: core-image-sato-1.0-r0 do_testimage: Last 25 lines of text:
[  254.896554] udevd[106]: worker [137] /devices/virtual/block/ram6 is taking a long time
[  375.198538] udevd[106]: worker [135] /devices/virtual/block/ram4 timeout; kill it
[  375.205006] udevd[106]: seq 759 '/devices/virtual/block/ram4' killed
[  375.205527] udevd[106]: worker [136] /devices/virtual/block/ram5 timeout; kill it
[  375.210974] udevd[106]: seq 760 '/devices/virtual/block/ram5' killed
[  375.211593] udevd[106]: worker [133] /devices/virtual/block/ram2 timeout; kill it
[  375.216278] udevd[106]: seq 757 '/devices/virtual/block/ram2' killed
[  375.216803] udevd[106]: worker [131] /devices/virtual/block/ram14 timeout; kill it
[  375.221555] udevd[106]: seq 755 '/devices/virtual/block/ram14' killed
[  375.222107] udevd[106]: worker [134] /devices/virtual/block/ram3 timeout; kill it
[  375.226329] udevd[106]: seq 758 '/devices/virtual/block/ram3' killed
[  439.321116] udevd[106]: worker [158] /devices/virtual/net/sit0 is taking a long time
[  439.328603] udevd[106]: worker [159] /devices/virtual/block/md0 is taking a long time
[  439.329158] udevd[106]: worker [150] /devices/virtual/block/ram9 is taking a long time
[  439.329669] udevd[106]: worker [152] /devices/virtual/net/lo is taking a long time
[  559.470986] udevd[106]: worker [158] /devices/virtual/net/sit0 timeout; kill it
[  559.477584] udevd[106]: seq 783 '/devices/virtual/net/sit0' killed
[  559.478113] udevd[106]: worker [159] /devices/virtual/block/md0 timeout; kill it
[  559.483312] udevd[106]: seq 866 '/devices/virtual/block/md0' killed
[  559.483853] udevd[106]: worker [150] /devices/virtual/block/ram9 timeout; kill it
[  559.488871] udevd[106]: seq 764 '/devices/virtual/block/ram9' killed
[  559.489369] udevd[106]: worker [152] /devices/virtual/net/lo timeout; kill it
[  559.494627] udevd[106]: seq 782 '/devices/virtual/net/lo' killed
[  559.496691] udevd[106]: worker [150] terminated by signal 9 (Killed)
[  559.497139] udevd[106]: worker [150] failed while handling '/devices/virtual/block/ram9'
WARNING: core-image-sato-1.0-r0 do_testimage: Check full boot log: /home/pokybuild/yocto-worker/qemumips/build/build/tmp/work/qemumips-poky-linux/core-image-sato/1.0-r0/testimage/qemu_boot_log.20200718024729
WARNING: core-image-sato-1.0-r0 do_testimage: Qemu ended unexpectedly, dump data from host is in /home/pokybuild/yocto-worker/qemumips/build/build/tmp/log/runtime-hostdump/202007180312_qemu
ERROR: core-image-sato-1.0-r0 do_testimage: 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_testimage(d)
     0003:
File: '/home/pokybuild/yocto-worker/qemumips/build/meta/classes/testimage.bbclass', lineno: 129, function: do_testimage
     0125:    netstat -an
     0126:}
     0127:
     0128:python do_testimage() {
 *** 0129:    testimage_main(d)
     0130:}
     0131:
     0132:addtask testimage
     0133:do_testimage[nostamp] = "1"
File: '/home/pokybuild/yocto-worker/qemumips/build/meta/classes/testimage.bbclass', lineno: 371, function: testimage_main
     0367:    orig_sigterm_handler = signal.signal(signal.SIGTERM, sigterm_exception)
     0368:    try:
     0369:        # We need to check if runqemu ends unexpectedly
     0370:        # or if the worker send us a SIGTERM
 *** 0371:        tc.target.start(params=d.getVar("TEST_QEMUPARAMS"), runqemuparams=d.getVar("TEST_RUNQEMUPARAMS"))
     0372:        import threading
     0373:        try:
     0374:            threading.Timer(int(d.getVar("TEST_OVERALL_TIMEOUT")), handle_test_timeout, (int(d.getVar("TEST_OVERALL_TIMEOUT")),)).start()
     0375:        except ValueError:
File: '/home/pokybuild/yocto-worker/qemumips/build/meta/lib/oeqa/core/target/qemu.py', lineno: 67, function: start
     0063:            if self.runner.server_ip:
     0064:                self.server_ip = self.runner.server_ip
     0065:        else:
     0066:            self.stop()
 *** 0067:            raise RuntimeError("FAILED to start qemu - check the task log and the boot log")
     0068:
     0069:    def stop(self):
     0070:        self.runner.stop()
Exception: RuntimeError: FAILED to start qemu - check the task log and the boot log

ERROR: Logfile of failure stored in: /home/pokybuild/yocto-worker/qemumips/build/build/tmp/work/qemumips-poky-linux/core-image-sato/1.0-r0/temp/log.do_testimage.37370
NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Failed
ERROR: Task (/home/pokybuild/yocto-worker/qemumips/build/meta/recipes-sato/images/core-image-sato.bb:do_testimage) failed with exit code '1'
Comment 2 Richard Purdie 2020-10-08 00:04:34 UTC 
Created attachment 4736 [details]
Logs of another failure

Looks like this failure is caused by the system running so slowly, in this case it was able to continue and run the tests.
Comment 4 Randy MacLeod 2020-10-08 08:02:11 UTC 
The performance improvement to qemumips are thought to fix this issue.