openprov / interop-test-harness

Interoperability test harness for the Southampton Provenance Suite.
MIT License
1 stars 2 forks source link

Travis CI terminates test run if log file grows larger than 4MB #12

Open mikej888 opened 8 years ago

mikej888 commented 8 years ago

When running a set of tests, a Travis CI test run can terminate with the following warning, if the log grows beyond 4MB:

The log length has exceeded the limit of 4 Megabytes (this usually means that test suite is raising the same exception over and over).

See, for example log.txt.

This could be an issue for the interoperability test harness which now run 7500+ tests. The problem arises from the outputs produced by nosetests.

nosetests supports two flags controlling test output:

To see the difference between these, compare and contrast their use with a simple Python test class that has one test that passes and one that fails:

import unittest

class FilesTestCase(unittest.TestCase):

  def test_one(self):
     print("Test one prints something");
     self.assertEqual(1, 1, msg="Test one assertEqual failed!")

  def test_two(self):
    print("Test two prints something else");
    self.assertEqual(2, 1, msg="Test two assertEqual failed!")
$ nosetests test_verbosity.py 
.F
======================================================================
FAIL: test_two (test_verbosity.FilesTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!")
AssertionError: Test two assertEqual failed!
-------------------- >> begin captured stdout << ---------------------
Test two prints something else

--------------------- >> end captured stdout << ----------------------

----------------------------------------------------------------------
Ran 2 tests in 0.001s

FAILED (failures=1)
$ nosetests -v test_verbosity.py 
test_one (test_verbosity.FilesTestCase) ... ok
test_two (test_verbosity.FilesTestCase) ... FAIL

======================================================================
FAIL: test_two (test_verbosity.FilesTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!")
AssertionError: Test two assertEqual failed!
-------------------- >> begin captured stdout << ---------------------
Test two prints something else

--------------------- >> end captured stdout << ----------------------

----------------------------------------------------------------------
Ran 2 tests in 0.002s

FAILED (failures=1)
$ nosetests --nocapture test_verbosity.py 
Test one prints something
.Test two prints something else
F
======================================================================
FAIL: test_two (test_verbosity.FilesTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!")
AssertionError: Test two assertEqual failed!

----------------------------------------------------------------------
Ran 2 tests in 0.001s

FAILED (failures=1)
$ nosetests -v --nocapture test_verbosity.py 
test_one (test_verbosity.FilesTestCase) ... Test one prints something
ok
test_two (test_verbosity.FilesTestCase) ... Test two prints something else
FAIL

======================================================================
FAIL: test_two (test_verbosity.FilesTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!")
AssertionError: Test two assertEqual failed!

----------------------------------------------------------------------
Ran 2 tests in 0.001s

FAILED (failures=1)

nosetests test report (the content from ===== onwards) is printed to the standard error stream.

At present, the test jobs are run as follows:

nosetests --nocapture -v ...

If many of the interoperability tests fail and/or the tests print lots of information (e.g. ProvToolbox provconvert, when used to compare documents, prints information to standard output on their differences) then this can cause the test output to quickly balloon. This can be the case even if both -v and --nocapture are omitted.

The use of HTML reporting (#8) (using nose-htmloutput and nose-html-reporting) does not avert this, since the HTML report is generated in addition to the nose test report.

One solution is to redirect the standard error stream to a file,

$ nosetests -v test_verbosity.py > test_report.txt 2>&1
$ more test_report.txt 
test_one (test_verbosity.FilesTestCase) ... ok
test_two (test_verbosity.FilesTestCase) ... FAIL

=============================================================
=========
FAIL: test_two (test_verbosity.FilesTestCase)
-------------------------------------------------------------
---------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, 
in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!"
)
nose.proxy.AssertionError: 2 != 1 : Test two assertEqual fail
ed!
-------------------- >> begin captured stdout << ------------
---------
Test two prints something else

--------------------- >> end captured stdout << -------------
---------

-------------------------------------------------------------
---------
Ran 2 tests in 0.002s

FAILED (failures=1)

Adopting this solution would incur the need to push the test report file to a place where it could be browsed further e.g. see #8 and using Uploading Artifacts on Travis CI.

Note that I tried this in conjunction with --nocapture too but the standard output printed while tests are running appears after the nosetests test report:

$ more test_report.txt 
test_one (test_verbosity.FilesTestCase) ... ok
test_two (test_verbosity.FilesTestCase) ... FAIL

=============================================================
=========
FAIL: test_two (test_verbosity.FilesTestCase)
-------------------------------------------------------------
---------
Traceback (most recent call last):
  File "/disk/ssi-dev0/home/mjj/test_verbosity.py", line 11, 
in test_two
    self.assertEqual(2, 1, msg="Test two assertEqual failed!"
)
AssertionError: 2 != 1 : Test two assertEqual failed!

-------------------------------------------------------------
---------
Ran 2 tests in 0.001s

FAILED (failures=1)
Test one prints something
Test two prints something else

But, arguably, --nocapture isn't so useful as it isn't necessary to capture standard output from all tests, only those that fail, which is done regardless.

Another option to reducing the overall test output is to partition up the tests into smaller jobs (e.g. using the Travis build matrix for parallelisation as described in #9)