10225 2016-09-06 09:58:17 +0000 Signs of a race in do_testimage 2017-12-06 17:10:15 +0000 1 1 10 QA/Testing Build Testing general 2.2 x86 Multiple RESOLVED FIXED High normal 2.2 M4 1 joshuagloe anibal.limon alejandro.hernandez anibal.limon leonardo.sandoval.gonzalez liezhi.yang meta.mr.watcher meta.watcher --- --- No (bug/feature does not impact docs) oldest_to_newest 65817 0 joshuagloe 2016-09-06 09:58:17 +0000 nightly-x86-lsb failed during oe-selftest on a builder in the new build cluster, we haven't seen this failure on the current cluster and a FileNotFound Exception seems likely to be a race. http://autobuilder.yocto.io:8010/builders/nightly-x86-lsb/builds/39/steps/Running%20Sanity%20Tests/logs/stdio Copy of stack trace below: ERROR: core-image-lsb-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-autobuilder/yocto-worker/nightly-x86-lsb/build/meta/classes/testimage.bbclass', lineno: 104, function: do_testimage 0100: netstat -an 0101:} 0102: 0103:python do_testimage() { *** 0104: testimage_main(d) 0105:} 0106: 0107:addtask testimage 0108:do_testimage[nostamp] = "1" File: '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/meta/classes/testimage.bbclass', lineno: 152, function: testimage_main 0148: if d.getVar('VIRTUAL-RUNTIME_init_manager', '') == 'systemd': 0149: bootparams = 'systemd.log_level=debug systemd.log_target=console' 0150: target.start(extra_bootparams=bootparams) 0151: starttime = time.time() *** 0152: result = tc.runTests() 0153: stoptime = time.time() 0154: if result.wasSuccessful(): 0155: bb.plain("%s - Ran %d test%s in %.3fs" % (pn, result.testsRun, result.testsRun != 1 and "s" or "", stoptime - starttime)) 0156: msg = "%s - OK - All required tests passed" % pn File: '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/meta/lib/oeqa/oetest.py', lineno: 401, function: runTests 0397: runner = unittest.TextTestRunner(verbosity=2) 0398: if 'bb' in sys.modules: 0399: runner.stream.write = custom_verbose 0400: *** 0401: return runner.run(self.suite) 0402: 0403:class RuntimeTestContext(TestContext): 0404: def __init__(self, d, target, exported=False): 0405: super(RuntimeTestContext, self).__init__(d, exported) File: '/usr/lib/python3.5/unittest/runner.py', lineno: 176, function: run 0172: startTestRun = getattr(result, 'startTestRun', None) 0173: if startTestRun is not None: 0174: startTestRun() 0175: try: *** 0176: test(result) 0177: finally: 0178: stopTestRun = getattr(result, 'stopTestRun', None) 0179: if stopTestRun is not None: 0180: stopTestRun() File: '/usr/lib/python3.5/unittest/suite.py', lineno: 84, function: __call__ 0080: self._removed_tests += test.countTestCases() 0081: self._tests[index] = None 0082: 0083: def __call__(self, *args, **kwds): *** 0084: return self.run(*args, **kwds) 0085: 0086: def debug(self): 0087: """Run the tests without collecting errors in a TestResult""" 0088: for test in self: File: '/usr/lib/python3.5/unittest/suite.py', lineno: 122, function: run 0118: getattr(result, '_moduleSetUpFailed', False)): 0119: continue 0120: 0121: if not debug: *** 0122: test(result) 0123: else: 0124: test.debug() 0125: 0126: if self._cleanup: File: '/usr/lib/python3.5/unittest/suite.py', lineno: 84, function: __call__ 0080: self._removed_tests += test.countTestCases() 0081: self._tests[index] = None 0082: 0083: def __call__(self, *args, **kwds): *** 0084: return self.run(*args, **kwds) 0085: 0086: def debug(self): 0087: """Run the tests without collecting errors in a TestResult""" 0088: for test in self: File: '/usr/lib/python3.5/unittest/suite.py', lineno: 122, function: run 0118: getattr(result, '_moduleSetUpFailed', False)): 0119: continue 0120: 0121: if not debug: *** 0122: test(result) 0123: else: 0124: test.debug() 0125: 0126: if self._cleanup: File: '/usr/lib/python3.5/unittest/suite.py', lineno: 84, function: __call__ 0080: self._removed_tests += test.countTestCases() 0081: self._tests[index] = None 0082: 0083: def __call__(self, *args, **kwds): *** 0084: return self.run(*args, **kwds) 0085: 0086: def debug(self): 0087: """Run the tests without collecting errors in a TestResult""" 0088: for test in self: File: '/usr/lib/python3.5/unittest/suite.py', lineno: 122, function: run 0118: getattr(result, '_moduleSetUpFailed', False)): 0119: continue 0120: 0121: if not debug: *** 0122: test(result) 0123: else: 0124: test.debug() 0125: 0126: if self._cleanup: File: '/usr/lib/python3.5/unittest/case.py', lineno: 648, function: __call__ 0644: # even though we no longer us it internally 0645: return outcome.success 0646: 0647: def __call__(self, *args, **kwds): *** 0648: return self.run(*args, **kwds) 0649: 0650: def debug(self): 0651: """Run the test without collecting errors in a TestResult""" 0652: self.setUp() File: '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/meta/lib/oeqa/utils/decorators.py', lineno: 194, function: run 0190: local_log.results("Testcase "+str(test_case)+": PASSED") 0191: 0192: # Create symlink to the current log 0193: if os.path.lexists(linkfile): *** 0194: os.remove(linkfile) 0195: os.symlink(logfile, linkfile) 0196: 0197: original_class.run = run 0198: Exception: FileNotFoundError: [Errno 2] No such file or directory: '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/results-bitbake-worker.log' ERROR: core-image-lsb-1.0-r0 do_testimage: Function failed: do_testimage ERROR: Logfile of failure stored in: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/tmp/work/qemux86-poky-linux/core-image-lsb/1.0-r0/temp/log.do_testimage.13132 ERROR: Task (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/meta/recipes-extended/images/core-image-lsb.bb:do_testimage) failed with exit code '1' 65839 1 alejandro.hernandez 2016-09-06 21:13:35 +0000 This sure looks like a race condition, since the file does exist, I'm guessing it was created afterwards: ls -l /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/results-bitbake-worker.log lrwxrwxrwx 1 pokybuild users 116 Sep 5 15:13 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/results-bitbake-worker.log -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/results-bitbake-worker.20160905220801.log 65841 2 alejandro.hernandez 2016-09-06 21:29:57 +0000 The line where it fails is inside an if, that's supposed to check that: 0192: # Create symlink to the current log 0193: if os.path.lexists(linkfile): *** 0194: os.remove(linkfile) According to python's documentation: os.path.lexists: Return True if path refers to an existing path. Returns True for broken symbolic links. Equivalent to exists() on platforms lacking os.lstat(). So it could return true for a broken link, but that still doesn't explain why the os.remove() would fail for a broken link. Or this is a very specific race, where the file is removed, an maybe recreated by some other process just after checking if it existed 65856 3 liezhi.yang 2016-09-07 07:15:38 +0000 (In reply to comment #2) > The line where it fails is inside an if, that's supposed to check that: > > 0192: # Create symlink to the current log > 0193: if os.path.lexists(linkfile): > *** 0194: os.remove(linkfile) > > > According to python's documentation: > > os.path.lexists: > > Return True if path refers to an existing path. Returns True for broken > symbolic links. Equivalent to exists() on platforms lacking os.lstat(). > > So it could return true for a broken link, but that still doesn't explain > why the os.remove() would fail for a broken link. > > Or this is a very specific race, where the file is removed, an maybe > recreated by some other process just after checking if it existed It should be a race issue, for example: bitbake <image1> <image2> -c testimage Then two testimage may handle it at the same, I think that we can rename results-bitbake-worker.log to something liek core-image-minimal-testimage.log to fix the problem. 65876 4 alejandro.hernandez 2016-09-07 15:22:54 +0000 (In reply to comment #3) > > It should be a race issue, for example: > bitbake <image1> <image2> -c testimage > > Then two testimage may handle it at the same, I think that we can rename > results-bitbake-worker.log to something liek > core-image-minimal-testimage.log to fix the problem. I see no harm in renaming the worker log to some image-specific name, and I agree I believ this would likely fix the issue. 65920 5 joshuagloe 2016-09-08 12:55:39 +0000 (In reply to comment #4) > (In reply to comment #3) > > > > > It should be a race issue, for example: > > bitbake <image1> <image2> -c testimage > > > > Then two testimage may handle it at the same, I think that we can rename > > results-bitbake-worker.log to something liek > > core-image-minimal-testimage.log to fix the problem. > > I see no harm in renaming the worker log to some image-specific name, and I > agree I believ this would likely fix the issue. It's a reasonable solution, one I was also considering. The trouble is how do we get the name of the target bitbake was invoked with into the decorator that sets up the log filename? AFAICT the decorator and the classes it decorates have no idea what the target the parent bitbake process was invoked with is. 66043 6 anibal.limon 2016-09-12 16:21:02 +0000 (In reply to comment #5) > (In reply to comment #4) > > (In reply to comment #3) > > > > > > > > It should be a race issue, for example: > > > bitbake <image1> <image2> -c testimage > > > > > > Then two testimage may handle it at the same, I think that we can rename > > > results-bitbake-worker.log to something liek > > > core-image-minimal-testimage.log to fix the problem. > > > > I see no harm in renaming the worker log to some image-specific name, and I > > agree I believ this would likely fix the issue. > > It's a reasonable solution, one I was also considering. The trouble is how > do we get the name of the target bitbake was invoked with into the decorator > that sets up the log filename? > > AFAICT the decorator and the classes it decorates have no idea what the > target the parent bitbake process was invoked with is. Another possible solution will be usage of bb.utils.lock before and after the soft link related code. 66107 7 anibal.limon 2016-09-13 20:27:25 +0000 At, http://lists.openembedded.org/pipermail/openembedded-core/2016-September/126472.html 66225 8 anibal.limon 2016-09-15 19:04:18 +0000 Merged at, http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=62c45ffbc7c239b6d50931a0fc46f9a67635b1b1