test failure output is duplicated/triplicated

[Richard Jones]

When running "tox -e py27" in the oslo.middleware project, and forcing one of the tests to fail, the following is observed:

======================================================================
FAIL: tests.test_cors.CORSMiddlewareTest.test_add_headers
tags: worker-0
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/richard/src/openstack/oslo.middleware/tests/test_cors.py", line 45, in test_add_headers
    FAIL
NameError: global name 'FAIL' is not defined
Traceback (most recent call last):
_StringException: Empty attachments:
  stderr
  stdout

Traceback (most recent call last):
  File "/Users/richard/src/openstack/oslo.middleware/tests/test_cors.py", line 45, in test_add_headers
    FAIL
NameError: global name 'FAIL' is not defined

Traceback (most recent call last):
_StringException: Empty attachments:
  stderr
  stdout

Traceback (most recent call last):
  File "/Users/richard/src/openstack/oslo.middleware/tests/test_cors.py", line 45, in test_add_headers
    FAIL
NameError: global name 'FAIL' is not defined
Ran 18 tests in 0.033s (-0.003s)
FAILED (id=86, failures=1 (+1))
error: testr failed (1)
ERROR: InvocationError: '/Users/richard/src/openstack/oslo.middleware/.tox/py27/bin/python setup.py testr --slowest --testr-args='

Also, the "Traceback..._StringException..." parts of the ouput are just noise as far as I can tell.

[Dan Smith (danms)]

Note that this also affects the openstack-nova project

[Robert Collins (lifeless)]

Does this happen in a vanilla test suite? I know there are a bunch of adapters in oslo that play around with stdout etc that might interact to cause this.

[Matthew Treinish (treinish)]

Here are 2 simple ways to reproduce the issue:

http://paste.openstack.org/show/166475/

and

http://paste.openstack.org/show/166477/

[Clark Boylan (cboylan)]

I think the logging fixture uses the StringStream fixture under the hood and just making a StringStream fixture appears to be sufficient to create the behavior.

[Robert Collins (lifeless)]

Thanks, I shall investigate.

[Robert Collins (lifeless)]

Wow two very different reproducers. The first one works with subunit.run, eliminating testrepository as a cause.

[Robert Collins (lifeless)]

Ug well thats special. Empty pythonlogging attachment is triggering a TypeError in the subunit status -> bytes code, and thats caught by the fallback code for APIs in testtools, triggering a conversion to to a pretend exception. This explains 2 copies.

[Robert Collins (lifeless)]

The conversion then fails identically, giving:
"TypeError: "cannot concatenate 'str' and 'NoneType' objects""

That then bubbles up to a second level of fallback code explaining the third copy.

[Robert Collins (lifeless)]

bug is in this code in testtools:
1344 file_bytes = None
1345 for next_bytes in content.iter_bytes():
1346 if file_bytes is not None:
(Pdb)
1347 self.status(file_name=name, file_bytes=file_bytes,
1348 mime_type=mime_type, test_id=test_id, timestamp=now)
1349 file_bytes = next_bytes
1350 self.status(file_name=name, file_bytes=file_bytes, eof=True,
1351 -> mime_type=mime_type, test_id=test_id, timestamp=now)

[Robert Collins (lifeless)]

https://github.com/testing-cabal/testtools/pull/131