tests/qemu-iotests/testrunner.py

   1 # Class for actually running tests.
   2 #
   3 # Copyright (c) 2020-2021 Virtuozzo International GmbH
   4 #
   5 # This program is free software; you can redistribute it and/or modify
   6 # it under the terms of the GNU General Public License as published by
   7 # the Free Software Foundation; either version 2 of the License, or
   8 # (at your option) any later version.
   9 #
  10 # This program is distributed in the hope that it will be useful,
  11 # but WITHOUT ANY WARRANTY; without even the implied warranty of
  12 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  13 # GNU General Public License for more details.
  14 #
  15 # You should have received a copy of the GNU General Public License
  16 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
  17 #
  18
  19 import os
  20 from pathlib import Path
  21 import datetime
  22 import time
  23 import difflib
  24 import subprocess
  25 import contextlib
  26 import json
  27 import shutil
  28 import sys
  29 from multiprocessing import Pool
  30 from typing import List, Optional, Any, Sequence, Dict, \
  31         ContextManager
  32
  33 from testenv import TestEnv
  34
  35
  36 def silent_unlink(path: Path) -> None:
  37     try:
  38         path.unlink()
  39     except OSError:
  40         pass
  41
  42
  43 def file_diff(file1: str, file2: str) -> List[str]:
  44     with open(file1, encoding="utf-8") as f1, \
  45          open(file2, encoding="utf-8") as f2:
  46         # We want to ignore spaces at line ends. There are a lot of mess about
  47         # it in iotests.
  48         # TODO: fix all tests to not produce extra spaces, fix all .out files
  49         # and use strict diff here!
  50         seq1 = [line.rstrip() for line in f1]
  51         seq2 = [line.rstrip() for line in f2]
  52         res = [line.rstrip()
  53                for line in difflib.unified_diff(seq1, seq2, file1, file2)]
  54         return res
  55
  56
  57 class LastElapsedTime(ContextManager['LastElapsedTime']):
  58     """ Cache for elapsed time for tests, to show it during new test run
  59
  60     It is safe to use get() at any time.  To use update(), you must either
  61     use it inside with-block or use save() after update().
  62     """
  63     def __init__(self, cache_file: str, env: TestEnv) -> None:
  64         self.env = env
  65         self.cache_file = cache_file
  66         self.cache: Dict[str, Dict[str, Dict[str, float]]]
  67
  68         try:
  69             with open(cache_file, encoding="utf-8") as f:
  70                 self.cache = json.load(f)
  71         except (OSError, ValueError):
  72             self.cache = {}
  73
  74     def get(self, test: str,
  75             default: Optional[float] = None) -> Optional[float]:
  76         if test not in self.cache:
  77             return default
  78
  79         if self.env.imgproto not in self.cache[test]:
  80             return default
  81
  82         return self.cache[test][self.env.imgproto].get(self.env.imgfmt,
  83                                                        default)
  84
  85     def update(self, test: str, elapsed: float) -> None:
  86         d = self.cache.setdefault(test, {})
  87         d.setdefault(self.env.imgproto, {})[self.env.imgfmt] = elapsed
  88
  89     def save(self) -> None:
  90         with open(self.cache_file, 'w', encoding="utf-8") as f:
  91             json.dump(self.cache, f)
  92
  93     def __enter__(self) -> 'LastElapsedTime':
  94         return self
  95
  96     def __exit__(self, exc_type: Any, exc_value: Any, traceback: Any) -> None:
  97         self.save()
  98
  99
 100 class TestResult:
 101     def __init__(self, status: str, description: str = '',
 102                  elapsed: Optional[float] = None, diff: Sequence[str] = (),
 103                  casenotrun: str = '', interrupted: bool = False) -> None:
 104         self.status = status
 105         self.description = description
 106         self.elapsed = elapsed
 107         self.diff = diff
 108         self.casenotrun = casenotrun
 109         self.interrupted = interrupted
 110
 111
 112 class TestRunner(ContextManager['TestRunner']):
 113     shared_self = None
 114
 115     @staticmethod
 116     def proc_run_test(test: str, test_field_width: int) -> TestResult:
 117         # We are in a subprocess, we can't change the runner object!
 118         runner = TestRunner.shared_self
 119         assert runner is not None
 120         return runner.run_test(test, test_field_width, mp=True)
 121
 122     def run_tests_pool(self, tests: List[str],
 123                        test_field_width: int, jobs: int) -> List[TestResult]:
 124
 125         # passing self directly to Pool.starmap() just doesn't work, because
 126         # it's a context manager.
 127         assert TestRunner.shared_self is None
 128         TestRunner.shared_self = self
 129
 130         with Pool(jobs) as p:
 131             results = p.starmap(self.proc_run_test,
 132                                 zip(tests, [test_field_width] * len(tests)))
 133
 134         TestRunner.shared_self = None
 135
 136         return results
 137
 138     def __init__(self, env: TestEnv, tap: bool = False,
 139                  color: str = 'auto') -> None:
 140         self.env = env
 141         self.tap = tap
 142         self.last_elapsed = LastElapsedTime('.last-elapsed-cache', env)
 143
 144         assert color in ('auto', 'on', 'off')
 145         self.color = (color == 'on') or (color == 'auto' and
 146                                          sys.stdout.isatty())
 147
 148         self._stack: contextlib.ExitStack
 149
 150     def __enter__(self) -> 'TestRunner':
 151         self._stack = contextlib.ExitStack()
 152         self._stack.enter_context(self.env)
 153         self._stack.enter_context(self.last_elapsed)
 154         return self
 155
 156     def __exit__(self, exc_type: Any, exc_value: Any, traceback: Any) -> None:
 157         self._stack.close()
 158
 159     def test_print_one_line(self, test: str,
 160                             test_field_width: int,
 161                             starttime: str,
 162                             endtime: Optional[str] = None, status: str = '...',
 163                             lasttime: Optional[float] = None,
 164                             thistime: Optional[float] = None,
 165                             description: str = '',
 166                             end: str = '\n') -> None:
 167         """ Print short test info before/after test run """
 168         test = os.path.basename(test)
 169
 170         if test_field_width is None:
 171             test_field_width = 8
 172
 173         if self.tap:
 174             if status == 'pass':
 175                 print(f'ok {self.env.imgfmt} {test}')
 176             elif status == 'fail':
 177                 print(f'not ok {self.env.imgfmt} {test}')
 178             elif status == 'not run':
 179                 print(f'ok {self.env.imgfmt} {test} # SKIP')
 180             return
 181
 182         if lasttime:
 183             lasttime_s = f' (last: {lasttime:.1f}s)'
 184         else:
 185             lasttime_s = ''
 186         if thistime:
 187             thistime_s = f'{thistime:.1f}s'
 188         else:
 189             thistime_s = '...'
 190
 191         if endtime:
 192             endtime = f'[{endtime}]'
 193         else:
 194             endtime = ''
 195
 196         if self.color:
 197             if status == 'pass':
 198                 col = '\033[32m'
 199             elif status == 'fail':
 200                 col = '\033[1m\033[31m'
 201             elif status == 'not run':
 202                 col = '\033[33m'
 203             else:
 204                 col = ''
 205
 206             col_end = '\033[0m'
 207         else:
 208             col = ''
 209             col_end = ''
 210
 211         print(f'{test:{test_field_width}} {col}{status:10}{col_end} '
 212               f'[{starttime}] {endtime:13}{thistime_s:5} {lasttime_s:14} '
 213               f'{description}', end=end)
 214
 215     def find_reference(self, test: str) -> str:
 216         if self.env.cachemode == 'none':
 217             ref = f'{test}.out.nocache'
 218             if os.path.isfile(ref):
 219                 return ref
 220
 221         ref = f'{test}.out.{self.env.imgfmt}'
 222         if os.path.isfile(ref):
 223             return ref
 224
 225         ref = f'{test}.{self.env.qemu_default_machine}.out'
 226         if os.path.isfile(ref):
 227             return ref
 228
 229         return f'{test}.out'
 230
 231     def do_run_test(self, test: str) -> TestResult:
 232         """
 233         Run one test
 234
 235         :param test: test file path
 236
 237         Note: this method may be called from subprocess, so it does not
 238         change ``self`` object in any way!
 239         """
 240
 241         f_test = Path(test)
 242         f_reference = Path(self.find_reference(test))
 243
 244         if not f_test.exists():
 245             return TestResult(status='fail',
 246                               description=f'No such test file: {f_test}')
 247
 248         if not os.access(str(f_test), os.X_OK):
 249             sys.exit(f'Not executable: {f_test}')
 250
 251         if not f_reference.exists():
 252             return TestResult(status='not run',
 253                               description='No qualified output '
 254                                           f'(expected {f_reference})')
 255
 256         args = [str(f_test.resolve())]
 257         env = self.env.prepare_subprocess(args)
 258
 259         # Split test directories, so that tests running in parallel don't
 260         # break each other.
 261         for d in ['TEST_DIR', 'SOCK_DIR']:
 262             env[d] = os.path.join(
 263                 env[d],
 264                 f"{self.env.imgfmt}-{self.env.imgproto}-{f_test.name}")
 265             Path(env[d]).mkdir(parents=True, exist_ok=True)
 266
 267         test_dir = env['TEST_DIR']
 268         f_bad = Path(test_dir, f_test.name + '.out.bad')
 269         f_notrun = Path(test_dir, f_test.name + '.notrun')
 270         f_casenotrun = Path(test_dir, f_test.name + '.casenotrun')
 271
 272         for p in (f_notrun, f_casenotrun):
 273             silent_unlink(p)
 274
 275         t0 = time.time()
 276         with f_bad.open('w', encoding="utf-8") as f:
 277             with subprocess.Popen(args, cwd=str(f_test.parent), env=env,
 278                                   stdin=subprocess.DEVNULL,
 279                                   stdout=f, stderr=subprocess.STDOUT) as proc:
 280                 try:
 281                     proc.wait()
 282                 except KeyboardInterrupt:
 283                     proc.terminate()
 284                     proc.wait()
 285                     return TestResult(status='not run',
 286                                       description='Interrupted by user',
 287                                       interrupted=True)
 288                 ret = proc.returncode
 289
 290         elapsed = round(time.time() - t0, 1)
 291
 292         if ret != 0:
 293             return TestResult(status='fail', elapsed=elapsed,
 294                               description=f'failed, exit status {ret}',
 295                               diff=file_diff(str(f_reference), str(f_bad)))
 296
 297         if f_notrun.exists():
 298             return TestResult(
 299                 status='not run',
 300                 description=f_notrun.read_text(encoding='utf-8').strip())
 301
 302         casenotrun = ''
 303         if f_casenotrun.exists():
 304             casenotrun = f_casenotrun.read_text(encoding='utf-8')
 305
 306         diff = file_diff(str(f_reference), str(f_bad))
 307         if diff:
 308             if os.environ.get("QEMU_IOTESTS_REGEN", None) is not None:
 309                 shutil.copyfile(str(f_bad), str(f_reference))
 310                 print("########################################")
 311                 print("#####    REFERENCE FILE UPDATED    #####")
 312                 print("########################################")
 313             return TestResult(status='fail', elapsed=elapsed,
 314                               description=f'output mismatch (see {f_bad})',
 315                               diff=diff, casenotrun=casenotrun)
 316         else:
 317             f_bad.unlink()
 318             return TestResult(status='pass', elapsed=elapsed,
 319                               casenotrun=casenotrun)
 320
 321     def run_test(self, test: str,
 322                  test_field_width: int,
 323                  mp: bool = False) -> TestResult:
 324         """
 325         Run one test and print short status
 326
 327         :param test: test file path
 328         :param test_field_width: width for first field of status format
 329         :param mp: if true, we are in a multiprocessing environment, don't try
 330                    to rewrite things in stdout
 331
 332         Note: this method may be called from subprocess, so it does not
 333         change ``self`` object in any way!
 334         """
 335
 336         last_el = self.last_elapsed.get(test)
 337         start = datetime.datetime.now().strftime('%H:%M:%S')
 338
 339         if not self.tap:
 340             self.test_print_one_line(test=test,
 341                                      test_field_width=test_field_width,
 342                                      status = 'started' if mp else '...',
 343                                      starttime=start,
 344                                      lasttime=last_el,
 345                                      end = '\n' if mp else '\r')
 346         else:
 347             testname = os.path.basename(test)
 348             print(f'# running {self.env.imgfmt} {testname}')
 349
 350         res = self.do_run_test(test)
 351
 352         end = datetime.datetime.now().strftime('%H:%M:%S')
 353         self.test_print_one_line(test=test,
 354                                  test_field_width=test_field_width,
 355                                  status=res.status,
 356                                  starttime=start, endtime=end,
 357                                  lasttime=last_el, thistime=res.elapsed,
 358                                  description=res.description)
 359
 360         if res.casenotrun:
 361             if self.tap:
 362                 print('#' + res.casenotrun.replace('\n', '\n#'))
 363             else:
 364                 print(res.casenotrun)
 365
 366         sys.stdout.flush()
 367         return res
 368
 369     def run_tests(self, tests: List[str], jobs: int = 1) -> bool:
 370         n_run = 0
 371         failed = []
 372         notrun = []
 373         casenotrun = []
 374
 375         if self.tap:
 376             print('TAP version 13')
 377             self.env.print_env('# ')
 378             print('1..%d' % len(tests))
 379         else:
 380             self.env.print_env()
 381
 382         test_field_width = max(len(os.path.basename(t)) for t in tests) + 2
 383
 384         if jobs > 1:
 385             results = self.run_tests_pool(tests, test_field_width, jobs)
 386
 387         for i, t in enumerate(tests):
 388             name = os.path.basename(t)
 389
 390             if jobs > 1:
 391                 res = results[i]
 392             else:
 393                 res = self.run_test(t, test_field_width)
 394
 395             assert res.status in ('pass', 'fail', 'not run')
 396
 397             if res.casenotrun:
 398                 casenotrun.append(t)
 399
 400             if res.status != 'not run':
 401                 n_run += 1
 402
 403             if res.status == 'fail':
 404                 failed.append(name)
 405                 if res.diff:
 406                     if self.tap:
 407                         print('\n'.join(res.diff), file=sys.stderr)
 408                     else:
 409                         print('\n'.join(res.diff))
 410             elif res.status == 'not run':
 411                 notrun.append(name)
 412             elif res.status == 'pass':
 413                 assert res.elapsed is not None
 414                 self.last_elapsed.update(t, res.elapsed)
 415
 416             sys.stdout.flush()
 417             if res.interrupted:
 418                 break
 419
 420         if not self.tap:
 421             if notrun:
 422                 print('Not run:', ' '.join(notrun))
 423
 424             if casenotrun:
 425                 print('Some cases not run in:', ' '.join(casenotrun))
 426
 427             if failed:
 428                 print('Failures:', ' '.join(failed))
 429                 print(f'Failed {len(failed)} of {n_run} iotests')
 430             else:
 431                 print(f'Passed all {n_run} iotests')
 432         return not failed