| # |
| # Licensed to the Apache Software Foundation (ASF) under one |
| # or more contributor license agreements. See the NOTICE file |
| # distributed with this work for additional information |
| # regarding copyright ownership. The ASF licenses this file |
| # to you under the Apache License, Version 2.0 (the |
| # "License"); you may not use this file except in compliance |
| # with the License. You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, |
| # software distributed under the License is distributed on an |
| # "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
| # KIND, either express or implied. See the License for the |
| # specific language governing permissions and limitations |
| # under the License. |
| # |
| |
| from __future__ import print_function |
| import datetime |
| import json |
| import multiprocessing |
| import os |
| import platform |
| import re |
| import subprocess |
| import sys |
| import time |
| import traceback |
| |
| from .compat import logfile_open, path_join, str_join |
| from .test import TestEntry |
| |
| LOG_DIR = 'log' |
| RESULT_HTML = 'index.html' |
| RESULT_JSON = 'results.json' |
| FAIL_JSON = 'known_failures_%s.json' |
| |
| |
| def generate_known_failures(testdir, overwrite, save, out): |
| def collect_failures(results): |
| success_index = 5 |
| for r in results: |
| if not r[success_index]: |
| yield TestEntry.get_name(*r) |
| try: |
| with logfile_open(path_join(testdir, RESULT_JSON), 'r') as fp: |
| results = json.load(fp) |
| except IOError: |
| sys.stderr.write('Unable to load last result. Did you run tests ?\n') |
| return False |
| fails = collect_failures(results['results']) |
| if not overwrite: |
| known = load_known_failures(testdir) |
| known.extend(fails) |
| fails = known |
| fails_json = json.dumps(sorted(set(fails)), indent=2, separators=(',', ': ')) |
| if save: |
| with logfile_open(os.path.join(testdir, FAIL_JSON % platform.system()), 'w+') as fp: |
| fp.write(fails_json) |
| sys.stdout.write('Successfully updated known failures.\n') |
| if out: |
| sys.stdout.write(fails_json) |
| sys.stdout.write('\n') |
| return True |
| |
| |
| def load_known_failures(testdir): |
| try: |
| with logfile_open(path_join(testdir, FAIL_JSON % platform.system()), 'r') as fp: |
| return json.load(fp) |
| except IOError: |
| return [] |
| |
| |
| class TestReporter(object): |
| # Unfortunately, standard library doesn't handle timezone well |
| # DATETIME_FORMAT = '%a %b %d %H:%M:%S %Z %Y' |
| DATETIME_FORMAT = '%a %b %d %H:%M:%S %Y' |
| |
| def __init__(self): |
| self._log = multiprocessing.get_logger() |
| self._lock = multiprocessing.Lock() |
| |
| @classmethod |
| def test_logfile(cls, test_name, prog_kind, dir=None): |
| relpath = path_join('log', '%s_%s.log' % (test_name, prog_kind)) |
| return relpath if not dir else os.path.realpath(path_join(dir, relpath)) |
| |
| def _start(self): |
| self._start_time = time.time() |
| |
| @property |
| def _elapsed(self): |
| return time.time() - self._start_time |
| |
| @classmethod |
| def _format_date(cls): |
| return '%s' % datetime.datetime.now().strftime(cls.DATETIME_FORMAT) |
| |
| def _print_date(self): |
| print(self._format_date(), file=self.out) |
| |
| def _print_bar(self, out=None): |
| print( |
| '===============================================================================', |
| file=(out or self.out)) |
| |
| def _print_exec_time(self): |
| print('Test execution took {:.1f} seconds.'.format(self._elapsed), file=self.out) |
| |
| |
| class ExecReporter(TestReporter): |
| def __init__(self, testdir, test, prog): |
| super(ExecReporter, self).__init__() |
| self._test = test |
| self._prog = prog |
| self.logpath = self.test_logfile(test.name, prog.kind, testdir) |
| self.out = None |
| |
| def begin(self): |
| self._start() |
| self._open() |
| if self.out and not self.out.closed: |
| self._print_header() |
| else: |
| self._log.debug('Output stream is not available.') |
| |
| def end(self, returncode): |
| self._lock.acquire() |
| try: |
| if self.out and not self.out.closed: |
| self._print_footer(returncode) |
| self._close() |
| self.out = None |
| else: |
| self._log.debug('Output stream is not available.') |
| finally: |
| self._lock.release() |
| |
| def killed(self): |
| print(file=self.out) |
| print('Server process is successfully killed.', file=self.out) |
| self.end(None) |
| |
| def died(self): |
| print(file=self.out) |
| print('*** Server process has died unexpectedly ***', file=self.out) |
| self.end(None) |
| |
| _init_failure_exprs = { |
| 'server': list(map(re.compile, [ |
| '[Aa]ddress already in use', |
| 'Could not bind', |
| 'EADDRINUSE', |
| ])), |
| 'client': list(map(re.compile, [ |
| '[Cc]onnection refused', |
| 'Could not connect to', |
| 'Could not open UNIX ', # domain socket (rb) |
| 'ECONNREFUSED', |
| 'econnrefused', # erl |
| 'CONNECTION-REFUSED-ERROR', # cl |
| 'connect ENOENT', # nodejs domain socket |
| 'No such file or directory', # domain socket |
| 'Sockets.TcpClient.Connect', # csharp |
| ])), |
| } |
| |
| def maybe_false_positive(self): |
| """Searches through log file for socket bind error. |
| Returns True if suspicious expression is found, otherwise False""" |
| try: |
| if self.out and not self.out.closed: |
| self.out.flush() |
| exprs = self._init_failure_exprs[self._prog.kind] |
| |
| def match(line): |
| for expr in exprs: |
| if expr.search(line): |
| self._log.info("maybe false positive: %s" % line) |
| return True |
| |
| with logfile_open(self.logpath, 'r') as fp: |
| if any(map(match, fp)): |
| return True |
| except (KeyboardInterrupt, SystemExit): |
| raise |
| except Exception as ex: |
| self._log.warn('[%s]: Error while detecting false positive: %s' % (self._test.name, str(ex))) |
| self._log.info(traceback.print_exc()) |
| return False |
| |
| def _open(self): |
| self.out = logfile_open(self.logpath, 'w+') |
| |
| def _close(self): |
| self.out.close() |
| |
| def _print_header(self): |
| self._print_date() |
| print('Executing: %s' % str_join(' ', self._prog.command), file=self.out) |
| print('Directory: %s' % self._prog.workdir, file=self.out) |
| print('config:delay: %s' % self._test.delay, file=self.out) |
| print('config:timeout: %s' % self._test.timeout, file=self.out) |
| self._print_bar() |
| self.out.flush() |
| |
| def _print_footer(self, returncode=None): |
| self._print_bar() |
| if returncode is not None: |
| print('Return code: %d (negative values indicate kill by signal)' % returncode, file=self.out) |
| else: |
| print('Process is killed.', file=self.out) |
| self._print_exec_time() |
| self._print_date() |
| |
| |
| class SummaryReporter(TestReporter): |
| def __init__(self, basedir, testdir_relative, concurrent=True): |
| super(SummaryReporter, self).__init__() |
| self._basedir = basedir |
| self._testdir_rel = testdir_relative |
| self.logdir = path_join(self.testdir, LOG_DIR) |
| self.out_path = path_join(self.testdir, RESULT_JSON) |
| self.concurrent = concurrent |
| self.out = sys.stdout |
| self._platform = platform.system() |
| self._revision = self._get_revision() |
| self._tests = [] |
| if not os.path.exists(self.logdir): |
| os.mkdir(self.logdir) |
| self._known_failures = load_known_failures(self.testdir) |
| self._unexpected_success = [] |
| self._flaky_success = [] |
| self._unexpected_failure = [] |
| self._expected_failure = [] |
| self._print_header() |
| |
| @property |
| def testdir(self): |
| return path_join(self._basedir, self._testdir_rel) |
| |
| def _result_string(self, test): |
| if test.success: |
| if test.retry_count == 0: |
| return 'success' |
| elif test.retry_count == 1: |
| return 'flaky(1 retry)' |
| else: |
| return 'flaky(%d retries)' % test.retry_count |
| elif test.expired: |
| return 'failure(timeout)' |
| else: |
| return 'failure(%d)' % test.returncode |
| |
| def _get_revision(self): |
| p = subprocess.Popen(['git', 'rev-parse', '--short', 'HEAD'], |
| cwd=self.testdir, stdout=subprocess.PIPE) |
| out, _ = p.communicate() |
| return out.strip() |
| |
| def _format_test(self, test, with_result=True): |
| name = '%s-%s' % (test.server.name, test.client.name) |
| trans = '%s-%s' % (test.transport, test.socket) |
| if not with_result: |
| return '{:24s}{:18s}{:25s}'.format(name[:23], test.protocol[:17], trans[:24]) |
| else: |
| return '{:24s}{:18s}{:25s}{:s}\n'.format(name[:23], test.protocol[:17], |
| trans[:24], self._result_string(test)) |
| |
| def _print_test_header(self): |
| self._print_bar() |
| print( |
| '{:24s}{:18s}{:25s}{:s}'.format('server-client:', 'protocol:', 'transport:', 'result:'), |
| file=self.out) |
| |
| def _print_header(self): |
| self._start() |
| print('Apache Thrift - Integration Test Suite', file=self.out) |
| self._print_date() |
| self._print_test_header() |
| |
| def _print_unexpected_failure(self): |
| if len(self._unexpected_failure) > 0: |
| self.out.writelines([ |
| '*** Following %d failures were unexpected ***:\n' % len(self._unexpected_failure), |
| 'If it is introduced by you, please fix it before submitting the code.\n', |
| # 'If not, please report at https://issues.apache.org/jira/browse/THRIFT\n', |
| ]) |
| self._print_test_header() |
| for i in self._unexpected_failure: |
| self.out.write(self._format_test(self._tests[i])) |
| self._print_bar() |
| else: |
| print('No unexpected failures.', file=self.out) |
| |
| def _print_flaky_success(self): |
| if len(self._flaky_success) > 0: |
| print( |
| 'Following %d tests were expected to cleanly succeed but needed retry:' % len(self._flaky_success), |
| file=self.out) |
| self._print_test_header() |
| for i in self._flaky_success: |
| self.out.write(self._format_test(self._tests[i])) |
| self._print_bar() |
| |
| def _print_unexpected_success(self): |
| if len(self._unexpected_success) > 0: |
| print( |
| 'Following %d tests were known to fail but succeeded (maybe flaky):' % len(self._unexpected_success), |
| file=self.out) |
| self._print_test_header() |
| for i in self._unexpected_success: |
| self.out.write(self._format_test(self._tests[i])) |
| self._print_bar() |
| |
| def _http_server_command(self, port): |
| if sys.version_info[0] < 3: |
| return 'python -m SimpleHTTPServer %d' % port |
| else: |
| return 'python -m http.server %d' % port |
| |
| def _print_footer(self): |
| fail_count = len(self._expected_failure) + len(self._unexpected_failure) |
| self._print_bar() |
| self._print_unexpected_success() |
| self._print_flaky_success() |
| self._print_unexpected_failure() |
| self._write_html_data() |
| self._assemble_log('unexpected failures', self._unexpected_failure) |
| self._assemble_log('known failures', self._expected_failure) |
| self.out.writelines([ |
| 'You can browse results at:\n', |
| '\tfile://%s/%s\n' % (self.testdir, RESULT_HTML), |
| '# If you use Chrome, run:\n', |
| '# \tcd %s\n#\t%s\n' % (self._basedir, self._http_server_command(8001)), |
| '# then browse:\n', |
| '# \thttp://localhost:%d/%s/\n' % (8001, self._testdir_rel), |
| 'Full log for each test is here:\n', |
| '\ttest/log/server_client_protocol_transport_client.log\n', |
| '\ttest/log/server_client_protocol_transport_server.log\n', |
| '%d failed of %d tests in total.\n' % (fail_count, len(self._tests)), |
| ]) |
| self._print_exec_time() |
| self._print_date() |
| |
| def _render_result(self, test): |
| return [ |
| test.server.name, |
| test.client.name, |
| test.protocol, |
| test.transport, |
| test.socket, |
| test.success, |
| test.as_expected, |
| test.returncode, |
| { |
| 'server': self.test_logfile(test.name, test.server.kind), |
| 'client': self.test_logfile(test.name, test.client.kind), |
| }, |
| ] |
| |
| def _write_html_data(self): |
| """Writes JSON data to be read by result html""" |
| results = [self._render_result(r) for r in self._tests] |
| with logfile_open(self.out_path, 'w+') as fp: |
| fp.write(json.dumps({ |
| 'date': self._format_date(), |
| 'revision': str(self._revision), |
| 'platform': self._platform, |
| 'duration': '{:.1f}'.format(self._elapsed), |
| 'results': results, |
| }, indent=2)) |
| |
| def _assemble_log(self, title, indexes): |
| if len(indexes) > 0: |
| def add_prog_log(fp, test, prog_kind): |
| print('*************************** %s message ***************************' % prog_kind, |
| file=fp) |
| path = self.test_logfile(test.name, prog_kind, self.testdir) |
| if os.path.exists(path): |
| with logfile_open(path, 'r') as prog_fp: |
| print(prog_fp.read(), file=fp) |
| filename = title.replace(' ', '_') + '.log' |
| with logfile_open(os.path.join(self.logdir, filename), 'w+') as fp: |
| for test in map(self._tests.__getitem__, indexes): |
| fp.write('TEST: [%s]\n' % test.name) |
| add_prog_log(fp, test, test.server.kind) |
| add_prog_log(fp, test, test.client.kind) |
| fp.write('**********************************************************************\n\n') |
| print('%s are logged to %s/%s/%s' % (title.capitalize(), self._testdir_rel, LOG_DIR, filename)) |
| |
| def end(self): |
| self._print_footer() |
| return len(self._unexpected_failure) == 0 |
| |
| def add_test(self, test_dict): |
| test = TestEntry(self.testdir, **test_dict) |
| self._lock.acquire() |
| try: |
| if not self.concurrent: |
| self.out.write(self._format_test(test, False)) |
| self.out.flush() |
| self._tests.append(test) |
| return len(self._tests) - 1 |
| finally: |
| self._lock.release() |
| |
| def add_result(self, index, returncode, expired, retry_count): |
| self._lock.acquire() |
| try: |
| failed = returncode is None or returncode != 0 |
| flaky = not failed and retry_count != 0 |
| test = self._tests[index] |
| known = test.name in self._known_failures |
| if failed: |
| if known: |
| self._log.debug('%s failed as expected' % test.name) |
| self._expected_failure.append(index) |
| else: |
| self._log.info('unexpected failure: %s' % test.name) |
| self._unexpected_failure.append(index) |
| elif flaky and not known: |
| self._log.info('unexpected flaky success: %s' % test.name) |
| self._flaky_success.append(index) |
| elif not flaky and known: |
| self._log.info('unexpected success: %s' % test.name) |
| self._unexpected_success.append(index) |
| test.success = not failed |
| test.returncode = returncode |
| test.retry_count = retry_count |
| test.expired = expired |
| test.as_expected = known == failed |
| if not self.concurrent: |
| self.out.write(self._result_string(test) + '\n') |
| else: |
| self.out.write(self._format_test(test)) |
| finally: |
| self._lock.release() |