Bug 10225

Summary: Signs of a race in do_testimage
Product: [QA/Testing] Build Testing Reporter: Joshua Lock <joshuagloe>
Component: generalAssignee: Aníbal Limón <anibal.limon>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: High CC: alejandro.hernandez, anibal.limon, leonardo.sandoval.gonzalez, liezhi.yang, meta.mr.watcher, meta.watcher
Version: 2.2   
Target Milestone: 2.2 M4   
Hardware: x86   
OS: Multiple   
Whiteboard:
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)

Description Joshua Lock 2016-09-06 09:58:17 UTC
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'
Comment 1 Alejandro Hernandez 2016-09-06 21:13:35 UTC
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
Comment 2 Alejandro Hernandez 2016-09-06 21:29:57 UTC
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
Comment 3 Robert Yang 2016-09-07 07:15:38 UTC
(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.
Comment 4 Alejandro Hernandez 2016-09-07 15:22:54 UTC
(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.
Comment 5 Joshua Lock 2016-09-08 12:55:39 UTC
(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.
Comment 6 Aníbal Limón 2016-09-12 16:21:02 UTC
(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.