#2 During running tests, it's very hard to see what's happening
Opened 2 years ago by churchyard. Modified 3 months ago

Recently a test was running couple hours at https://jenkins-continuous-infra.apps.ci.centos.org/blue/organizations/jenkins/fedora-rawhide-pr-pipeline/detail/fedora-rawhide-pr-pipeline/271/pipeline

All I could see was gibberish in the live logs (jsons, asterisks, git internals) and no actual output from the test script at https://src.fedoraproject.org/tests/python/blob/master/f/smoke/venv.sh - note that for me as a developer, this is the only important output.

I needed to wait until the test fail so see the useful output in Artifacts.


E.g. this is what I see in the live log:

TASK [str-common-init : Copy tests to test environment] ************************

changed: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2] => {"changed": true, "cmd": "/usr/bin/rsync --delay-updates -F --compress --archive --rsh=/usr/bin/ssh -S none -i /tmp/inventory-cloudaw8aDt/identity -o Port=2321 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o UserKnownHostsFile=/dev/null --out-format=<<CHANGED>>%i %n%L /workDir/workspace/fedora-rawhide-pr-pipeline/python36/tests/ root@127.0.0.3:/var/str/", "msg": "cd+++++++++ ./\n<f+++++++++ tests.yml\ncd+++++++++ python/\n<f+++++++++ python/.gitignore\n<f+++++++++ python/README.rst\ncd+++++++++ python/.git/\n<f+++++++++ python/.git/HEAD\n<f+++++++++ python/.git/ORIG_HEAD\n<f+++++++++ python/.git/config\n<f+++++++++ python/.git/description\n<f+++++++++ python/.git/index\n<f+++++++++ python/.git/packed-refs\ncd+++++++++ python/.git/branches/\ncd+++++++++ python/.git/hooks/\n<f+++++++++ python/.git/hooks/applypatch-msg.sample\n<f+++++++++ python/.git/hooks/commit-msg.sample\n<f+++++++++ python/.git/hooks/post-update.sample\n<f+++++++++ python/.git/hooks/pre-applypatch.sample\n<f+++++++++ python/.git/hooks/pre-commit.sample\n<f+++++++++ python/.git/hooks/pre-push.sample\n<f+++++++++ python/.git/hooks/pre-rebase.sample\n<f+++++++++ python/.git/hooks/prepare-commit-msg.sample\n<f+++++++++ python/.git/hooks/update.sample\ncd+++++++++ python/.git/info/\n<f+++++++++ python/.git/info/exclude\ncd+++++++++ python/.git/logs/\n<f+++++++++ python/.git/logs/HEAD\ncd+++++++++ python/.git/logs/refs/\ncd+++++++++ python/.git/logs/refs/heads/\n<f+++++++++ python/.git/logs/refs/heads/master\ncd+++++++++ python/.git/logs/refs/remotes/\ncd+++++++++ python/.git/logs/refs/remotes/origin/\n<f+++++++++ python/.git/logs/refs/remotes/origin/HEAD\ncd+++++++++ python/.git/objects/\ncd+++++++++ python/.git/objects/01/\n<f+++++++++ python/.git/objects/01/2955887145232fd678dbc6f4252bb21fb05f23\ncd+++++++++ python/.git/objects/03/\n<f+++++++++ python/.git/objects/03/434a6f26c1fef4a19363c31e9643fce9e86c4e\ncd+++++++++ python/.git/objects/0c/\n<f+++++++++ python/.git/objects/0c/b918215aa632764335b3057272713d9d9c2615\ncd+++++++++ python/.git/objects/25/\n<f+++++++++ python/.git/objects/25/40126bc6af6b52caf5d06a8288197d523ade10\ncd+++++++++ python/.git/objects/26/\n<f+++++++++ python/.git/objects/26/9c82dc2b56464cc598f43cf6356bb1a8225cd2\ncd+++++++++ python/.git/objects/30/\n<f+++++++++ python/.git/objects/30/00a7ccbe63f26d92b14dfbfbc2279092b3755b\ncd+++++++++ python/.git/objects/35/\n<f+++++++++ python/.git/objects/35/276572d6fb18bcbd5fbb2b81ab97c5ac075232\ncd+++++++++ python/.git/objects/3a/\n<f+++++++++ python/.git/objects/3a/0d22e0e78a9370740b3dc82f2129ac88489cd5\ncd+++++++++ python/.git/objects/3d/\n<f+++++++++ python/.git/objects/3d/886dc7dce1097fab823abdf841a403d60e6536\ncd+++++++++ python/.git/objects/3f/\n<f+++++++++ python/.git/objects/3f/4794ab3885b40e7782229b3ce90a51641d38f3\ncd+++++++++ python/.git/objects/41/\n<f+++++++++ python/.git/objects/41/3ee198691f12fdf29c0fe4f27577bdaca0cd40\n<f+++++++++ python/.git/objects/41/eef2c4dc8857a6ecf281dce8dedf6fad40132b\ncd+++++++++ python/.git/objects/42/\n<f+++++++++ python/.git/objects/42/e0692eab5e5cbfa29cab013df5732bfa322285\ncd+++++++++ python/.git/objects/44/\n<f+++++++++ python/.git/objects/44/2c21a45feffb7c8886e2d8e8cfa1d511c7cdda\ncd+++++++++ python/.git/objects/50/\n<f+++++++++ python/.git/objects/50/f0f592f5a46df89fa290d604d77e9e961e5911\ncd+++++++++ python/.git/objects/51/\n<f+++++++++ python/.git/objects/51/69b862387116eeaec7442a48e936506800afb2\ncd+++++++++ python/.git/objects/57/\n<f+++++++++ python/.git/objects/57/457cbafb54cbedb417c2ed72bd6aea4fc67705\ncd+++++++++ python/.git/objects/5b/\n<f+++++++++ python/.git/objects/5b/166dd62f41aa3b00af308e0f391305167af927\ncd+++++++++ python/.git/objects/70/\n<f+++++++++ python/.git/objects/70/9f92488093a9fdec88f3d64bd112f74daaf7d5\ncd+++++++++ python/.git/objects/72/\n<f+++++++++ python/.git/objects/72/d721171733b3a72a4e4a7cf337f1556bf9abb9\ncd+++++++++ python/.git/objects/73/\n<f+++++++++ python/.git/objects/73/e7da996e4e05d68d4968398fe8b322122e03a2\n<f+++++++++ python/.git/objects/73/f68d714041b194bc37990ef04aab5d4e794ccd\ncd+++++++++ python/.git/objects/7f/\n<f+++++++++ python/.git/objects/7f/890d12b895b2b9ae79db34caf1f041be21ae47\ncd+++++++++ python/.git/objects/8e/\n<f+++++++++ python/.git/objects/8e/20322586353451e0de311c91851f3bd2ead207\ncd+++++++++ python/.git/objects/91/\n<f+++++++++ python/.git/objects/91/ede54e8520cac33ec9e919478c91bee795f7ef\ncd+++++++++ python/.git/objects/97/\n<f+++++++++ python/.git/objects/97/b6509e63808b2b824a4a4fde7825a1d400cd84\ncd+++++++++ python/.git/objects/98/\n<f+++++++++ python/.git/objects/98/17e2e7cd1f2fb74c1541b27cde8a52958bbdbe\ncd+++++++++ python/.git/objects/9d/\n<f+++++++++ python/.git/objects/9d/211db15bb2a6bb9ca41585e2b9672a5da1e9ca\ncd+++++++++ python/.git/objects/a5/\n<f+++++++++ python/.git/objects/a5/5748915e99178b13e9755c74654c50601a5c99\ncd+++++++++ python/.git/objects/a6/\n<f+++++++++ python/.git/objects/a6/067a88207cd19a63c4095daf3eafb862b32633\ncd+++++++++ python/.git/objects/a8/\n<f+++++++++ python/.git/objects/a8/22a9ef4e834d5dd4a628e4d688be8e275348c7\ncd+++++++++ python/.git/objects/aa/\n<f+++++++++ python/.git/objects/aa/5f2fee637c42bae5146c32aa78bc00f4d3a598\ncd+++++++++ python/.git/objects/b2/\n<f+++++++++ python/.git/objects/b2/0291faee0d67b7db18c65df4d68eeac13a2a55\ncd+++++++++ python/.git/objects/bb/\n<f+++++++++ python/.git/objects/bb/36258644ca9eb0db46e612a24fbc7a4339a59a\ncd+++++++++ python/.git/objects/d7/\n<f+++++++++ python/.git/objects/d7/cf02c145474ae62753f7f8ee344f6138be485c\ncd+++++++++ python/.git/objects/df/\n<f+++++++++ python/.git/objects/df/58d21b89cbfdccd3058a07fa8292f780b60899\ncd+++++++++ python/.git/objects/f4/\n<f+++++++++ python/.git/objects/f4/07a87e64316d9b92fe72a8f364b6066ebd9627\ncd+++++++++ python/.git/objects/fc/\n<f+++++++++ python/.git/objects/fc/b6314f297e4423e4e777a16d963563f3d64740\ncd+++++++++ python/.git/objects/info/\ncd+++++++++ python/.git/objects/pack/\ncd+++++++++ python/.git/refs/\ncd+++++++++ python/.git/refs/heads/\n<f+++++++++ python/.git/refs/heads/master\ncd+++++++++ python/.git/refs/remotes/\ncd+++++++++ python/.git/refs/remotes/origin/\n<f+++++++++ python/.git/refs/remotes/origin/HEAD\ncd+++++++++ python/.git/refs/tags/\ncd+++++++++ python/smoke/\n<f+++++++++ python/smoke/venv.sh\n", "rc": 0, "stdout_lines": ["cd+++++++++ ./", "<f+++++++++ tests.yml", "cd+++++++++ python/", "<f+++++++++ python/.gitignore", "<f+++++++++ python/README.rst", "cd+++++++++ python/.git/", "<f+++++++++ python/.git/HEAD", "<f+++++++++ python/.git/ORIG_HEAD", "<f+++++++++ python/.git/config", "<f+++++++++ python/.git/description", "<f+++++++++ python/.git/index", "<f+++++++++ python/.git/packed-refs", "cd+++++++++ python/.git/branches/", "cd+++++++++ python/.git/hooks/", "<f+++++++++ python/.git/hooks/applypatch-msg.sample", "<f+++++++++ python/.git/hooks/commit-msg.sample", "<f+++++++++ python/.git/hooks/post-update.sample", "<f+++++++++ python/.git/hooks/pre-applypatch.sample", "<f+++++++++ python/.git/hooks/pre-commit.sample", "<f+++++++++ python/.git/hooks/pre-push.sample", "<f+++++++++ python/.git/hooks/pre-rebase.sample", "<f+++++++++ python/.git/hooks/prepare-commit-msg.sample", "<f+++++++++ python/.git/hooks/update.sample", "cd+++++++++ python/.git/info/", "<f+++++++++ python/.git/info/exclude", "cd+++++++++ python/.git/logs/", "<f+++++++++ python/.git/logs/HEAD", "cd+++++++++ python/.git/logs/refs/", "cd+++++++++ python/.git/logs/refs/heads/", "<f+++++++++ python/.git/logs/refs/heads/master", "cd+++++++++ python/.git/logs/refs/remotes/", "cd+++++++++ python/.git/logs/refs/remotes/origin/", "<f+++++++++ python/.git/logs/refs/remotes/origin/HEAD", "cd+++++++++ python/.git/objects/", "cd+++++++++ python/.git/objects/01/", "<f+++++++++ python/.git/objects/01/2955887145232fd678dbc6f4252bb21fb05f23", "cd+++++++++ python/.git/objects/03/", "<f+++++++++ python/.git/objects/03/434a6f26c1fef4a19363c31e9643fce9e86c4e", "cd+++++++++ python/.git/objects/0c/", "<f+++++++++ python/.git/objects/0c/b918215aa632764335b3057272713d9d9c2615", "cd+++++++++ python/.git/objects/25/", "<f+++++++++ python/.git/objects/25/40126bc6af6b52caf5d06a8288197d523ade10", "cd+++++++++ python/.git/objects/26/", "<f+++++++++ python/.git/objects/26/9c82dc2b56464cc598f43cf6356bb1a8225cd2", "cd+++++++++ python/.git/objects/30/", "<f+++++++++ python/.git/objects/30/00a7ccbe63f26d92b14dfbfbc2279092b3755b", "cd+++++++++ python/.git/objects/35/", "<f+++++++++ python/.git/objects/35/276572d6fb18bcbd5fbb2b81ab97c5ac075232", "cd+++++++++ python/.git/objects/3a/", "<f+++++++++ python/.git/objects/3a/0d22e0e78a9370740b3dc82f2129ac88489cd5", "cd+++++++++ python/.git/objects/3d/", "<f+++++++++ python/.git/objects/3d/886dc7dce1097fab823abdf841a403d60e6536", "cd+++++++++ python/.git/objects/3f/", "<f+++++++++ python/.git/objects/3f/4794ab3885b40e7782229b3ce90a51641d38f3", "cd+++++++++ python/.git/objects/41/", "<f+++++++++ python/.git/objects/41/3ee198691f12fdf29c0fe4f27577bdaca0cd40", "<f+++++++++ python/.git/objects/41/eef2c4dc8857a6ecf281dce8dedf6fad40132b", "cd+++++++++ python/.git/objects/42/", "<f+++++++++ python/.git/objects/42/e0692eab5e5cbfa29cab013df5732bfa322285", "cd+++++++++ python/.git/objects/44/", "<f+++++++++ python/.git/objects/44/2c21a45feffb7c8886e2d8e8cfa1d511c7cdda", "cd+++++++++ python/.git/objects/50/", "<f+++++++++ python/.git/objects/50/f0f592f5a46df89fa290d604d77e9e961e5911", "cd+++++++++ python/.git/objects/51/", "<f+++++++++ python/.git/objects/51/69b862387116eeaec7442a48e936506800afb2", "cd+++++++++ python/.git/objects/57/", "<f+++++++++ python/.git/objects/57/457cbafb54cbedb417c2ed72bd6aea4fc67705", "cd+++++++++ python/.git/objects/5b/", "<f+++++++++ python/.git/objects/5b/166dd62f41aa3b00af308e0f391305167af927", "cd+++++++++ python/.git/objects/70/", "<f+++++++++ python/.git/objects/70/9f92488093a9fdec88f3d64bd112f74daaf7d5", "cd+++++++++ python/.git/objects/72/", "<f+++++++++ python/.git/objects/72/d721171733b3a72a4e4a7cf337f1556bf9abb9", "cd+++++++++ python/.git/objects/73/", "<f+++++++++ python/.git/objects/73/e7da996e4e05d68d4968398fe8b322122e03a2", "<f+++++++++ python/.git/objects/73/f68d714041b194bc37990ef04aab5d4e794ccd", "cd+++++++++ python/.git/objects/7f/", "<f+++++++++ python/.git/objects/7f/890d12b895b2b9ae79db34caf1f041be21ae47", "cd+++++++++ python/.git/objects/8e/", "<f+++++++++ python/.git/objects/8e/20322586353451e0de311c91851f3bd2ead207", "cd+++++++++ python/.git/objects/91/", "<f+++++++++ python/.git/objects/91/ede54e8520cac33ec9e919478c91bee795f7ef", "cd+++++++++ python/.git/objects/97/", "<f+++++++++ python/.git/objects/97/b6509e63808b2b824a4a4fde7825a1d400cd84", "cd+++++++++ python/.git/objects/98/", "<f+++++++++ python/.git/objects/98/17e2e7cd1f2fb74c1541b27cde8a52958bbdbe", "cd+++++++++ python/.git/objects/9d/", "<f+++++++++ python/.git/objects/9d/211db15bb2a6bb9ca41585e2b9672a5da1e9ca", "cd+++++++++ python/.git/objects/a5/", "<f+++++++++ python/.git/objects/a5/5748915e99178b13e9755c74654c50601a5c99", "cd+++++++++ python/.git/objects/a6/", "<f+++++++++ python/.git/objects/a6/067a88207cd19a63c4095daf3eafb862b32633", "cd+++++++++ python/.git/objects/a8/", "<f+++++++++ python/.git/objects/a8/22a9ef4e834d5dd4a628e4d688be8e275348c7", "cd+++++++++ python/.git/objects/aa/", "<f+++++++++ python/.git/objects/aa/5f2fee637c42bae5146c32aa78bc00f4d3a598", "cd+++++++++ python/.git/objects/b2/", "<f+++++++++ python/.git/objects/b2/0291faee0d67b7db18c65df4d68eeac13a2a55", "cd+++++++++ python/.git/objects/bb/", "<f+++++++++ python/.git/objects/bb/36258644ca9eb0db46e612a24fbc7a4339a59a", "cd+++++++++ python/.git/objects/d7/", "<f+++++++++ python/.git/objects/d7/cf02c145474ae62753f7f8ee344f6138be485c", "cd+++++++++ python/.git/objects/df/", "<f+++++++++ python/.git/objects/df/58d21b89cbfdccd3058a07fa8292f780b60899", "cd+++++++++ python/.git/objects/f4/", "<f+++++++++ python/.git/objects/f4/07a87e64316d9b92fe72a8f364b6066ebd9627", "cd+++++++++ python/.git/objects/fc/", "<f+++++++++ python/.git/objects/fc/b6314f297e4423e4e777a16d963563f3d64740", "cd+++++++++ python/.git/objects/info/", "cd+++++++++ python/.git/objects/pack/", "cd+++++++++ python/.git/refs/", "cd+++++++++ python/.git/refs/heads/", "<f+++++++++ python/.git/refs/heads/master", "cd+++++++++ python/.git/refs/remotes/", "cd+++++++++ python/.git/refs/remotes/origin/", "<f+++++++++ python/.git/refs/remotes/origin/HEAD", "cd+++++++++ python/.git/refs/tags/", "cd+++++++++ python/smoke/", "<f+++++++++ python/smoke/venv.sh"]}



TASK [str-common-init : Start services defined in `required_services`] *********



TASK [standard-test-basic : Execute tests] *************************************
changed: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2] => (item={u'smoke': {u'run': u'VERSION=3.6 ./venv.sh', u'dir': u'python/smoke'}}) => {"changed": true, "cmd": "if [[ -z ${TEST} ]]; then\n echo \"FAIL: Test case name is not set\" >> /tmp/artifacts//test.log\n exit\n fi\n if [[ -z ${TEST_DIR} ]]; then\n echo \"FAIL: Test directory for $TEST not found\" >> /tmp/artifacts//test.log\n exit\n fi\n if [[ -z ${TEST_CMD} ]]; then\n echo \"FAIL: Does not know how to run $TEST\" >> /tmp/artifacts//test.log\n exit\n fi\n log_file_name=$(echo $TEST | sed -e 's/\\//-/g').log\n logfile=/tmp/artifacts//${log_file_name}\n exec 2>>$logfile 1>>$logfile\n cd $TEST_DIR\n #if command is a file make it executable\n cmd=\"$(echo $TEST_CMD | awk '{print $1;}')\"\n if [ -f \"$cmd\" ]; then\n chmod 0775 \"$cmd\"\n fi\n status=\"FAIL\"\n #execute the test\n eval $TEST_CMD\n if [ $? -eq 0 ]; then\n status=\"PASS\"\n fi\n echo \"${status} $TEST\" >> /tmp/artifacts//test.log\n # Add test status as prefix to test case log\n mv ${logfile} /tmp/artifacts//${status}_${log_file_name}", "delta": "0:00:14.443871", "end": "2018-08-30 10:41:00.201671", "item": {"smoke": {"dir": "python/smoke", "run": "VERSION=3.6 ./venv.sh"}}, "rc": 0, "start": "2018-08-30 10:40:45.757800", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}



TASK [standard-test-basic : Check the results] *********************************

changed: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2] => {"changed": true, "cmd": "grep \"^FAIL\" /tmp/artifacts//test.log", "delta": "0:00:00.007065", "end": "2018-08-30 10:41:01.039233", "failed_when_result": false, "rc": 0, "start": "2018-08-30 10:41:01.032168", "stderr": "", "stderr_lines": [], "stdout": "FAIL smoke", "stdout_lines": ["FAIL smoke"]}



TASK [standard-test-basic : Set role result] ***********************************

ok: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2] => {"ansible_facts": {"role_result_failed": true, "role_result_msg": "FAIL smoke"}, "changed": false}



TASK [standard-test-basic : include_role] **************************************



TASK [str-common-final : Pull out the logs from test environment to test runner] ***

changed: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2] => {"changed": true, "cmd": "/usr/bin/rsync --delay-updates -F --compress --archive --rsh=/usr/bin/ssh -S none -i /tmp/inventory-cloudaw8aDt/identity -o Port=2321 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o UserKnownHostsFile=/dev/null --out-format=<<CHANGED>>%i %n%L root@127.0.0.3:/tmp/artifacts// /workDir/workspace/fedora-rawhide-pr-pipeline/logs/", "msg": ".d..t...... ./\n>f+++++++++ FAIL_smoke.log\n>f+++++++++ test.log\n", "rc": 0, "stdout_lines": [".d..t...... ./", ">f+++++++++ FAIL_smoke.log", ">f+++++++++ test.log"]}



TASK [str-common-final : Report role result] ***********************************

fatal: [/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2]: FAILED! => {

    "msg": [

        "Tests failed: True", 

        "Tests msg: FAIL smoke", 

        ""

    ]

}

    to retry, use: --limit @/workDir/workspace/fedora-rawhide-pr-pipeline/python36/tests/tests.retry



PLAY RECAP *********************************************************************

/workDir/workspace/fedora-rawhide-pr-pipeline/images/test_subject.qcow2 : ok=32   changed=9    unreachable=0    failed=1   



+ clean_up

+ rm -rf tests/package

+ mkdir -p tests/package

+ cp -rp /workDir/workspace/fedora-rawhide-pr-pipeline/logs/FAIL_smoke.log /workDir/workspace/fedora-rawhide-pr-pipeline/logs/default_provisioners.log /workDir/workspace/fedora-rawhide-pr-pipeline/logs/test.log /workDir/workspace/fedora-rawhide-pr-pipeline/logs/test_subject.qcow2.guest.log /workDir/workspace/fedora-rawhide-pr-pipeline/logs/test_subject.qcow2.qemu.log /workDir/workspace/fedora-rawhide-pr-pipeline/logs/tests.yml-run.txt tests/package/

+ cat /workDir/workspace/fedora-rawhide-pr-pipeline/logs/test.log

FAIL smoke

And this is what I want to see:

+ VERSION=3.6
+ PYTHON=python3.6
+ METHOD=venv
+ TOX=true
+ rm -rf venv .tox __pycache__ '.pytest*' 'test_*.py' '*.pyx' '*.c' '*.so'
+ '[' venv == venv ']'
+ python3.6 -m venv venv
+ set +u
+ source venv/bin/activate
++ deactivate nondestructive
++ '[' -n '' ']'
++ '[' -n '' ']'
++ '[' -n /bin/sh -o -n '' ']'
++ hash -r
++ '[' -n '' ']'
++ unset VIRTUAL_ENV
++ '[' '!' nondestructive = nondestructive ']'
++ VIRTUAL_ENV=/var/str/python/smoke/venv
++ export VIRTUAL_ENV
++ _OLD_VIRTUAL_PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
++ PATH=/var/str/python/smoke/venv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
++ export PATH
++ '[' -n '' ']'
++ '[' -z '' ']'
++ _OLD_VIRTUAL_PS1=
++ '[' 'x(venv) ' '!=' x ']'
++ PS1='(venv) '
++ export PS1
++ '[' -n /bin/sh -o -n '' ']'
++ hash -r
+ set -u
+ python -c 'import sys; print(sys.version)'
+ head -n1
+ grep 3.6
3.6.6 (default, Aug 30 2018, 10:14:54) 
+ '[' 3.6 == 2.6 ']'
+ python -m pip install pytest Cython
Collecting pytest
  Downloading https://files.pythonhosted.org/packages/0e/8c/673d56ebe1c9362ff829acf7e67fd4aba09377d44d80fc7435f1369bfe3a/pytest-3.7.4-py2.py3-none-any.whl (204kB)
Collecting Cython
  Downloading https://files.pythonhosted.org/packages/19/8e/32b280abb0947a96cdbb8329fb2014851a21fc1d099009f946ea8a8202c3/Cython-0.28.5-cp36-cp36m-manylinux1_x86_64.whl (3.4MB)
Collecting six>=1.10.0 (from pytest)
  Downloading https://files.pythonhosted.org/packages/67/4b/141a581104b1f6397bfa78ac9d43d8ad29a7ca43ea90a2d863fe3056e86a/six-1.11.0-py2.py3-none-any.whl
Collecting atomicwrites>=1.0 (from pytest)
  Downloading https://files.pythonhosted.org/packages/0a/67/6cc7ebe2c939aa8e0de9cc3d2660b105d365330c2a8ffb066738fc83562f/atomicwrites-1.2.0-py2.py3-none-any.whl
Collecting pluggy>=0.7 (from pytest)
  Downloading https://files.pythonhosted.org/packages/f5/f1/5a93c118663896d83f7bcbfb7f657ce1d0c0d617e6b4a443a53abcc658ca/pluggy-0.7.1-py2.py3-none-any.whl
Requirement already satisfied: setuptools in ./venv/lib/python3.6/site-packages (from pytest) (39.2.0)
Collecting more-itertools>=4.0.0 (from pytest)
  Downloading https://files.pythonhosted.org/packages/79/b1/eace304ef66bd7d3d8b2f78cc374b73ca03bc53664d78151e9df3b3996cc/more_itertools-4.3.0-py3-none-any.whl (48kB)
Collecting py>=1.5.0 (from pytest)
  Downloading https://files.pythonhosted.org/packages/c8/47/d179b80ab1dc1bfd46a0c87e391be47e6c7ef5831a9c138c5c49d1756288/py-1.6.0-py2.py3-none-any.whl (83kB)
Collecting attrs>=17.4.0 (from pytest)
  Downloading https://files.pythonhosted.org/packages/41/59/cedf87e91ed541be7957c501a92102f9cc6363c623a7666d69d51c78ac5b/attrs-18.1.0-py2.py3-none-any.whl
Installing collected packages: six, atomicwrites, pluggy, more-itertools, py, attrs, pytest, Cython
Successfully installed Cython-0.28.5 atomicwrites-1.2.0 attrs-18.1.0 more-itertools-4.3.0 pluggy-0.7.1 py-1.6.0 pytest-3.7.4 six-1.11.0
+ cat
+ python -m pytest -v test_foo.py
============================= test session starts ==============================
platform linux -- Python 3.6.6, pytest-3.7.4, py-1.6.0, pluggy-0.7.1 -- /var/str/python/smoke/venv/bin/python
cachedir: .pytest_cache
rootdir: /var/str/python/smoke, inifile:
collecting ... collected 1 item

test_foo.py::test_foo PASSED                                             [100%]

=========================== 1 passed in 0.02 seconds ===========================
+ cat
+ cat
+ python setup.py build_ext --inplace
Compiling module.pyx because it changed.
[1/1] Cythonizing module.pyx
running build_ext
building 'module' extension
creating build
creating build/temp.linux-x86_64-3.6
gcc -pthread -Wno-unused-result -Wsign-compare -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DNDEBUG -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv -fPIC -I/var/str/python/smoke/venv/include -I/usr/include/python3.6m -c module.c -o build/temp.linux-x86_64-3.6/module.o
error: command 'gcc' failed with exit status 1

Metadata Update from @bookwar:
- Issue tagged with: UX

2 years ago

Yes and Yes! Exactly my thoughts here. To solve this, we need to wrap around ansible :/ Planned, but yeah, we are not so close to have this done :(

Even wrapping aroud ansible does not help here, as the ^ output is available just after ansible finishes :/ We need to investigate if we can solve this at all.

@mvadkert You are talking about real-time line by line logging from ansible task. And it is indeed hard to do. There are certain ways to do it, but all of them are "hackish".

Let's maybe first focus on the problem: "what do we show as the output for the task". Adding logs to that output is doable.

@churchyard will it help if we have the test log printed once the test task itself is done? Right after the task, not after the entire job run.

@bookwar It would certainly be better. However not great either.

What I'm hoping for is output like this:

https://travis-ci.org/python/cpython/jobs/466504840

I would love to to see the output of my tests:

  • as they are run
  • without crazy unreadable gibberish all around

The CI system knows that the main output of the test is supposed to be in file $artifacts/test.log, the exact path is known to it. So provided the test writes to the log in real time, the CI system should be able to display the file in real time as well.

On the test side, all it needs to do is to run commands inside tests.yml like this:

shell: ./run_test_suite.sh &> {{ artifacts }}/test.log

On the CI side, it needs some smart file monitoring (btw, BuildBot can do it, so perhaps some code can be borrowed from there).

How exactly do i put that in? It makes the test fail immediately (so fast that they had no chance to actually run):

ASK [standard-test-basic : Execute tests] *************************************
changed: [/home/churchyard/tmp/test_subject.qcow2] => (item={'smoke': {'dir': 'python/smoke', 'run': 'VERSION=3.7 ./venv.sh &> ./artifacts/test.log'}})
changed: [/home/churchyard/tmp/test_subject.qcow2] => (item={'selftest': {'dir': 'python/selftest', 'run': 'VERSION=3.7 X="-x test_socket -x test_asyncgen -x test_asyncio -x test_compile -x test_concurrent_futures -x test_itertools -x test_multiprocessing_fork -x test_multiprocessing_forkserver -x test_shutil -x test_time -x test_multiprocessing_spawn -x test_threading -x test_wsgiref" ./parallel.sh &> ./artifacts/test.log'}})
changed: [/home/churchyard/tmp/test_subject.qcow2] => (item={'findleaks': {'dir': 'python/selftest', 'run': 'VERSION=3.7 X="-x test_socket -x test_asyncgen -x test_asyncio -x test_compile -x test_concurrent_futures -x test_itertools -x test_multiprocessing_fork -x test_multiprocessing_forkserver -x test_shutil -x test_time -x test_multiprocessing_spawn -x test_threading -x test_wsgiref" ./findleaks.sh &> ./artifacts/test.log'}})

TASK [standard-test-basic : Check the results] *********************************
changed: [/home/churchyard/tmp/test_subject.qcow2]

TASK [standard-test-basic : Set role result] ***********************************
ok: [/home/churchyard/tmp/test_subject.qcow2]

TASK [include_role : str-common-final] *****************************************

TASK [str-common-final : Pull out the logs from test environment to test runner] ***
changed: [/home/churchyard/tmp/test_subject.qcow2]

TASK [str-common-final : Report role result] ***********************************
fatal: [/home/churchyard/tmp/test_subject.qcow2]: FAILED! => {
    "msg": [
        "Tests failed: True",
        "Tests msg: FAIL smoke",
        "FAIL selftest",
        "FAIL findleaks",
        ""
    ]
}
    to retry, use: --limit @/home/churchyard/tmp/python3/tests/tests.retry

PLAY RECAP *********************************************************************
/home/churchyard/tmp/test_subject.qcow2 : ok=23   changed=8    unreachable=0    failed=1   
$ cat artifacts/test.log
FAIL smoke
FAIL selftest
FAIL findleaks

It is now a little better, yet still ti seems that the logs are only retrospective.

@churchyard another one to ping and see if things are better now, or if they're still not as clear as you're expecting.

When the tests run, I still cannot see live output. I need to wait until all the tests finish to download the logs from the artifacts.

Is the Jenkins console helpful, or at you looking for something else?

Here's one example that's running as I post this update; I verified it's accessible even without any login provided:

https://jenkins-continuous-infra.apps.ci.centos.org/job/fedora-rawhide-build-pipeline/11905/console

No. It shows me a wall of ansible log, but when it comes to the interesting part, all I see is:

TASK [standard-test-basic : Execute tests] *************************************

:hourglass_flowing_sand: :hourglass_flowing_sand: :hourglass_flowing_sand:

For dozens of minutes or even an hour. There is no way that I know of to see what's going on or to see live log of the tests.

Fair enough - though I don't know of a good way to look inside of ansible execution of a step. @mvadkert @astepano @bgoncalv @msrb any ideas if we could allow the standard test step to be more verbose, even if we expanded the tests into more sub steps maybe?

I don't know if there is anything we can do as long as we use Ansible to execute the test. AFAIK Ansible is only able to show the stdout after the command is run. In our case the command is the script to execute the test case.

Hmm, it would seem there's an open issue in ansible as well trying to get this functionality:

https://github.com/ansible/proposals/issues/92

You can sidestep ansible deficiencies if you recommend that the main log file should be present in $TEST_ARTIFACTS directory (as defined by Standard Test Interface), called main.log (or test.log or whatever), and it should be written in real-time (i.e. the tests would redirect their script output into that file, for each script executed in the ansible script). You can then display the file contents live, during task execution.

Here's an example from now-extinct Taskotron task:
https://pagure.io/taskotron/task-rpmlint/blob/develop/f/tests.yml#_80
https://pagure.io/taskotron/task-rpmlint/blob/develop/f/tests.yml#_85
https://pagure.io/taskotron/task-rpmlint/blob/develop/f/tests.yml#_91

Unless you make that behavior mandatory, it will not be universal. But even when it is just optional, the test authors will quickly adapt, I believe, when they see the benefits.

Login to comment on this ticket.

Metadata