Bug 13298

Summary: python3 ptest results are inconsistent per image
Product: [Build System, Metadata & Runtime] OE-Core Reporter: Joshua Watt <JPEWhacker>
Component: coreAssignee: Trevor Gamblin <tgamblin>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: Medium+ CC: a.abfattah, derek, liezhi.yang, meta.mr.watcher, meta.watcher, michael.opdenacker, randy.macleod, richard.purdie, tgamblin, Zheng.Qiu
Version: 2.7   
Target Milestone: 4.3 M2   
Hardware: x86   
OS: Multiple   
Whiteboard: NEWCOMER
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)
Attachments:
Description Flags
ptest log from core-image-sato build
none
ptest log from core-image-sato-sdk build
none
python3 ptest log from core-image-sato build
none
python3 ptest log from core-image-sato-sdk build
none
python3 ptest run 2 log from core-image-sato build none

Description Joshua Watt 2019-04-18 18:35:06 UTC
python3 is generating different ptest results between the core-image-sato and core-image-sato-sdk images. Specifically:

core-image-sato: https://autobuilder.yocto.io/pub/non-release/20190417-10/testresults/qemux86-64-ptest/testresults.json

Recipe                       | Passed      | Failed   | Skipped   | 
python3                      | 30321       | 2        | 1019      | 

core-image-sato-sdk: https://autobuilder.yocto.io/pub/non-release/20190417-14/testresults/qemux86-64-ptest/testresults.json

Recipe                       | Passed      | Failed   | Skipped   | 
python3                      | 30329       | 2        | 1011      |
Comment 1 Joshua Watt 2019-04-18 18:35:39 UTC
Created attachment 4499 [details]
ptest log from core-image-sato build
Comment 2 Joshua Watt 2019-04-18 18:35:53 UTC
Created attachment 4500 [details]
ptest log from core-image-sato-sdk build
Comment 3 Randy MacLeod 2019-04-25 14:54:39 UTC
Needs gcc?
Comment 4 Richard Purdie 2019-05-30 14:28:59 UTC
core-image-minimal:

python3                      | 30277       | 2        | 1043      | 

core-image-sato-sdk-ptest:

python3                      | 30331       | 2        | 1009      | 


so questions still remain about the counts and dependencies.
Comment 5 Mingli Yu 2019-08-05 07:10:47 UTC
Run test against qemux86-64 in my env:
core-image-minimal:

python3                      |  30812      | 1        |   1045    | 

core-image-sato-sdk-ptest:

python3                      |   30834     | 1        |    1022   | 

There are totally 416 cases, and each has its own subcases, so the total number is the sum up of all the subcases.

For core-image-minimal:
the total cases is: 30812+1+1045=31858

For core-image-sato-sdk-ptest:
the total case is: 30834+1+1022=31857

This means: there are 22 cases in core-image-sato-sdk-ptest marked as PASS(30834-30812=22), but in core-image-minimal marked as SKIP as below:
> SKIP: test_build_ext (distutils.tests.test_build_ext.BuildExtTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_find_on_libpath (ctypes.test.test_find.LibPathFindTest) 'gcc, needed for test, not available'
> SKIP: test_folds (test.datetimetester.IranTest_Fast) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_folds (test.datetimetester.IranTest_Pure) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_folds (test.datetimetester.ZoneInfoTest_Fast) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'"
> SKIP: test_folds (test.datetimetester.ZoneInfoTest_Pure) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'"
> SKIP: test_gaps (test.datetimetester.IranTest_Fast) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_gaps (test.datetimetester.IranTest_Pure) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_gaps (test.datetimetester.ZoneInfoTest_Fast) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'"
> SKIP: test_gaps (test.datetimetester.ZoneInfoTest_Pure) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'"
> SKIP: test_get_outputs (distutils.tests.test_build_ext.BuildExtTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_get_outputs (distutils.tests.test_build_ext.ParallelBuildExtTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_gl (ctypes.test.test_find.Test_OpenGL_libs) 'lib_gl not available'
> SKIP: test_glu (ctypes.test.test_find.Test_OpenGL_libs) 'lib_glu not available'
> SKIP: test_lookup_issue1813 (test.test_codecs.CodecsModuleTest) 'test needs Turkish locale'
> SKIP: test_record_extensions (distutils.tests.test_install.InstallTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_run (distutils.tests.test_build_clib.BuildCLibTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_search_cpp (distutils.tests.test_config_cmd.ConfigTestCase) "The 'x86_64-poky-linux-gcc' command is not found"
> SKIP: test_system_transitions (test.datetimetester.IranTest_Fast) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_system_transitions (test.datetimetester.IranTest_Pure) "Skipping Asia/Tehran: [Errno 2] No such file or directory: '/usr/share/zoneinfo/Asia/Tehran'"
> SKIP: test_system_transitions (test.datetimetester.ZoneInfoTest_Fast) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'"
> SKIP: test_system_transitions (test.datetimetester.ZoneInfoTest_Pure) "Skipping America/New_York: [Errno 2] No such file or directory: '/usr/share/zoneinfo/America/New_York'" 

But there is one more case test_getsetlocale_issue1813 (test.test_locale.TestMiscellaneous) marked as SKIP as below for core-image-minimal, 
SKIP: test_getsetlocale_issue1813 (test.test_locale.TestMiscellaneous) 'test needs Turkish locale'
but missed in core-image-sato-sdk-ptest report as its format as below for core-image-sato-sdk-ptest:
test_getsetlocale_issue1813 (test.test_locale.TestMiscellaneous) ... testing with ('tr_TR', 'ISO8859-9') ok

After added a patch to convert test_getsetlocale_issue1813 (test.test_locale.TestMiscellaneous) ... testing with ('tr_TR', 'ISO8859-9') ok
to
PASS: test_getsetlocale_issue1813 (test.test_locale.TestMiscellaneous)
the counts should be consistent.
Comment 6 Trevor Gamblin 2020-02-21 14:26:20 UTC
Working on this again now, but seeing a different output - getting a BrokenPipeError when running the ptest. Looking into it...
Comment 7 Randy MacLeod 2022-06-07 22:51:21 UTC
Trevor are you planning to get to this for 4.1 ? If not, please move to unassigned.
Comment 8 Ahmed Abdelfattah 2023-03-30 15:10:40 UTC
Hi,

I am also getting different results for ptest runs even for the same image on latest kirkstone branch commit hash 85661be8ff3623faf05525bc9f27a2457381f8e9. 

Here are the results that I got running on a qemux86-64 on a MacOS with HVF acceleratiom

core-image-sato
Total duration: 25 min 21 sec
Tests result: SUCCESS
DURATION: 1522
Number of tests:  37135 Number of failures:  8 Number of errors:  0 Number of skipped tests:  1340


core-image-sato-sdk 
Total duration: 1 hour 41 min
Tests result: FAILURE
DURATION: 6076
Number of tests:  37135 Number of failures:  18 Number of errors:  5 Number of skipped tests:  1336

core-image-sato-sdk (2nd run)
Total duration: 2 hour 7 min
Tests result: FAILURE
DURATION: 7667
Number of tests:  37135 Number of failures:  30 Number of errors:  3 Number of skipped tests:  1334



Since I am a newcomer, am not sure if I am running the tests the right way, as I have just followed this documentation https://wiki.yoctoproject.org/wiki/Ptest but I couldn't get a good summary of the total number of tests for a test run and had to write my own script to count and summarize the test runs. I hope there is a better way of doing as it seems other people in the comments are reporting the results in a consistent format.
I attached all the logs which I got and used to come up with this result.

Looking at the failed test cases , I see they are mostly related to timer related APIs and could probably be failing on qemu only and yield different results on real hardware but I don't have hardware at my disposal right now.
Sample of failures:

['Traceback (most recent call last):\n', '  File "/usr/lib/python3.10/test/_test_multiprocessing.py", line 1583, in test_waitfor_timeout\n', '    self.assertTrue(success.value)\n']
['Traceback (most recent call last):\n', '  File "/usr/lib/python3.10/test/test_os.py", line 895, in test_utime_current_old\n', '    self._test_utime_current(set_time)\n']
['Traceback (most recent call last):\n', '  File "/usr/lib/python3.10/test/test_socket.py", line 351, in raise_queued_exception\n', '    raise self.queue.get()\n']



Some enhancements I would suggest/could look at:
* A better formatting of overall test results rather than the huge log.
* some investigation on making qemu more reliable with respect to timing aspects..
Comment 9 Ahmed Abdelfattah 2023-03-30 15:20:54 UTC
Created attachment 4940 [details]
python3 ptest log from core-image-sato build
Comment 10 Ahmed Abdelfattah 2023-03-30 15:21:48 UTC
Created attachment 4941 [details]
python3 ptest log from core-image-sato-sdk build
Comment 11 Ahmed Abdelfattah 2023-03-30 15:22:17 UTC
Created attachment 4942 [details]
python3 ptest run 2 log from core-image-sato build
Comment 12 Randy MacLeod 2023-03-31 18:56:21 UTC
Ahmed,
It's good that you have been able to reproduce the differences in ptest outcomes.

We do struggle with timing issue in qemu and usually we try to get upstream to increase the timeout if that makes sense for them or have a local patch that does so.

There is recent work to compare ptest runs using resulttool but I haven't had a chance to try that out so take a look at the last month or two of matches for:

  https://lore.kernel.org/openembedded-core/?q=resulttool

and maybe Michael Opdenacker will be adding a summary to the docs (I've CCed him here rather than create a defect).
Comment 13 Randy MacLeod 2023-03-31 18:58:00 UTC
Ahmed, also, as you may know, if you want to get a wider audience for discussion or input, then please post something to either the oe-core or yocto email lists.
Comment 14 Michael Opdenacker 2023-04-04 17:50:44 UTC
Hi Randy
Did you think about mentioning the new "yocto-testresults-query" tool
in the release notes?
Cheers
Comment 15 Randy MacLeod 2023-04-04 18:44:34 UTC
Michael, 

Yes, I expect that whoever writes the release notes will cover the "yocto-testresults-query" tool. Is that you, or Paul E?

Ahmed, any news?
Comment 16 Michael Opdenacker 2023-04-04 19:30:45 UTC
Both of us I hope, but I'll do my best to contribute as many details as possible.
Thanks.
Comment 17 Ahmed Abdelfattah 2023-04-11 20:18:02 UTC
So I looked into the resulttool and it is tailored to parse the output of the json file generated by running the test image.
Example: example bitbake core-image-sato-sdk -c testimage -v
It takes to be honest too long on my machine so I couldn’t reproduce with the resulttool yet.

But the logs generated the way I used to run ptest from within the target are not supported by the resulttool.

I didn’t get the time to look into yocto-testresults-query yet.

Now, going back to the main scope I think the tests will keep giving different results , if you have suggestions for that local patch to increase the timeout then I can do another test run.
Comment 18 Richard Purdie 2023-04-12 10:38:46 UTC
(In reply to Ahmed Abdelfattah from comment #17)
> So I looked into the resulttool and it is tailored to parse the output of
> the json file generated by running the test image.
> Example: example bitbake core-image-sato-sdk -c testimage -v
> It takes to be honest too long on my machine so I couldn’t reproduce with
> the resulttool yet.
> 
> But the logs generated the way I used to run ptest from within the target
> are not supported by the resulttool.
> 
> I didn’t get the time to look into yocto-testresults-query yet.
> 
> Now, going back to the main scope I think the tests will keep giving
> different results , if you have suggestions for that local patch to increase
> the timeout then I can do another test run.

One tip to reduce the execution time would be just to run the python ptest in both images and not any of the other tests, For example, in OE-Core master:

meta/recipes-core/images/core-image-ptest.bb:TEST_SUITES = "ping ssh parselogs ptest"

which you could set in local.conf.

I think there were also improvements in ptest dependencies in master but I don't know how much of this issue was addressed there.
Comment 19 Trevor Gamblin 2023-06-29 13:11:22 UTC
My results:

core-image-sato:
----------------------------------------------------------------------
Ran 210 tests in 0.369s

OK (skipped=26)

== Tests result: FAILURE ==

403 tests OK.

3 tests failed:
    test_cgitb test_cppext test_zipapp

28 tests skipped:
    test_asdl_parser test_check_c_globals test_clinic test_curses
    test_devpoll test_gdb test_idle test_kqueue test_launcher
    test_msilib test_ossaudiodev test_readline test_smtpnet
    test_socketserver test_startfile test_tcl test_tix test_tk
    test_ttk_guionly test_ttk_textonly test_turtle test_urllib2net
    test_urllibnet test_winconsoleio test_winreg test_winsound
    test_xmlrpc_net test_zipfile64

Total duration: 22 min 46 sec
Tests result: FAILURE
DURATION: 1368
END: /usr/lib/python3/ptest
2023-06-28T20:45
STOP: ptest-runner
TOTAL: 1 FAIL: 0

core-image-sato-sdk:
----------------------------------------------------------------------
Ran 210 tests in 0.345s

OK (skipped=26)

== Tests result: FAILURE ==

404 tests OK.

2 tests failed:
    test_cgitb test_zipapp

28 tests skipped:
    test_asdl_parser test_check_c_globals test_clinic test_curses
    test_devpoll test_gdb test_idle test_kqueue test_launcher
    test_msilib test_ossaudiodev test_readline test_smtpnet
    test_socketserver test_startfile test_tcl test_tix test_tk
    test_ttk_guionly test_ttk_textonly test_turtle test_urllib2net
    test_urllibnet test_winconsoleio test_winreg test_winsound
    test_xmlrpc_net test_zipfile64

Total duration: 23 min 8 sec
Tests result: FAILURE
DURATION: 1389
END: /usr/lib/python3/ptest
2023-06-28T20:22
STOP: ptest-runner
TOTAL: 1 FAIL: 0


So there's a very minimal difference between the images now, and the main gap appears to be the presence of cpp. I'm undecided on whether or not it should be in the ptest RDEPENDS...
Comment 20 Richard Purdie 2023-06-29 14:13:16 UTC
Thanks for checking into this! Could you also compare that against a core-image-ptest-python3 please? We probably should put cpp in the python-ptest dependencies, I suspect it won't add much to the build time as it is already building the compiler?
Comment 21 Trevor Gamblin 2023-06-29 14:32:23 UTC
Will do. Meanwhile, here's the actual failure for the test_cppext test:

0:05:43 load avg: 0.32 [ 90/434] test_cppext
/var/volatile/tmp/test_python_790æ/tempcwd/env/lib/python3.11/site-packages/setuptools/__init__.py:10: DeprecationWarning: The distutils package is deprecated and slated for removal in Python 3.12. Use setuptools or check PEP 632 for potential alternatives
  import distutils.core
/usr/lib/python3.11/distutils/command/build_ext.py:13: DeprecationWarning: The distutils.sysconfig module is deprecated, use sysconfig instead
  from distutils.sysconfig import customize_compiler, get_python_version
test_build_cpp03 (test.test_cppext.TestCPPExt.test_build_cpp03) ... running build_ext
building '_testcpp03ext' extension 
creating build
creating build/temp.linux-x86_64-3.11
creating build/temp.linux-x86_64-3.11/usr
creating build/temp.linux-x86_64-3.11/usr/lib
creating build/temp.linux-x86_64-3.11/usr/lib/python3.11
creating build/temp.linux-x86_64-3.11/usr/lib/python3.11/test
error: command 'x86_64-poky-linux-gcc' failed: No such file or directory
x86_64-poky-linux-gcc -m64 -march=core2 -mtune=core2 -msse3 -mfpmath=sse -fstack-protector-strong -O2 -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security -Werror=format-security -Wsign-compare -DNDEBUG -g -O3 -Wall -O2 -pipe -g -feliminate-unused-debug-types -fcanon-prefix-map -fmacro-prefix-map=/python3/3.11.4-r0/Python-
3.11.4=/usr/src/debug/python3/3.11.4-r0 -fdebug-prefix-map=/python3/3.11.4-r0/Python-3.11.4=/usr/src/debug/python3/3.11.4-r0 -fmacro-prefix-map=/build/path/unavailable/=/usr/src/debug/python3/3.11.4-r0 -fdebug-prefix-map=/build/path/unavailable/=/usr/src/debug/python3/3.11.4-r0 -fdebug-prefix-map== -fmacro-prefix-map
== -fdebug-prefix-map== -O2 -pipe -g -feliminate-unused-debug-types -fcanon-prefix-map -fmacro-prefix-map=/python3/3.11.4-r0/Python-3.11.4=/usr/src/debug/python3/3.11.4-r0 -fdebug-prefix-map=/python3/3.11.4-r0/Python-3.11.4=/usr/src/debug/python3/3.11.4-r0 -fmacro-prefix-map=/build/path/unavailable/=/usr/src/debug/py
thon3/3.11.4-r0 -fdebug-prefix-map=/build/path/unavailable/=/usr/src/debug/python3/3.11.4-r0 -fdebug-prefix-map== -fmacro-prefix-map== -fdebug-prefix-map== -fPIC -I/var/volatile/tmp/test_python_790æ/tempcwd/env/include -I/usr/include/python3.11 -c /usr/lib/python3.11/test/_testcppext.cpp -o build/temp.linux-x86_64-3.
11/usr/lib/python3.11/test/_testcppext.o -Werror -std=c++03

x86_64-poky-linux-gcc shouldn't be in the image, right?
Comment 22 Trevor Gamblin 2023-06-29 18:29:10 UTC
Went down the rabbit hole to attempt a fix. Adding gcc and cpp to the ptest RDEPENDS (which isn't desirable anyway) didn't work on its own, because of an issue not being able to find cc1plus. Adding g++ didn't help either as then the tests started complaining about distutils being deprecated.

I then went looking in the Python source, I found two commits that will go into 3.12 which change the test to no longer use distutils:

https://github.com/python/cpython/commit/9e677406ee6666b32d869ce68c826519ff877445
https://github.com/python/cpython/commit/afa759fb800be416f69e3e9c9b3efe68006316f5

Backporting these together onto 3.11.4 (current oe-core python3) was successful with some minor adjustments to the source, but test_cppext still fails because it can't find a setuptools wheel, and test_distutils also started failing. I'll have to dig into this more next week.
Comment 23 Trevor Gamblin 2023-06-29 19:06:23 UTC
For comparison, here is how core-image-ptest-python3 fares with testimage:

----------------------------------------------------------------------
Ran 210 tests in 0.392s

OK (skipped=26)

== Tests result: FAILURE ==

403 tests OK.

3 tests failed:
    test_cgitb test_cppext test_zipapp

28 tests skipped:
    test_asdl_parser test_check_c_globals test_clinic test_curses
    test_devpoll test_gdb test_idle test_kqueue test_launcher
    test_msilib test_ossaudiodev test_readline test_smtpnet
    test_socketserver test_startfile test_tcl test_tix test_tk
    test_ttk_guionly test_ttk_textonly test_turtle test_urllib2net
    test_urllibnet test_winconsoleio test_winreg test_winsound
    test_xmlrpc_net test_zipfile64

Total duration: 23 min 9 sec
Tests result: FAILURE
DURATION: 1391
END: /usr/lib/python3/ptest
2023-06-29T19:04
STOP: ptest-runner
TOTAL: 1 FAIL: 0
Comment 24 Richard Purdie 2023-07-03 10:26:42 UTC
(In reply to Trevor Gamblin from comment #23)
> For comparison, here is how core-image-ptest-python3 fares with testimage:
> 

Thanks, that confirms there is really just a handful of issues left!
Comment 25 Trevor Gamblin 2023-07-04 18:47:50 UTC
My disutils rambling was not relevant to the failure. Adding the following to the image allows for the test_cppext test to pass:

gcc g++ binutils

This seems like a lot, as discussed before. Do we want to try adding these exclusively for the Python3 ptests, or do we want to disable that test?
Comment 26 Trevor Gamblin 2023-07-11 18:00:46 UTC
New patch in that does the following:

- Adds gcc, g++, binutils to the ptest RDEPENDS for python3 to cover test_cppext
- Adds more memory for core-image-ptest-python3 (2048 MB)
- Parallelizes the test run to improve overall runtime

If there are no issues with that patch then this issue should be closed soon.
Comment 27 Trevor Gamblin 2023-07-18 18:34:57 UTC
Fixed in this patch:

https://git.openembedded.org/openembedded-core/commit/?id=50a719d3002a4119e8b2be43aec8fe01aa0c2a40

Results:

== Tests result: SUCCESS ==                                                                                                                                    
                                                                                                                                                               
405 tests OK.                                                                                                                                                  
                                                                                                                                                               
29 tests skipped:                                                                                                                                              
    test_asdl_parser test_check_c_globals test_clinic test_curses                                                                                                                                                                                                                                                             
    test_devpoll test_gdb test_idle test_ioctl test_kqueue                                                                                                     
    test_launcher test_msilib test_ossaudiodev test_readline                                                                                                   
    test_smtpnet test_socketserver test_startfile test_tcl test_tix                                                                                            
    test_tk test_ttk_guionly test_ttk_textonly test_turtle                                                                                                     
    test_urllib2net test_urllibnet test_winconsoleio test_winreg                                                                                               
    test_winsound test_xmlrpc_net test_zipfile64                                                                                                               
                                                                                                                                                               
Total duration: 5 min 10 sec                                                                                                                                   
Tests result: SUCCESS