From cd8fa2fe74d6785271409aacd1d3d68d863e47f7 Mon Sep 17 00:00:00 2001 From: Chris Johns Date: Mon, 7 Sep 2020 10:05:19 +1000 Subject: tester: Add support for test-too-long - A test that loops generating output did not timeout. Monitor the the session time and set a maximum test period. --- tester/rt/config.py | 45 +++++++---- tester/rt/exe.py | 172 ++++++++++++++++++++++++++++++++++++++++ tester/rt/gdb.py | 117 ++++++++++++++++++++------- tester/rt/report.py | 28 ++++++- tester/rt/test.py | 6 +- tester/rt/tftp.py | 33 ++++++-- tester/rtems/testing/testing.mc | 3 +- tester/wscript | 1 + 8 files changed, 348 insertions(+), 57 deletions(-) create mode 100644 tester/rt/exe.py diff --git a/tester/rt/config.py b/tester/rt/config.py index ee639e9..bc9263a 100644 --- a/tester/rt/config.py +++ b/tester/rt/config.py @@ -1,6 +1,6 @@ # # RTEMS Tools Project (http://www.rtems.org/) -# Copyright 2013-2017 Chris Johns (chrisj@rtems.org) +# Copyright 2013-2020 Chris Johns (chrisj@rtems.org) # All rights reserved. # # This file is part of the RTEMS Tools package in 'rtems-tools'. @@ -49,6 +49,7 @@ from rtemstoolkit import path from rtemstoolkit import stacktraces import console +import exe import gdb import tftp @@ -78,6 +79,7 @@ class file(config.file): self.report = report self.name = name self.timedout = False + self.test_too_long = False self.test_started = False self.kill_good = False self.kill_on_end = False @@ -102,6 +104,12 @@ class file(config.file): self._unlock() self.capture('*** TIMEOUT TIMEOUT') + def _test_too_long(self): + self._lock() + self.test_too_long = True + self._unlock() + self.capture('*** TEST TOO LONG') + def _ok_kill(self): self._lock() self.kill_good = True @@ -219,22 +227,20 @@ class file(config.file): else: raise error.general(self._name_line_msg('invalid console type')) - def _dir_execute(self, data, total, index, exe, bsp_arch, bsp): - self.process = execute.execute(output = self.capture) - if self.console: - self.console.open() + def _dir_execute(self, data, total, index, rexe, bsp_arch, bsp): + self.process = exe.exe(bsp_arch, bsp, trace = self.exe_trace('exe')) if not self.in_error: - self.capture_console('run: %s' % (' '.join(data))) + if self.console: + self.console.open() if not self.opts.dry_run(): - ec, proc = self.process.open(data, - timeout = (int(self.expand('%{timeout}')), - self._timeout)) - self._lock() - if not (self.kill_good or self.defined('exe_ignore_ret')) and ec > 0: - self._error('execute failed: %s: exit-code:%d' % (' '.join(data), ec)) - elif self.timedout: - self.process.kill() - self._unlock() + self.process.open(data, + ignore_exit_code = self.defined('exe_ignore_ret'), + output = self.capture, + console = self.capture_console, + timeout = (int(self.expand('%{timeout}')), + int(self.expand('%{max_test_period}')), + self._timeout, + self._test_too_long)) if self.console: self.console.close() @@ -255,7 +261,10 @@ class file(config.file): script = script, output = self.capture, gdb_console = self.capture_console, - timeout = int(self.expand('%{timeout}'))) + timeout = (int(self.expand('%{timeout}')), + int(self.expand('%{max_test_period}')), + self._timeout, + self._test_too_long)) if self.console: self.console.close() @@ -278,7 +287,9 @@ class file(config.file): output_length = self._output_length, console = self.capture_console, timeout = (int(self.expand('%{timeout}')), - self._timeout)) + int(self.expand('%{max_test_period}')), + self._timeout, + self._test_too_long)) if self.console: self.console.close() diff --git a/tester/rt/exe.py b/tester/rt/exe.py new file mode 100644 index 0000000..5655073 --- /dev/null +++ b/tester/rt/exe.py @@ -0,0 +1,172 @@ +# SPDX-License-Identifier: BSD-2-Clause +'''Executable test target.''' + +# Copyright (C) 2013-2020 Chris Johns (chrisj@rtems.org) +# +# Redistribution and use in source and binary forms, with or without +# modification, are permitted provided that the following conditions +# are met: +# 1. Redistributions of source code must retain the above copyright +# notice, this list of conditions and the following disclaimer. +# 2. Redistributions in binary form must reproduce the above copyright +# notice, this list of conditions and the following disclaimer in the +# documentation and/or other materials provided with the distribution. +# +# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" +# AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE +# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE +# ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE +# LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR +# CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF +# SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS +# INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN +# CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) +# ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE +# POSSIBILITY OF SUCH DAMAGE. + +from __future__ import print_function + +import datetime +import os +import threading +import time + +from rtemstoolkit import execute + + +class exe(object): + '''RTEMS Testing EXE base.''' + + # pylint: disable=useless-object-inheritance + # pylint: disable=too-many-instance-attributes + + def __init__(self, bsp_arch, bsp, trace=False): + self.trace = trace + self.lock_trace = False + self.lock_locked = None + self.lock = threading.RLock() + self.bsp = bsp + self.bsp_arch = bsp_arch + self.output = None + self.output_length = 0 + self.process = None + self.ecode = None + self.output = None + self.output_buffer = '' + self.console = None + self.timeout = None + self.test_too_long = None + self.kill_good = True + + def _lock(self, msg): + if self.lock_trace: + print('|[ LOCK:%s ]|' % (msg)) + self.lock_locked = datetime.datetime.now() + self.lock.acquire() + + def _unlock(self, msg): + if self.lock_trace: + period = datetime.datetime.now() - self.lock_locked + print('|] UNLOCK:%s [| : %s' % (msg, period)) + self.lock.release() + + def _capture(self, text): + self._lock('_capture') + self.output_length += len(text) + self._unlock('_capture') + if self.output is not None: + self.output(text) + + def _timeout(self): + self._kill() + if self.timeout is not None: + self.timeout() + + def _test_too_long(self): + self._kill() + if self.test_too_long is not None: + self.test_too_long() + + def _kill(self): + self._lock('_kill') + self.kill_good = True + self._unlock('_kill') + if self.process: + # pylint: disable=bare-except + try: + self.process.kill() + except: + pass + self.process = None + + def _execute(self, args): + '''Thread to execute the test and to wait for it to finish.''' + # pylint: disable=unused-variable + cmds = args + if self.console is not None: + self.console('exe: %s' % (' '.join(cmds))) + ecode, proc = self.process.open(cmds) + if self.trace: + print('gdb done', ecode) + self._lock('_execute') + self.ecode = ecode + self.process = None + self._unlock('_execute') + + def _monitor(self, timeout): + output_length = self.output_length + step = 0.25 + period = timeout[0] + seconds = timeout[1] + while self.process and period > 0 and seconds > 0: + current_length = self.output_length + if output_length != current_length: + period = timeout[0] + output_length = current_length + if seconds < step: + seconds = 0 + else: + seconds -= step + if period < step: + step = period + period = 0 + else: + period -= step + self._unlock('_monitor') + time.sleep(step) + self._lock('_monitor') + if self.process is not None: + if period == 0: + self._timeout() + elif seconds == 0: + self._test_too_long() + + def open(self, command, ignore_exit_code, output, console, timeout): + '''Open the execute test run''' + # pylint: disable=too-many-arguments + self._lock('_open') + self.timeout = timeout[2] + self.test_too_long = timeout[3] + try: + cmds = execute.arg_list(command) + self.output = output + self.console = console + self.process = execute.execute(output=self._capture) + exec_thread = threading.Thread(target=self._execute, args=[cmds]) + exec_thread.start() + self._monitor(timeout) + if self.ecode is not None and \ + not (self.kill_good or ignore_exit_code) and self.ecode > 0: + if self.output: + self.output('*** TARGET ERROR %d %s ***' % + (self.ecode, os.strerror(self.ecode))) + finally: + self._unlock('_open') + + def kill(self): + '''Kill the test run.''' + self._lock('_kill') + try: + self._kill() + finally: + self._unlock('_kill') diff --git a/tester/rt/gdb.py b/tester/rt/gdb.py index bfd3749..d0cf504 100644 --- a/tester/rt/gdb.py +++ b/tester/rt/gdb.py @@ -43,6 +43,7 @@ except ImportError: import queue import sys import threading +import time from rtemstoolkit import error from rtemstoolkit import execute @@ -67,15 +68,19 @@ class gdb(object): self.bsp = bsp self.bsp_arch = bsp_arch self.output = None + self.output_length = 0 self.gdb_console = None self.input = queue.Queue() self.commands = queue.Queue() self.process = None + self.ecode = None self.state = {} self.running = False self.breakpoints = {} self.output = None self.output_buffer = '' + self.timeout = None + self.test_too_long = None self.lc = 0 def _lock(self, msg): @@ -153,13 +158,14 @@ class gdb(object): return False def _timeout(self): - self._lock('_timeout') - try: - if self.output: - self.output('*** TIMEOUT TIMEOUT') - self._gdb_quit(backtrace = True) - finally: - self._unlock('_timeout') + self._stop() + if self.timeout is not None: + self.timeout() + + def _test_too_long(self): + self._stop() + if self.test_too_long is not None: + self.test_too_long() def _cleanup(self, proc): self._lock('_cleanup') @@ -181,10 +187,73 @@ class gdb(object): finally: self._unlock('_gdb_quit') + def _stop(self): + self._gdb_quit(backtrace=True) + seconds = 5 + step = 0.1 + while self.process and seconds > 0: + if seconds > step: + seconds -= step + else: + seconds = 0 + self._unlock('_stop') + time.sleep(step) + self._lock('_stop') + if self.process and seconds == 0: + self._kill() + + def _kill(self): + if self.process: + self.process.kill() + self.process = None + + def _execute_gdb(self, args): + '''Thread to execute GDB and to wait for it to finish.''' + cmds = args + self.gdb_console('gdb: %s' % (' '.join(cmds))) + ecode, proc = self.process.open(cmds) + if self.trace: + print('gdb done', ecode) + self._lock('_execute_gdb') + self.ecode = ecode + self.process = None + self.running = False + self._unlock('_execute_gdb') + + def _monitor(self, timeout): + output_length = self.output_length + step = 0.25 + period = timeout[0] + seconds = timeout[1] + while self.process and period > 0 and seconds > 0: + current_length = self.output_length + if output_length != current_length: + period = timeout[0] + output_length = current_length + if seconds < step: + seconds = 0 + else: + seconds -= step + if period < step: + step = period + period = 0 + else: + period -= step + self._unlock('_monitor') + time.sleep(step) + self._lock('_monitor') + if self.process is not None: + if period == 0: + self._timeout() + elif seconds == 0: + self._test_too_long() + def open(self, command, executable, - output, gdb_console, script = None, tty = None, - timeout = 300): + output, gdb_console, timeout, + script = None, tty = None): self._lock('_open') + self.timeout = timeout[2] + self.test_too_long = timeout[3] try: cmds = execute.arg_list(command) + ['-i=mi', '--nx', @@ -196,32 +265,25 @@ class gdb(object): self.output = output self.gdb_console = gdb_console self.script = script - self.running = False self.process = execute.execute(output = self._reader, input = self._writer, cleanup = self._cleanup) - finally: - self._unlock('_open') - self.gdb_console('gdb: %s' % (' '.join(cmds))) - ec, proc = self.process.open(cmds, timeout = (timeout, self._timeout)) - if self.trace: - print('gdb done', ec) - if ec > 0: - raise error.general('gdb exec: %s: %s' % (cmds[0], os.strerror(ec))) - self._lock('_open') - try: - self.process = None + exec_thread = threading.Thread(target=self._execute_gdb, + args=[cmds]) + exec_thread.start() + self._monitor(timeout) + if self.ecode is not None and self.ecode > 0: + raise error.general('gdb exec: %s: %s' % (cmds[0], + os.strerror(self.ecode))) finally: self._unlock('_open') def kill(self): - self._lock('_open') + self._lock('_kill') try: - if self.process: - self.process.kill() - self.process = None + self._kill() finally: - self._unlock('_open') + self._unlock('_kill') def gdb_expect(self): if self.trace: @@ -282,8 +344,9 @@ class gdb(object): if last_lf >= 0: lines = self.output_buffer[:last_lf] if self.trace: - print('/// console output') + print('/// console output: ', len(lines)) for line in lines.splitlines(): + self.output_length += len(line) self.output(line) self.output_buffer = self.output_buffer[last_lf + 1:] except: diff --git a/tester/rt/report.py b/tester/rt/report.py index c62d553..5f871dc 100644 --- a/tester/rt/report.py +++ b/tester/rt/report.py @@ -63,6 +63,7 @@ class report(object): self.indeterminate = 0 self.benchmark = 0 self.timeouts = 0 + self.test_too_long = 0 self.invalids = 0 self.wrong_version = 0 self.wrong_build = 0 @@ -79,6 +80,7 @@ class report(object): msg += 'Indeterminate: %*d%s' % (self.total_len, self.self.indeterminate, os.linesep) msg += 'Benchmark: %*d%s' % (self.total_len, self.self.benchmark, os.linesep) msg += 'Timeout: %*d%s' % (self.total_len, self.timeouts, os.linesep) + msg += 'Test too long: %*d%s' % (self.total_len, self.test_too_long, os.linesep) msg += 'Invalid: %*d%s' % (self.total_len, self.invalids, os.linesep) msg += 'Wrong Version %*d%s' % (self.total_len, self.wrong_version, os.linesep) msg += 'Wrong Build %*d%s' % (self.total_len, self.wrong_build, os.linesep) @@ -87,7 +89,7 @@ class report(object): def start(self, index, total, name, executable, bsp_arch, bsp, show_header): header = '[%*d/%*d] p:%-*d f:%-*d u:%-*d e:%-*d I:%-*d B:%-*d ' \ - 't:%-*d i:%-*d W:%-*d | %s/%s: %s' % \ + 't:%-*d L:%-*d i:%-*d W:%-*d | %s/%s: %s' % \ (len(str(total)), index, len(str(total)), total, len(str(total)), self.passed, @@ -97,6 +99,7 @@ class report(object): len(str(total)), self.indeterminate, len(str(total)), self.benchmark, len(str(total)), self.timeouts, + len(str(total)), self.test_too_long, len(str(total)), self.invalids, len(str(total)), self.wrong_version + self.wrong_build + self.wrong_tools, bsp_arch, @@ -123,11 +126,13 @@ class report(object): def end(self, name, output, output_prefix): start = False end = False + fatal = False state = None version = None build = None tools = None timeout = False + test_too_long = False prefixed_output = [] for line in output: if line[0] == output_prefix: @@ -137,8 +142,12 @@ class report(object): start = True elif line[1][4:].startswith('END OF '): end = True + elif line[1][4:].startswith('FATAL'): + fatal = True elif banner.startswith('TIMEOUT TIMEOUT'): timeout = True + elif banner.startswith('TEST TOO LONG'): + test_too_long = True elif banner.startswith('TEST VERSION:'): version = banner[13:].strip() elif banner.startswith('TEST STATE:'): @@ -184,9 +193,15 @@ class report(object): if state is None or state == 'EXPECTED_PASS': status = 'passed' self.passed += 1 + elif fatal: + status = 'fatal error' + self.failed += 1 elif timeout: status = 'timeout' self.timeouts += 1 + elif test_too_long: + status = 'test-too-long' + self.test_too_long += 1 elif start: if not end: status = 'failed' @@ -240,7 +255,7 @@ class report(object): return status def log(self, name, mode): - status_fails = ['failed', 'timeout', 'invalid', + status_fails = ['failed', 'timeout', 'test-too-long', 'invalid', 'wrong-version', 'wrong-build', 'wrong-tools'] if mode != 'none': self.lock.acquire() @@ -273,8 +288,9 @@ class report(object): def score_card(self, mode = 'full'): if mode == 'short': wrongs = self.wrong_version + self.wrong_build + self.wrong_tools - return 'Passed:%d Failed:%d Timeout:%d Invalid:%d Wrong:%d' % \ - (self.passed, self.failed, self.timeouts, self.invalids, wrongs) + return 'Passed:%d Failed:%d Timeout:%d Test-Too-long:%d Invalid:%d Wrong:%d' % \ + (self.passed, self.failed, self.timeouts, self.test_too_long, + self.invalids, wrongs) elif mode == 'full': l = [] l += ['Passed: %*d' % (self.total_len, self.passed)] @@ -284,6 +300,7 @@ class report(object): l += ['Indeterminate: %*d' % (self.total_len, self.indeterminate)] l += ['Benchmark: %*d' % (self.total_len, self.benchmark)] l += ['Timeout: %*d' % (self.total_len, self.timeouts)] + l += ['Test too long: %*d' % (self.total_len, self.test_too_long)] l += ['Invalid: %*d' % (self.total_len, self.invalids)] l += ['Wrong Version: %*d' % (self.total_len, self.wrong_version)] l += ['Wrong Build: %*d' % (self.total_len, self.wrong_build)] @@ -319,6 +336,9 @@ class report(object): if self.timeouts: l += ['Timeouts:'] l += show_state(self.results, 'timeout', self.name_max_len) + if self.test_too_long: + l += ['Test too long:'] + l += show_state(self.results, 'test-too-long', self.name_max_len) if self.invalids: l += ['Invalid:'] l += show_state(self.results, 'invalid', self.name_max_len) diff --git a/tester/rt/test.py b/tester/rt/test.py index 16ac352..3ecadf9 100644 --- a/tester/rt/test.py +++ b/tester/rt/test.py @@ -235,6 +235,7 @@ def generate_json_report(args, reports, start_time, end_time, json_log['summary']['indeterminate_count'] = reports.indeterminate json_log['summary']['benchmark_count'] = reports.benchmark json_log['summary']['timeout_count'] = reports.timeouts + json_log['summary']['too_long_count'] = reports.too_long json_log['summary']['invalid_count'] = reports.invalids json_log['summary']['wrong-version_count'] = reports.wrong_version json_log['summary']['wrong-build_count'] = reports.wrong_build @@ -246,8 +247,8 @@ def generate_json_report(args, reports, start_time, end_time, result_types = [ 'failed', 'user-input', 'expected-fail', 'indeterminate', - 'benchmark', 'timeout', 'invalid', 'wrong-version', 'wrong-build', - 'wrong-tools' + 'benchmark', 'timeout', 'too-long', 'invalid', 'wrong-version', + 'wrong-build', 'wrong-tools' ] json_results = {} for result_type in result_types: @@ -304,6 +305,7 @@ def generate_junit_report(args, reports, start_time, end_time, junit_prop['indeterminate_count'] = reports.indeterminate junit_prop['benchmark_count'] = reports.benchmark junit_prop['timeout_count'] = reports.timeouts + junit_prop['too_long_count'] = reports.too_long junit_prop['invalid_count'] = reports.invalids junit_prop['wrong-version_count'] = reports.wrong_version junit_prop['wrong-build_count'] = reports.wrong_build diff --git a/tester/rt/tftp.py b/tester/rt/tftp.py index 7af3a62..7829e8f 100644 --- a/tester/rt/tftp.py +++ b/tester/rt/tftp.py @@ -66,6 +66,7 @@ class tftp(object): self.port = 0 self.exe = None self.timeout = None + self.test_too_long = None self.timer = None self.running = False self.finished = False @@ -109,6 +110,15 @@ class tftp(object): if self.timeout is not None: self.timeout() + def _test_too_long(self): + self._stop() + while self.running or not self.finished: + self._unlock('_test_too_long') + time.sleep(0.1) + self._lock('_test_too_long') + if self.test_too_long is not None: + self.test_too_long() + def _exe_handle(self, req_file, raddress, rport): self._lock('_exe_handle') exe = self.exe @@ -166,29 +176,40 @@ class tftp(object): self.exe = executable if self.console: self.console('tftp: exe: %s' % (executable)) - self.timeout = timeout[1] + self.timeout = timeout[2] + self.test_too_long = timeout[3] self.listener = threading.Thread(target = self._runner, name = 'tftp-listener') self.listener.start() - step = 0.5 + step = 0.25 period = timeout[0] + seconds = timeout[1] output_len = self.output_length() - while not self.finished and period > 0: + while not self.finished and period > 0 and seconds > 0: + if not self.running and self.caught: + break current_length = self.output_length() if output_length != current_length: period = timeout[0] output_length = current_length + if seconds < step: + seconds = 0 + else: + seconds -= step if period < step: + step = period period = 0 else: period -= step self._unlock('_open') time.sleep(step) self._lock('_open') - if not self.finished and period == 0: - self._timeout() + if not self.finished: + if period == 0: + self._timeout() + elif seconds == 0: + self._test_too_long() caught = self.caught - self.caught = None self._init() self._unlock('_open') if caught is not None: diff --git a/tester/rtems/testing/testing.mc b/tester/rtems/testing/testing.mc index 662b352..d03ea6d 100644 --- a/tester/rtems/testing/testing.mc +++ b/tester/rtems/testing/testing.mc @@ -51,7 +51,8 @@ _rtbase: none, none, '%{_rtdir}' _rtscripts: none, none, '%{_rtbase}/rtems/testing' # Defaults -timeout: none, none, '180' +timeout: none, none, '180' # seconds +max_test_period: none, none, '300' # seconds # Tests detected as invalid that are valid invalid_tests: none, none, '''minimum.exe''' diff --git a/tester/wscript b/tester/wscript index e0e4693..ad1cf2d 100644 --- a/tester/wscript +++ b/tester/wscript @@ -60,6 +60,7 @@ def build(bld): 'rt/config.py', 'rt/console.py', 'rt/coverage.py', + 'rt/exe.py', 'rt/gdb.py', 'rt/options.py', 'rt/report.py', -- cgit v1.2.3