Bug 8383

Summary: smart runtime test failure
Product: [Build System, Metadata & Runtime] OE-Core Reporter: Paul Eggleton <bluelightning>
Component: coreAssignee: Mariano Lopez <mariano.lopez>
Status: RESOLVED WORKSFORME QA Contact: Alexandru Georgescu <alexandru.c.georgescu>
Severity: normal    
Priority: Medium+ CC: akuster, alejandro.franco, alexandru.c.georgescu, jku, joshuagloe, leonardo.sandoval.gonzalez, liezhi.yang, meta.mr.watcher, meta.watcher, richard.purdie
Version: 2.0   
Target Milestone: 2.2 M3   
Hardware: x86   
OS: Multiple   
Whiteboard:
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)
Attachments:
Description Flags
Failure log from autobuilder for nightly-ppc-lsb
none
Failure log from autobuilder for nightly-x86-64-lsb
none
Failure log from autobuilder for nightly-qa-systemd-x86-64 none

Description Paul Eggleton 2015-09-23 13:21:09 UTC
Created attachment 2762 [details]
Failure log from autobuilder for nightly-ppc-lsb

From https://autobuilder.yoctoproject.org/main/builders/nightly-ppc-lsb/builds/493/steps/Running%20Sanity%20Tests/logs/stdio (https://autobuilder.yoctoproject.org/main/builders/nightly-ppc-lsb/builds/493 , mpc8315e-rdb, debian8):

------------- snip -------------
| FAIL: test_smart_remove_package (oeqa.runtime.smart.SmartRepoTest)
| ----------------------------------------------------------------------
| Traceback (most recent call last):
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/lib/oeqa/utils/decorators.py", line 102, in wrapped_f
|     return func(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f
|     return f(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/lib/oeqa/runtime/smart.py", line 174, in test_smart_remove_package
|     self.smart('install -y psplash')
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f
|     return f(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-ppc-lsb/build/meta/lib/oeqa/runtime/smart.py", line 22, in smart
|     self.assertEqual(status, expected, message)
| AssertionError: 1 != 0 : smart install -y psplash
| Loading cache...
| Updating cache...               ######################################## [100%]
| 
| Computing transaction...
| 
| Installing packages (2):
|   psplash-0.1+git0+14c8f7b705-r15@ppc7400
|   psplash-default-0.1+git0+14c8f7b705-r15@ppc7400
| 
| 30.8kB of package files are needed. 143.3kB will be used.
| 
| 
| Traceback (most recent call last):
|   File "/usr/bin/smart", line 200, in <module>
|     main(sys.argv[1:])
|   File "/usr/bin/smart", line 173, in main
|     exitcode = iface.run(opts.command, opts.argv)
|   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in run
|     result = _command.main(self._ctrl, opts)
|   File "/usr/lib/python2.7/site-packages/smart/commands/install.py", line 207, in main
|     ctrl.commitTransaction(trans, confirm=confirm)
|   File "/usr/lib/python2.7/site-packages/smart/control.py", line 681, in commitTransaction
|     return self.commitChangeSet(trans.getChangeSet(), caching, confirm)
|   File "/usr/lib/python2.7/site-packages/smart/control.py", line 749, in commitChangeSet
|     pmclass().commit(pmcs, pkgpaths)
|   File "/usr/lib/python2.7/site-packages/smart/backends/rpm/pm.py", line 179, in commit
|     fd = os.open(path, os.O_RDONLY)
| TypeError: coercing to Unicode: need string or buffer, NoneType found
| Unhandled exception in thread started by
| sys.excepthook is missing
| lost sys.stderr
| Unhandled exception in thread started by
| sys.excepthook is missing
| lost sys.stder
------------- snip -------------


A very similar error occurred in the same build: https://autobuilder.yoctoproject.org/main/builders/nightly-x86-64-lsb/builds/504/steps/Running%20Sanity%20Tests/logs/stdio (https://autobuilder.yoctoproject.org/main/builders/nightly-x86-64-lsb/builds/504 , genericx86-64, fedora21)

------------- snip -------------
| ======================================================================
| FAIL: test_smart_remote_repo (oeqa.runtime.smart.SmartRepoTest)
| ----------------------------------------------------------------------
| Traceback (most recent call last):
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64-lsb/build/meta/lib/oeqa/utils/decorators.py", line 102, in wrapped_f
|     return func(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64-lsb/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f
|     return f(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64-lsb/build/meta/lib/oeqa/runtime/smart.py", line 136, in test_smart_remote_repo
|     self.smart('update')
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64-lsb/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f
|     return f(*args)
|   File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-64-lsb/build/meta/lib/oeqa/runtime/smart.py", line 22, in smart
|     self.assertEqual(status, expected, message)
| AssertionError: 1 != 0 : smart update
| Loading cache...
| Updating cache...               ######################################## [100%]
| 
| Fetching information for 'all'...
| -> http://192.168.7.5:48723/rpm/all/repodata/repomd.xml
| repomd.xml                      ######################################## [ 16%]
| Traceback (most recent call last):
|   File "/usr/bin/smart", line 200, in <module>
| 
| Fetching information for 'qemux86_64'...
| -> http://192.168.7.5:48723/rpm/qemux86_64/repodata/repomd.xml
| repomd.xml                      ######################################## [ 41%]
|     main(sys.argv[1:])
|   File "/usr/bin/smart", line 173, in main
|     exitcode = iface.run(opts.command, opts.argv)
|   File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in run
|     result = _command.main(self._ctrl, opts)
|   File "/usr/lib/python2.7/site-packages/smart/commands/update.py", line 82, in main
|     failed = not ctrl.reloadChannels(channels, caching=NEVER)
|   File "/usr/lib/python2.7/site-packages/smart/control.py", line 388, in reloadChannels
|     if not channel.fetch(self._fetcher, progress):
|   File "/usr/lib/python2.7/site-packages/smart/channels/rpm_md.py", line 242, in fetch
|     digest = getFileDigest(item.getTargetPath())
|   File "/usr/lib/python2.7/site-packages/smart/util/filetools.py", line 34, in getFileDigest
|     file = open(path)
| TypeError: coercing to Unicode: need string or buffer, NoneType found
------------- snip -------------
Comment 1 Paul Eggleton 2015-09-23 13:21:53 UTC
Created attachment 2763 [details]
Failure log from autobuilder for nightly-x86-64-lsb
Comment 2 Paul Eggleton 2015-09-23 13:55:06 UTC
Richard believes this is due to multiple tests that make use of the same package feed(s) racing against eachother.
Comment 3 Richard Purdie 2015-09-24 15:01:08 UTC
Further analysis shows the race I was thinking of isn't possible so it can't be that.
Comment 4 Alex Franco 2015-10-26 16:34:41 UTC
(In reply to comment #1)
> Created attachment 2763 [details]
> Failure log from autobuilder for nightly-x86-64-lsb

It is in ERW: http://errors.yoctoproject.org/Errors/Details/18416/
There are apparently no similar errors reported in ERW in October, September or August
Comment 5 Mariano Lopez 2015-10-27 16:42:03 UTC
This is the only occurrence of this bug and I wasn't able to reproduce. Closing and if the error happens again it will be reopened.
Comment 6 Alexandru Georgescu 2015-10-28 12:56:38 UTC
verified as per above comments.
Comment 7 Jussi Kukkonen 2016-06-21 15:44:01 UTC
Reopening, nightly-qa-systemd just failed with the same trace (although different test):


core-image-sato-1.0-r0 do_testimage: ======================================================================
core-image-sato-1.0-r0 do_testimage: FAIL: test_smart_remote_repo (oeqa.runtime.smart.SmartRepoTest)
core-image-sato-1.0-r0 do_testimage: ----------------------------------------------------------------------
core-image-sato-1.0-r0 do_testimage: Traceback (most recent call last):
  File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 109, in wrapped_f
    return func(*args, **kwargs)
  File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 97, in wrapped_f
    return f(*args, **kwargs)
  File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/runtime/smart.py", line 136, in test_smart_remote_repo
    self.smart('update')
  File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 97, in wrapped_f
    return f(*args, **kwargs)
  File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/runtime/smart.py", line 22, in smart
    self.assertEqual(status, expected, message)
AssertionError: 1 != 0 : smart update
Loading cache...
Updating cache...               ######################################## [100%]

                                                                               
Fetching information for 'all'...
                                                                               
-> http://192.168.7.1:40933/rpm/all/repodata/repomd.xml
repomd.xml                      ######################################## [ 16%]
                                                                               
Fetching information for 'qemux86_64'...
                                                                               
-> http://192.168.7.1:40933/rpm/qemux86_64/repodata/repomd.xml
repomd.xml                      ######################################## [ 41%]
Traceback (most recent call last):
  File "/usr/bin/smart", line 200, in <module>
    main(sys.argv[1:])
  File "/usr/bin/smart", line 173, in main
    exitcode = iface.run(opts.command, opts.argv)
  File "/usr/lib/python2.7/site-packages/smart/interface.py", line 53, in run
    result = _command.main(self._ctrl, opts)
  File "/usr/lib/python2.7/site-packages/smart/commands/update.py", line 82, in main
    failed = not ctrl.reloadChannels(channels, caching=NEVER)
  File "/usr/lib/python2.7/site-packages/smart/control.py", line 388, in reloadChannels
    if not channel.fetch(self._fetcher, progress):
  File "/usr/lib/python2.7/site-packages/smart/channels/rpm_md.py", line 242, in fetch
    digest = getFileDigest(item.getTargetPath())
  File "/usr/lib/python2.7/site-packages/smart/util/filetools.py", line 34, in getFileDigest
    file = open(path)
TypeError: coercing to Unicode: need string or buffer, NoneType found
Comment 8 Mariano Lopez 2016-06-21 16:10:46 UTC
(In reply to comment #7)
> Reopening, nightly-qa-systemd just failed with the same trace (although
> different test):
> 

Can you please attach the log and the errors.yp.org link?
Comment 10 Mariano Lopez 2016-06-21 19:31:15 UTC
Created attachment 3245 [details]
Failure log from autobuilder for nightly-qa-systemd-x86-64
Comment 11 Mariano Lopez 2016-06-21 20:39:48 UTC
After a search in errors.yoctoproject.org these are all matches for "TypeError: coercing to Unicode: need string or buffer, NoneType found" exception in smart. Please note the third error was on 17/05/16 and fourth was on 01/03/16. Seems to be a intermittent issue.

universal poky x86-64
http://errors.yoctoproject.org/Errors/Details/69620/

universal poky-lsb ppc
http://errors.yoctoproject.org/Errors/Details/69500/

universal poky x86-64
http://errors.yoctoproject.org/Errors/Details/63820/

ubuntu-15.10 poky x86-64
http://errors.yoctoproject.org/Errors/Details/38881/

opensuse-13.1 poky-lsb ppc
http://errors.yoctoproject.org/Errors/Details/24100/

debian-8.2 poky mips64
http://errors.yoctoproject.org/Errors/Details/19600/

fedora-21 poky-lsb x86-64
http://errors.yoctoproject.org/Errors/Details/18416/

debian-8.2 poky-lsb ppc
http://errors.yoctoproject.org/Errors/Details/18415/

fedora-21 poky mips
http://errors.yoctoproject.org/Errors/Details/15031/

ubuntu-15.04 poky x86-64
http://errors.yoctoproject.org/Errors/Details/14912/

centos-7.1 poky mips
http://errors.yoctoproject.org/Errors/Details/14873/

fedora-22 poky-lsb mips
http://errors.yoctoproject.org/Errors/Details/14710/

ubuntu-12.04 poky mips64
http://errors.yoctoproject.org/Errors/Details/14139/

debian-7.8 poky mips
http://errors.yoctoproject.org/Errors/Details/12135/

ubuntu-14.10 poky x86-64
http://errors.yoctoproject.org/Errors/Details/11560/

debian-8.0 poky x86-64
http://errors.yoctoproject.org/Errors/Details/10763/

centos-6.6 poky mips
http://errors.yoctoproject.org/Errors/Details/10271/

debian-7.8 poky mips
http://errors.yoctoproject.org/Errors/Details/9534/

opensuse 13.1 poky x86-64
http://errors.yoctoproject.org/Errors/Details/9474/
Comment 12 Mariano Lopez 2016-06-22 15:41:48 UTC
It seems this is a upstream bug:

https://bugs.launchpad.net/smart/+bug/244038
Comment 13 Mariano Lopez 2016-06-22 16:04:42 UTC
Per the bug thread the issue is a race condition when fetching a file using HTTP, FTP, or SCP. The proposed solution is already implemented in the smart version OE is using but the issue is still there.
Comment 14 Mariano Lopez 2016-06-24 15:10:00 UTC
A way to reproduce the issue is to comment the line 299 "item.setSucceeded(uncomppath)" file fetcher.py. This means the run() method exits without calling item.setSucceeded or item.setFailed(). Unfortunately this method to reproduce the bug doesn't work for debuggin.
Comment 15 Mariano Lopez 2016-06-27 17:30:08 UTC
The way to reproduce the bug in the previous comment is when the file downloaded from the repository server is compressed, and even that way it is intermittent. A way to 100% way to reproduce it is to comment line 1314 "item.setSucceeded(localpath, fetchedsize)", this way is 100% reproducible.
Comment 16 Mariano Lopez 2016-06-27 20:15:16 UTC
Checking a bit more on this, and trying to make it fail with other execution paths, the only way to get the traceback found in the autobuilders is that somehow item._targetpath doesn't get updated. If line "item.setSucceeded(localpath, fetchedsize)" is commented but _targetpath is set manually, the execution succeed; if item.setSucceeded(localpath, fetchedsize) is executed but _targetpath is manually set to None, it will throw the traceback.
Comment 17 Mariano Lopez 2016-06-30 14:45:43 UTC
After more checking on this, thread synchronization seems fine and there is no way to finish the fetching without setting the status to FAILED or SUCCESS.
Comment 18 Mariano Lopez 2016-06-30 19:34:38 UTC
Another way to reproduce the bug is to add a new constant for the failure status, use this in setSucceeded() and setFailed() methods in FetchItem class, and last make the task fail in fetch() method in URLLIB class. This is interesting because there are a lot of comparasions using "is" instead of "==".
Comment 19 Mariano Lopez 2016-07-11 13:36:23 UTC
After several testing, it is always the same object, so no difference between == and is. I'm back to square one.
Comment 20 Saul Wold 2016-07-28 14:45:35 UTC
*** Bug 10007 has been marked as a duplicate of this bug. ***
Comment 21 Mariano Lopez 2016-08-10 15:06:32 UTC
A patch to add debugging was added to smart:

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=909e2120d40c7f0b44be13928899bc6d4675f70d
Comment 22 Leonardo Sandoval Gonzalez 2016-08-25 17:41:54 UTC
The problem original seen has not been observed since proposed patch was merged, thus closing it. In case it comes again, this should be reopened.