Unit tests broke with recent commit

Bug #1130146 reported by Hans Lindgren
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Critical
Daniel Berrange

Bug Description

A recent change, Add libvirt XML schema support for resource tuning parameters, commit 082c4ca417705975b8ef3672ce6ed40661d0f019 broke the unit tests, resulting in a lot of test not being run, while still reporting success.

See http://lists.openstack.org/pipermail/openstack-dev/2013-February/005810.html for the details.

Hans Lindgren (hanlind)
Changed in nova:
assignee: Hans Lindgren (hanlind) → nobody
Sean Dague (sdague)
Changed in nova:
status: New → Confirmed
Changed in nova:
milestone: none → grizzly-3
Revision history for this message
Sean Dague (sdague) wrote :

Definitely confirmed with master, you'll see the following:

Exception in thread Thread-6:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 505, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/testtools/testsuite.py", line 102, in _run_test
    test.run(process_result)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/subunit/__init__.py", line 1196, in run
    protocol.lineReceived(line)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/subunit/__init__.py", line 573, in lineReceived
    self._state.lineReceived(line)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/subunit/__init__.py", line 410, in lineReceived
    self.details_parser.lineReceived(line)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/subunit/details.py", line 119, in lineReceived
    self._parse_state(line)
  File "/home/sdague/code/openstack/nova/.venv/local/lib/python2.7/site-packages/subunit/details.py", line 91, in _look_for_content
    raise ValueError("Invalid MIME type %r" % value)
ValueError: Invalid MIME type u'2013-02-19 15:46:03.877518Z'

And it looks like it drops a whole process full of tests (total count 4699 on master), but continutes to pass things

Sean Dague (sdague)
Changed in nova:
assignee: nobody → Robert Collins (lifeless)
Revision history for this message
Kevin L. Mitchell (klmitch) wrote :

Are we sure this is a bug in nova? The traceback never references the test suite itself, only subunit, and I cannot see anything in the referenced review which could introduce this error. I don't doubt the analysis is correct, I'm just asking for the evidence that it is the review's fault…

Revision history for this message
Hans Lindgren (hanlind) wrote :

At least it gets triggered by this change. If I revert this change on current trunk, everything starts working again.

Furthermore, I nailed it down to the test classes that this review touches is indeed the ones that triggers the exception, namely LibvirtConfigGuestInterfaceTest and LibvirtConfigGuestTest.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/22334

Changed in nova:
assignee: Robert Collins (lifeless) → Russell Bryant (russellb)
status: Confirmed → In Progress
Revision history for this message
Daniel Berrange (berrange) wrote :

It looks like there are probably two bugs in one here - first the test suite is failing for some reason due to this Nova changeset. The cause of that failure is then getting masked by some problem with subunit processing the output of the failing test.

Sean Dague (sdague)
affects: nova → testrepository
Changed in testrepository:
milestone: grizzly-3 → none
status: In Progress → Confirmed
Changed in nova:
status: New → Confirmed
importance: Undecided → Critical
assignee: nobody → Russell Bryant (russellb)
milestone: none → grizzly-3
Revision history for this message
Clark Boylan (cboylan) wrote :

https://bugs.launchpad.net/subunit/+bug/1130280 has been submitted against subunit requesting more graceful error handling of unexpected bits in the subunit stream.

Revision history for this message
Daniel Berrange (berrange) wrote :

It looks like the root cause is something in the nova/tests/matcher.py code - when the XMLMatches class detects an error whatever it prints is breaking subunit. This can be trivially demonstrated by putting an intentional typo into any of the test_libvirt_config.py XML strings.

Revision history for this message
Clark Boylan (cboylan) wrote :

Running `OS_STDOUT_CAPTURE=1 OS_STDERR_CAPTURE=1 OS_TEST_TIMEOUT=60 ${PYTHON:-python} -m subunit.run nova.tests.test_libvirt_config` ends with:

time: 2013-02-19 18:28:00.481044Z
test: nova.tests.test_libvirt_config.LibvirtConfigGuestInterfaceTest.test_config_bridge
time: 2013-02-19 18:28:00.501911Z
failure: nova.tests.test_libvirt_config.LibvirtConfigGuestInterfaceTest.test_config_bridge [ multipart
time: 2013-02-19 18:28:00.502121Z
2013-02-19 18:28:00.502 9031 CRITICAL nova [-] 'str' object has no attribute 'content_type'

This last line begins with a timestamp and is not expected by the subunit stream protocol. test_config_bridge is one of the places this is breaking.

Revision history for this message
Kevin L. Mitchell (klmitch) wrote :

Hmmm…there are no 'print' statements in XMLMatches. My best guess, though, is that, when formatting the mismatch message, a newline is being included, and this is then being misformatted by subunit when sending the message upstream. Seems to me that the proper fix will be stripping carriage returns and newlines (or converting them to their escape sequences). I can't see, though, where a newline could be included; in both attribute value mismatches and text value mismatches, I use a %r to render text possibly containing a newline…

Revision history for this message
Sean Dague (sdague) wrote :

On the nova side cburgess and I have tracked the failure down into

nova.tests.matchers.XMLMatcher()

Something about that is incorrectly interacting with asserThat()

Revision history for this message
Sean Dague (sdague) wrote :

You can replicate this with getting "1b9b66ba210c1dd886a95d79e5621e13fb64aa3a"

and running

./run_tests.sh nova.tests.test_libvirt_config

That should return a total of 48 tests. But instead you'll see some of these traces, and 44 or 43 tests passed (0 fails).

Revision history for this message
Sean Dague (sdague) wrote :

The place where this fails in testr is testsuite.py L100

    def _run_test(self, test, process_result, queue):
        try:
            test.run(process_result)
        finally:
            queue.put(test)

It seems that under these fail conditions the test.run(process_result) leaves us with a test which is invalid enough that it just gets silently dropped later. That's hugely dangerous.

If test isn't queueable after all is said and done, we need to insert an explicit fail so we at least know that things went horribly wrong and we don't pass when there should be failures.

Revision history for this message
Sean Dague (sdague) wrote :

The type that gets returned that causes the fail is an XMLTagMismatch object

Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

Fix proposed to branch: master
Review: https://review.openstack.org/22349

Changed in nova:
assignee: Russell Bryant (russellb) → Daniel Berrange (berrange)
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

Fix proposed to branch: master
Review: https://review.openstack.org/22350

Revision history for this message
Daniel Berrange (berrange) wrote :

The nova.tests.matchers.XMLMismatch class implements the get_details() method returning a dictionary with the expect
and actual XML output. It is returning a string values, but the testtools code requires that the dictionary values are instances of the testtools.content.Content object. To quote the 'get_details' docs on testtools.matchers.Mismatch

:return: a dict mapping names to Content objects. name is a string to
name the detail, and the Content object is the detail to add
to the result. For more information see the API to which items from
this dict are passed testtools.TestCase.addDetail.

I've posted https://review.openstack.org/#/c/22350/ to fix this

Revision history for this message
Robert Collins (lifeless) wrote :

https://bugs.launchpad.net/subunit/+bug/1130280 tracks the subunit parsing side of this; I don't believe there are any code changes for testrepository itself, so I'm going to remove that task. I will file a separate bug for testtools for the failure to notify of the processing error.

no longer affects: testrepository
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/22349
Committed: http://github.com/openstack/nova/commit/a89daffeb99956ab38c0b6c1144803c5b3e851f9
Submitter: Jenkins
Branch: master

commit a89daffeb99956ab38c0b6c1144803c5b3e851f9
Author: Daniel P. Berrange <email address hidden>
Date: Tue Feb 19 19:54:55 2013 +0000

    Fix XML config tests for disk/net/cpu tuning

    Due to a bug in the XML matching code, some XML formatting
    problems related to disk/net/cpu tuning were not flaged as
    errors. The problems were all simply ordering of the elements.
    This patch also fixes some indentation problems at the same time

    Fixes bug #1130146
    Change-Id: Iee392ed823002b8231b33c27b487c2538b2dc8cd
    Signed-off-by: Daniel P. Berrange <email address hidden>

Changed in nova:
status: In Progress → Fix Committed
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

Reviewed: https://review.openstack.org/22350
Committed: http://github.com/openstack/nova/commit/a7f72a59ba3214f19c7bd66a7ef465ecc22794dd
Submitter: Jenkins
Branch: master

commit a7f72a59ba3214f19c7bd66a7ef465ecc22794dd
Author: Daniel P. Berrange <email address hidden>
Date: Tue Feb 19 19:39:55 2013 +0000

    Fix XMLMatcher error reporting

    The nova.tests.matchers.XMLMismatch class implements the
    get_details() method returning a dictionary with the expect
    and actual XML output. It is returning a string values, but
    the testtools code requires that the dictionary values are
    instances of the testtools.content.Content object.

    To quote the 'get_details' docs on testtools.matchers.Mismatch

         :return: a dict mapping names to Content objects. name is a string to
             name the detail, and the Content object is the detail to add
             to the result. For more information see the API to which items from
             this dict are passed testtools.TestCase.addDetail.

    Related bug #1130146
    Change-Id: I75ec07d8b34b04c7b8009229fda49b344ed13bec
    Signed-off-by: Daniel P. Berrange <email address hidden>

Thierry Carrez (ttx)
Changed in nova:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: grizzly-3 → 2013.1
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.