add test.report_fragment()

Allow enriching the junit output with arbitrary subtasks within a test.

The current aim is, for handover tests, to not just show that a test
failed, but to show exactly which steps worked and which didn't, e.g.:

 handover.py/01_bts0_started PASSED
 handover.py/02.1_ms0_attach PASSED
 handover.py/02.2_ms1_attach PASSED
 handover.py/02.3_subscribed_in_msc PASSED
 handover.py/03_call_established PASSED
 handover.py/04.1_bts1_started FAILED

In this case it is immediately obvious from looking at the jenkins
results analyzer that bts1 is the cause of the test failure, and it is
visible which parts of the test are flaky, over time.

First user Will be the upcoming handover_2G suite, in
I0b2671304165a1aaae2b386af46fbd8b098e3bd8.

Change-Id: I4ca9100b6f8db24d1f7e0a09b3b7ba88b8ae3b59
This commit is contained in:
Neels Hofmeyr 2020-12-02 09:39:01 +01:00
parent 12ed99628c
commit 9596b210c5
6 changed files with 174 additions and 12 deletions

View File

@ -168,15 +168,67 @@ tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py]
---------------------------------------------------------------------
trial test_suite PASS
---------------------------------------------------------------------
PASS: test_suite (pass: 1, skip: 7)
PASS: test_suite (pass: 1, skip: 8)
pass: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py
skip: test_suite_params.py
skip: test_timeout.py
- run report fragment test
---------------------------------------------------------------------
trial test_suite
---------------------------------------------------------------------
----------------------------------------------
trial test_suite test_report_fragment.py
----------------------------------------------
tst test_report_fragment.py:[LINENR]: a step in the first fragment [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: ----- Report fragment: test_suite/test_report_fragment.py/fragment1: pass (N.Ns) [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: a step in the second fragment [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: ----- Report fragment: test_suite/test_report_fragment.py/fragment2: pass (N.Ns) [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: a step in the third fragment [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: ----- Report fragment: test_suite/test_report_fragment.py/fragment3: FAIL (N.Ns) [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: ERR: Exception: failure in the third fragment [test_suite↪test_report_fragment.py:[LINENR]]
tst test_report_fragment.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_report_fragment.py:[LINENR]]
---------------------------------------------------------------------
trial test_suite FAIL
---------------------------------------------------------------------
FAIL: test_suite (fail: 1, skip: 8)
skip: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
FAIL: test_report_fragment.py (N.N sec) Exception: failure in the third fragment
skip: test_suite_params.py
skip: test_timeout.py
################################### junit XML:
<testsuite disabled="8" errors="0" failures="2" hostname="localhost" name="test_suite" skipped="8" tests="9" time="[VAL]" timestamp="[TIMESTAMP]"><testcase classname="test_suite" name="hello_world.py" time="[VAL]"><skipped /><system-out>
----------------------------------------------
trial test_suite hello_world.py
----------------------------------------------
[TIMESTAMP] tst hello_world.py:[LINENR]: hello world
[TIMESTAMP] tst hello_world.py:[LINENR]: I am 'test_suite' / 'hello_world.py'
[TIMESTAMP] tst hello_world.py:[LINENR]: one
two
three
[TIMESTAMP] tst hello_world.py:[LINENR] Test passed (N.N sec)
</system-out></testcase><testcase classname="test_suite" name="mo_mt_sms.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="mo_sms.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="test_error.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="test_fail.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="test_fail_raise.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="test_report_fragment.py" time="[VAL]"><failure type="Exception">failure in the third fragment</failure><system-err>[BACKTRACE]
raise Exception('failure in the third fragment')
Exception: failure in the third fragment
</system-out></testcase><testcase classname="test_suite" name="test_suite_params.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase><testcase classname="test_suite" name="test_timeout.py" time="[VAL]"><skipped /><system-out>test log file not available</system-out></testcase></testsuite>
###################################
- a test with an error
@ -193,13 +245,14 @@ tst test_error.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_error.py:[
---------------------------------------------------------------------
trial test_suite FAIL
---------------------------------------------------------------------
FAIL: test_suite (fail: 1, skip: 7)
FAIL: test_suite (fail: 1, skip: 8)
skip: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
FAIL: test_error.py (N.N sec) AssertionError: test_error.py:[LINENR]: assert False
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py (N.N sec)
skip: test_suite_params.py
skip: test_timeout.py
@ -218,13 +271,14 @@ tst test_fail.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_fail.py:[LI
---------------------------------------------------------------------
trial test_suite FAIL
---------------------------------------------------------------------
FAIL: test_suite (fail: 1, skip: 7)
FAIL: test_suite (fail: 1, skip: 8)
skip: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py (N.N sec)
FAIL: test_fail.py (N.N sec) EpicFail: This failure is expected
skip: test_fail_raise.py
skip: test_report_fragment.py (N.N sec)
skip: test_suite_params.py
skip: test_timeout.py
@ -242,13 +296,14 @@ tst test_fail_raise.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_fail_
---------------------------------------------------------------------
trial test_suite FAIL
---------------------------------------------------------------------
FAIL: test_suite (fail: 1, skip: 7)
FAIL: test_suite (fail: 1, skip: 8)
skip: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py (N.N sec)
skip: test_fail.py (N.N sec)
FAIL: test_fail_raise.py (N.N sec) ExpectedFail: This failure is expected
skip: test_report_fragment.py (N.N sec)
skip: test_suite_params.py
skip: test_timeout.py
- test with half empty scenario
@ -397,13 +452,14 @@ tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py]
---------------------------------------------------------------------
trial test_suite PASS
---------------------------------------------------------------------
PASS: test_suite (pass: 1, skip: 7)
PASS: test_suite (pass: 1, skip: 8)
pass: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py
skip: test_suite_params.py
skip: test_timeout.py
- test with scenario
@ -552,13 +608,14 @@ tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py]
---------------------------------------------------------------------
trial test_suite PASS
---------------------------------------------------------------------
PASS: test_suite (pass: 1, skip: 7)
PASS: test_suite (pass: 1, skip: 8)
pass: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py
skip: test_suite_params.py
skip: test_timeout.py
- test with scenario and modifiers
@ -753,13 +810,14 @@ tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py]
---------------------------------------------------------------------
trial test_suite PASS
---------------------------------------------------------------------
PASS: test_suite (pass: 1, skip: 7)
PASS: test_suite (pass: 1, skip: 8)
pass: hello_world.py (N.N sec)
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py
skip: test_suite_params.py
skip: test_timeout.py
- test with suite-specific config
@ -962,13 +1020,14 @@ tst test_timeout.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_timeout.
---------------------------------------------------------------------
trial test_suite FAIL
---------------------------------------------------------------------
FAIL: test_suite (fail: 1, pass: 1, skip: 6)
FAIL: test_suite (fail: 1, pass: 1, skip: 7)
skip: hello_world.py
skip: mo_mt_sms.py
skip: mo_sms.py
skip: test_error.py
skip: test_fail.py
skip: test_fail_raise.py
skip: test_report_fragment.py
pass: test_suite_params.py (N.N sec)
FAIL: test_timeout.py (N.N sec) Error: test_timeout.py:[LINENR] Test Timeout triggered: 1 seconds elapsed [test_suite↪test_timeout.py:[LINENR]↪test_timeout.py]
- test with template overlay

View File

@ -1,6 +1,11 @@
/[^ ]*/selftest/ [PATH]/selftest/
\.py:[0-9]* .py:[LINENR]
\([0-9.]+ sec\) (N.N sec)
\([0-9.]+s\) (N.Ns)
{combining_scenarios='resources', scenario='foo'}:.* {combining_scenarios='resources', scenario='foo'}: [RESOURCE_DICT]
test_suite-[0-9]*-[0-9]* test_suite-[ID_NUM]-[ID_NUM]
suiteC-[0-9]*-[0-9]* suiteC-[ID_NUM]-[ID_NUM]
line [0-9]+ line [LINENR]
[0-9][0-9]:[0-9][0-9]:[0-9][0-9]\.[0-9]+ [TIMESTAMP]
time="[0-9]+" time="[VAL]"
timestamp="[^"]+" timestamp="[TIMESTAMP]"

View File

@ -3,6 +3,7 @@ import os
import sys
import _prep
import shutil
import re
from osmo_gsm_tester.core import log
from osmo_gsm_tester.core import config
from osmo_gsm_tester.core import util
@ -11,6 +12,8 @@ from osmo_gsm_tester.core import scenario
from osmo_gsm_tester.core import suite
from osmo_gsm_tester.core.schema import generate_schemas, get_all_schema
import xml.etree.ElementTree as et
config.override_conf = os.path.join(os.path.dirname(sys.argv[0]), 'paths.conf')
example_trial_dir = os.path.join('test_trial_tmp')
@ -51,6 +54,15 @@ s = suite.SuiteRun(trial, 'test_suite', s_def)
results = s.run_tests('hello_world.py')
print(report.suite_to_text(s))
print('- run report fragment test')
results = s.run_tests('test_report_fragment.py')
print(report.suite_to_text(s))
xml = et.tostring(report.suite_to_junit(s)).decode('utf-8')
xml = re.sub('Traceback.*raise', '[BACKTRACE]\nraise', xml, flags=re.M + re.DOTALL)
print('\n\n################################### junit XML:\n'
+ xml
+ '\n###################################\n\n')
log.style_change(src=True)
#log.style_change(trace=True)
print('\n- a test with an error')

View File

@ -0,0 +1,11 @@
from osmo_gsm_tester.testenv import *
with test.report_fragment('fragment1'):
print('a step in the first fragment')
with test.report_fragment('fragment2'):
print('a step in the second fragment')
with test.report_fragment('fragment3'):
print('a step in the third fragment')
raise Exception('failure in the third fragment')

View File

@ -132,14 +132,37 @@ def suite_to_junit(suite):
testsuite.set('time', str(math.ceil(suite.duration)))
testsuite.set('tests', str(len(suite.tests)))
passed, skipped, failed, errors = suite.count_test_results()
testsuite.set('errors', str(errors))
testsuite.set('failures', str(failed))
testsuite.set('skipped', str(skipped))
testsuite.set('disabled', str(skipped))
for suite_test in suite.tests:
testcase = test_to_junit(suite_test)
testcase.set('classname', suite.name())
testsuite.append(testcase)
for report_fragment in suite_test.report_fragments:
full_name = '%s/%s' % (suite_test.name(), report_fragment.name)
el = et.Element('testcase')
el.set('name', full_name)
el.set('time', str(math.ceil(report_fragment.duration)))
if report_fragment.result == test.Test.SKIP:
et.SubElement(el, 'skipped')
skipped += 1
elif report_fragment.result == test.Test.FAIL:
failure = et.SubElement(el, 'failure')
failure.set('type', suite_test.fail_type or 'failure')
failed += 1
elif report_fragment.result != test.Test.PASS:
error = et.SubElement(el, 'error')
error.text = 'could not run'
errors += 1
if report_fragment.output:
sout = et.SubElement(el, 'system-out')
sout.text = escape_xml_invalid_characters(report_fragment.output)
testsuite.append(el)
testsuite.set('errors', str(errors))
testsuite.set('failures', str(failed))
testsuite.set('skipped', str(skipped))
testsuite.set('disabled', str(skipped))
return testsuite
def test_to_junit(t):

View File

@ -43,6 +43,7 @@ class Test(log.Origin):
self._config_test_specific = config_test_specific
self.path = os.path.join(self.suite_run.definition.suite_dir, self.basename)
self.status = Test.UNKNOWN
self.report_fragments = []
self.start_timestamp = 0
self.duration = 0
self.fail_type = None
@ -183,4 +184,55 @@ class Test(log.Origin):
return ''
return lt.get_output(since_mark)
def report_fragment(self, name, result=None, **kwargs):
return Test.ReportFragment(parent_test=self, name=name, result=result, **kwargs)
class ReportFragment:
'''Add additional test results in junit XML.
Convenient method that includes a test log:
with test.report_fragment('foo'):
do_test_steps()
Or manually add a report fragment directly:
test.report_fragment('foo', result = test.PASS if worked else test.FAIL)
'''
def __init__(self, parent_test, name, result=None, output=None, since_mark=None, start_time=0.0):
self.parent_test = parent_test
self.name = name
self.result = Test.UNKNOWN
self.duration = 0.0
self.output = output
self.start_time = start_time
self.log_mark = since_mark
assert name not in (x.name for x in self.parent_test.report_fragments)
self.parent_test.report_fragments.append(self)
if result is not None:
self.got_result(result)
def __str__(self):
return '%s/%s/%s: %s (%.1fs)' % (self.parent_test.suite_run.name(),
self.parent_test.name(), self.name, self.result, self.duration)
def __enter__(self):
self.start_time = self.parent_test.elapsed_time()
self.log_mark = self.parent_test.get_log_mark()
def __exit__(self, *exc_info):
self.got_result(self.parent_test.PASS if exc_info[0] is None else self.parent_test.FAIL,
exc_info=exc_info)
def got_result(self, result, exc_info=None):
self.result = result
self.duration = self.parent_test.elapsed_time() - self.start_time
if self.log_mark is not None and self.output is None:
self.output = self.parent_test.get_log_output(since_mark=self.log_mark)
if exc_info is not None and exc_info[0] is not None:
o = []
if self.output:
o.append(self.output)
o.extend(traceback.format_exception(*exc_info))
self.output = '\n'.join(o)
self.parent_test.log('----- Report fragment:', self)
# vim: expandtab tabstop=4 shiftwidth=4