Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

verbose output confusing, as it shows test passed #7

Closed
okken opened this issue Apr 3, 2019 · 13 comments
Closed

verbose output confusing, as it shows test passed #7

okken opened this issue Apr 3, 2019 · 13 comments

Comments

@okken
Copy link

okken commented Apr 3, 2019

The example given in the readme is kinda weird when passed the -v flag.

(subtest) $ pytest -v test_sub_pytest.py  --tb=no
================= test session starts =================
platform darwin -- Python 3.8.0a1, pytest-4.4.0, py-1.8.0, pluggy-0.9.0 -- 
plugins: subtests-0.1.0
collected 1 item                                      

test_sub_pytest.py::test 
test_sub_pytest.py::test PASSED                 [100%]

========= 2 failed, 1 passed in 0.05 seconds ==========

The double ::test is a bit odd.
As is the PASSED.
And, well, with 1 test that has 5 subtests, where does the 2 failed 1 passed come from?
Specifically, the 1 passed?

@jurisbu
Copy link

jurisbu commented Apr 3, 2019

This is indeed misleading. If one has 2 subtests there will be report for 3 tests.

Another thing is how it will work with test reporting stuff like pytest-html and allure-pytest, it seems hairy atm.

@nicoddemus
Copy link
Member

Hi @okken and @jurisbu,

The double ::test is a bit odd.

Strange, I get different results here:

λ pytest .tmp\test_ut.py -v --tb=no
======================== test session starts ========================
platform win32 -- Python 3.7.1, pytest-4.4.0, py-1.8.0, pluggy-0.9.0 -- ...
plugins: subtests-0.1.1.dev4+gea4c7be
collected 1 item

.tmp/test_ut.py::test PASSED                                   [100%]
.tmp/test_ut.py::test FAILED                                   [100%]
.tmp/test_ut.py::test PASSED                                   [100%]
.tmp/test_ut.py::test FAILED                                   [100%]
.tmp/test_ut.py::test PASSED                                   [100%]
.tmp/test_ut.py::test PASSED                                   [100%]

================ 2 failed, 1 passed in 0.04 seconds =================

The 100% bit is indeed a bit weird, perhaps we should not show the percentage at all for subtests?

.tmp/test_ut.py::test PASSED                                   
.tmp/test_ut.py::test FAILED                                   
.tmp/test_ut.py::test PASSED                                   
.tmp/test_ut.py::test FAILED                                   
.tmp/test_ut.py::test PASSED                                   
.tmp/test_ut.py::test PASSED                                   [100%]

e.g, only show the percentage when we reach the end of the test.

And, well, with 1 test that has 5 subtests, where does the 2 failed 1 passed come from?
Specifically, the 1 passed?

I've tried to mimic the output from unittest when running subtests:

import unittest

class T(unittest.TestCase):

    def test_foo(self):
        for i in range(5):
            with self.subTest("custom message", i=i):
                self.assertEqual(i % 2, 0)

if __name__ == "__main__":
    unittest.main()
λ python .tmp\test_ut.py

======================================================================
FAIL: test_foo (__main__.T) [custom message] (i=1)
----------------------------------------------------------------------
Traceback (most recent call last):
  File ".tmp\test_ut.py", line 10, in test_foo
    self.assertEqual(i % 2, 0)
AssertionError: 1 != 0

======================================================================
FAIL: test_foo (__main__.T) [custom message] (i=3)
----------------------------------------------------------------------
Traceback (most recent call last):
  File ".tmp\test_ut.py", line 10, in test_foo
    self.assertEqual(i % 2, 0)
AssertionError: 1 != 0

----------------------------------------------------------------------
Ran 1 test in 0.001s

FAILED (failures=2)

It says above that it executed 1 test, but reported 2 failures. We actually have 5 sub-tests, with 3 of them passing and 2 failures, but the passing sub-tests don't count towards the summary. I followed the same approach to reporting for the subtests fixture, even though I agree it is a bit odd.

Of course we can change the output when running unittest subtests under pytest, or perhaps adopt a different reporting strategy when using subtests fixture?

@bskinn
Copy link

bskinn commented Apr 3, 2019

unittest's method of counting things when subTests are involved is just weird. If pytest-subtests's goal is to try to match unittest's behavior, then it's just gonna be weird too.

IIUC, accurately bookkeeping the subtests is kind of tricky problem: basically, a test runner really can't(?) know a priori how many subtests there will be in a given test function, because subtests might be generated by iteration, and iterables often don't have a known size until runtime, if even then.

Part of the problem also is that the test function itself can actually pass, even if every subtest it contains fails... since execution can reach the end of the function without error, etc. Or, every subtest might pass, but the overall test function could fail, if there are failing asserts in the function that aren't in a subtests.test context.

@nicoddemus
Copy link
Member

@bskinn that's a good assessment of the problem, thanks.

@bskinn
Copy link

bskinn commented Apr 3, 2019

@nicoddemus Sorry I only have diagnosis to offer, and no concrete ideas for addressing it. :-/

@nicoddemus
Copy link
Member

nicoddemus commented Apr 3, 2019

@bskinn No worries, appreciate the contribution already! 👍

@okken your output example only shows:

(subtest) $ pytest -v test_sub_pytest.py  --tb=no
================= test session starts =================
platform darwin -- Python 3.8.0a1, pytest-4.4.0, py-1.8.0, pluggy-0.9.0 -- 
plugins: subtests-0.1.0
collected 1 item                                      

test_sub_pytest.py::test 
test_sub_pytest.py::test PASSED                 [100%]

========= 2 failed, 1 passed in 0.05 seconds ==========

While I get very different results. Can you confirm that you are indeed using the example from the README? I will try later with Python 3.8 to check if I get a different outcome.

@jurisbu
Copy link

jurisbu commented Apr 4, 2019

@nicoddemus This is what I get with subtests-0.2.0

$ pytest -v test_ut.py --tb=no
======================================================== test session starts ========================================================
platform linux -- Python 3.7.2, pytest-4.4.0, py-1.8.0, pluggy-0.9.0 -- 
cachedir: .pytest_cache
rootdir: 
plugins: subtests-0.2.0
collected 1 item                                                                                                                    

test_ut.py::test 
test_ut.py::test PASSED                                                                                                       [100%]

================================================ 2 failed, 1 passed in 0.03 seconds =================================================
$ pip freeze
atomicwrites==1.3.0
attrs==19.1.0
more-itertools==7.0.0
pluggy==0.9.0
py==1.8.0
pytest==4.4.0
pytest-subtests==0.2.0
six==1.12.0

@nicoddemus
Copy link
Member

Indeed, I get the same results on Linux. Weird, no idea why there's such a difference between Linux and Windows here, I'll investigate. Thanks!

@nicoddemus
Copy link
Member

Found the problem: #10. I will finish the PR later and publish a new release.

Thanks everyone!

@okken
Copy link
Author

okken commented Apr 4, 2019

Sorry for the delay, Sounds like it's understood now.

The unittest output is confusing, yes.
However, it does NOT claim that a test passed if a subtest failed.
It doesn't say it failed either, which is definitely weird, but better than saying it passed.
Actually, I think those who implemented subTest in unittest just forgot to decide on an outcome.
It doesn't even use a newline where a result decision should be.
test_foo (test_sub.T) ...

So my opinion should be obvious by now.
Any failure in a test should fail the test.
At the very least, PASSED is wrong.
The notion that PASSED just means there were no asserts outside of the subtests is a very hard thing to explain.
Looks like 0.2.0 of the plugin now reports the test as both passed and failed.
Maybe that's ok?? not sure.

With this:

import unittest

class T(unittest.TestCase):
    def test_foo(self):
        for i in range(3):
            with self.subTest("custom message", i=i):
                self.assertEqual(i % 2, 0)

    def test_pass(self):
        pass

    def test_fail(self):
        assert False, 'fail intentionally'
c:\sub>python -m unittest -v test_sub.py
test_fail (test_sub.T) ... FAIL
test_foo (test_sub.T) ... test_pass (test_sub.T) ... ok

======================================================================
FAIL: test_fail (test_sub.T)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\sub\test_sub.py", line 13, in test_fail
    assert False, 'fail intentionally'
AssertionError: fail intentionally

======================================================================
FAIL: test_foo (test_sub.T) [custom message] (i=1)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\sub\test_sub.py", line 7, in test_foo
    self.assertEqual(i % 2, 0)
AssertionError: 1 != 0

----------------------------------------------------------------------
Ran 3 tests in 0.002s

FAILED (failures=2)

with pytest:

c:\sub>python -m pytest -v test_sub.py
=============================== test session starts ===============================
platform win32 -- Python 3.7.1, pytest-4.4.0, py-1.7.0, pluggy-0.9.0 -- C:\Users\okken\projects\pytest_wlan\venv\Scripts\python.exe
cachedir: .pytest_cache
metadata: {'Python': '3.7.1', 'Platform': 'Windows-10-10.0.17134-SP0', 'Packages': {'pytest': '4.4.0', 'py': '1.7.0', 'pluggy': '0.9.0'}, 'Plugins': {'subtests': '0.2.0''}}
rootdir: c:\sub
plugins: subtests-0.2.0
collected 3 items

test_sub.py::T::test_fail FAILED                                             [ 33%]
test_sub.py::T::test_foo FAILED                                          [ 66%]
test_sub.py::T::test_foo PASSED                                              [ 66%]
test_sub.py::T::test_pass PASSED                                             [100%]

==================================== FAILURES =====================================
___________________________________ T.test_fail ___________________________________

self = <test_sub.T testMethod=test_fail>

    def test_fail(self):
>       assert False, 'fail intentionally'
E       AssertionError: fail intentionally
E       assert False

test_sub.py:13: AssertionError
________________________ T.test_foo [custom message] (i=1) ________________________

self = <test_sub.T testMethod=test_foo>

    def test_foo(self):
        for i in range(3):
            with self.subTest("custom message", i=i):
>               self.assertEqual(i % 2, 0)
E               AssertionError: 1 != 0

test_sub.py:7: AssertionError
======================= 2 failed, 2 passed in 0.07 seconds ========================

@okken
Copy link
Author

okken commented Apr 4, 2019

Took a look at the xml output, with the --junitxml flag, and it also shows 4 tests
<testsuite errors="0" failures="2" name="pytest" skipped="0" tests="4" time="0.046">

But correctly shows 3 testcase blocks.
I think tests with mixed pass/fail subtests are being counted as 2 tests, one passed, one failed.

@okken
Copy link
Author

okken commented Apr 4, 2019

Also, I understand that this is a can-o-worms problem.
I appreciate Bruno working on it, as it will be really cool when it works with minimal surprises.

So, thank you Bruno.

I'll take a look at the code and try to understand it.
Let me (and others) know if there are any areas you'd like help with.

@okken
Copy link
Author

okken commented Apr 4, 2019

One more test case that is interesting.
This file:

import unittest

class T(unittest.TestCase):
    def test_fail(self):
        with self.subTest():
           self.assertEqual(1, 2)

No passing subtests, just one failure. Still shows PASSED.
I would expect FAILED and the bottom line to show 1 failed
Maybe pytest itself is calling pytest_runtest_logreport() at the end and causing an extra test to be counted.

pytest -v test_sub.py
=============================== test session starts ===============================
platform win32 -- Python 3.7.1, pytest-4.4.0, ...
plugins: subtests-0.2.0
collected 1 item

test_sub.py::T::test_fail FAILED                                         [100%]
test_sub.py::T::test_fail PASSED                                             [100%]

==================================== FAILURES =====================================
_____________________________ T.test_fail (<subtest>) _____________________________

self = <test_sub.T testMethod=test_fail>

    def test_fail(self):
        with self.subTest():
>          self.assertEqual(1, 2)
E          AssertionError: 1 != 2

test_sub.py:6: AssertionError
======================= 1 failed, 1 passed in 0.05 seconds ========================

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants