1# vim: ft=python fileencoding=utf-8 sts=4 sw=4 et: 2 3# Copyright 2015-2021 Florian Bruhin (The Compiler) <mail@qutebrowser.org> 4# 5# This file is part of qutebrowser. 6# 7# qutebrowser is free software: you can redistribute it and/or modify 8# it under the terms of the GNU General Public License as published by 9# the Free Software Foundation, either version 3 of the License, or 10# (at your option) any later version. 11# 12# qutebrowser is distributed in the hope that it will be useful, 13# but WITHOUT ANY WARRANTY; without even the implied warranty of 14# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 15# GNU General Public License for more details. 16# 17# You should have received a copy of the GNU General Public License 18# along with qutebrowser. If not, see <https://www.gnu.org/licenses/>. 19 20"""Base class for a subprocess run for tests.""" 21 22import re 23import time 24import warnings 25import dataclasses 26 27import pytest 28import pytestqt.wait_signal 29from PyQt5.QtCore import (pyqtSlot, pyqtSignal, QProcess, QObject, 30 QElapsedTimer, QProcessEnvironment) 31from PyQt5.QtTest import QSignalSpy 32 33from helpers import testutils 34 35from qutebrowser.utils import utils as quteutils 36 37 38class InvalidLine(Exception): 39 40 """Raised when the process prints a line which is not parsable.""" 41 42 43class ProcessExited(Exception): 44 45 """Raised when the child process did exit.""" 46 47 48class WaitForTimeout(Exception): 49 50 """Raised when wait_for didn't get the expected message.""" 51 52 53class BlacklistedMessageError(Exception): 54 55 """Raised when ensure_not_logged found a message.""" 56 57 58@dataclasses.dataclass 59class Line: 60 61 """Container for a line of data the process emits. 62 63 Attributes: 64 data: The raw data passed to the constructor. 65 waited_for: If Process.wait_for was used on this line already. 66 """ 67 68 data: str 69 waited_for: bool = False 70 71 72def _render_log(data, *, verbose, threshold=100): 73 """Shorten the given log without -v and convert to a string.""" 74 data = [str(d) for d in data] 75 is_exception = any('Traceback (most recent call last):' in line or 76 'Uncaught exception' in line for line in data) 77 if (len(data) > threshold and 78 not verbose and 79 not is_exception and 80 not testutils.ON_CI): 81 msg = '[{} lines suppressed, use -v to show]'.format( 82 len(data) - threshold) 83 data = [msg] + data[-threshold:] 84 85 if testutils.ON_CI: 86 data = [testutils.gha_group_begin('Log')] + data + [testutils.gha_group_end()] 87 88 return '\n'.join(data) 89 90 91@pytest.hookimpl(hookwrapper=True) 92def pytest_runtest_makereport(item, call): 93 """Add qutebrowser/server sections to captured output if a test failed.""" 94 outcome = yield 95 if call.when not in ['call', 'teardown']: 96 return 97 report = outcome.get_result() 98 99 if report.passed: 100 return 101 102 quteproc_log = getattr(item, '_quteproc_log', None) 103 server_logs = getattr(item, '_server_logs', []) 104 105 if not hasattr(report.longrepr, 'addsection'): 106 # In some conditions (on macOS and Windows it seems), report.longrepr 107 # is actually a tuple. This is handled similarly in pytest-qt too. 108 return 109 110 if item.config.getoption('--capture') == 'no': 111 # Already printed live 112 return 113 114 verbose = item.config.getoption('--verbose') 115 if quteproc_log is not None: 116 report.longrepr.addsection( 117 "qutebrowser output", _render_log(quteproc_log, verbose=verbose)) 118 for name, content in server_logs: 119 report.longrepr.addsection( 120 f"{name} output", _render_log(content, verbose=verbose)) 121 122 123class Process(QObject): 124 125 """Abstraction over a running test subprocess process. 126 127 Reads the log from its stdout and parses it. 128 129 Attributes: 130 _invalid: A list of lines which could not be parsed. 131 _data: A list of parsed lines. 132 _started: Whether the process was ever started. 133 proc: The QProcess for the underlying process. 134 exit_expected: Whether the process is expected to quit. 135 request: The request object for the current test. 136 137 Signals: 138 ready: Emitted when the server finished starting up. 139 new_data: Emitted when a new line was parsed. 140 """ 141 142 ready = pyqtSignal() 143 new_data = pyqtSignal(object) 144 KEYS = ['data'] 145 146 def __init__(self, request, parent=None): 147 super().__init__(parent) 148 self.request = request 149 self.captured_log = [] 150 self._started = False 151 self._invalid = [] 152 self._data = [] 153 self.proc = QProcess() 154 self.proc.setReadChannel(QProcess.StandardError) 155 self.exit_expected = None # Not started at all yet 156 157 def _log(self, line): 158 """Add the given line to the captured log output.""" 159 if self.request.config.getoption('--capture') == 'no': 160 print(line) 161 self.captured_log.append(line) 162 163 def log_summary(self, text): 164 """Log the given line as summary/title.""" 165 text = '\n{line} {text} {line}\n'.format(line='='*30, text=text) 166 self._log(text) 167 168 def _parse_line(self, line): 169 """Parse the given line from the log. 170 171 Return: 172 A self.ParseResult member. 173 """ 174 raise NotImplementedError 175 176 def _executable_args(self): 177 """Get the executable and necessary arguments as a tuple.""" 178 raise NotImplementedError 179 180 def _default_args(self): 181 """Get the default arguments to use if none were passed to start().""" 182 raise NotImplementedError 183 184 def _get_data(self): 185 """Get the parsed data for this test. 186 187 Also waits for 0.5s to make sure any new data is received. 188 189 Subprocesses are expected to alias this to a public method with a 190 better name. 191 """ 192 self.proc.waitForReadyRead(500) 193 self.read_log() 194 return self._data 195 196 def _wait_signal(self, signal, timeout=5000, raising=True): 197 """Wait for a signal to be emitted. 198 199 Should be used in a contextmanager. 200 """ 201 blocker = pytestqt.wait_signal.SignalBlocker(timeout=timeout, raising=raising) 202 blocker.connect(signal) 203 return blocker 204 205 @pyqtSlot() 206 def read_log(self): 207 """Read the log from the process' stdout.""" 208 if not hasattr(self, 'proc'): 209 # I have no idea how this happens, but it does... 210 return 211 while self.proc.canReadLine(): 212 line = self.proc.readLine() 213 line = bytes(line).decode('utf-8', errors='ignore').rstrip('\r\n') 214 215 try: 216 parsed = self._parse_line(line) 217 except InvalidLine: 218 self._invalid.append(line) 219 self._log("INVALID: {}".format(line)) 220 continue 221 222 if parsed is None: 223 if self._invalid: 224 self._log("IGNORED: {}".format(line)) 225 else: 226 self._data.append(parsed) 227 self.new_data.emit(parsed) 228 229 def start(self, args=None, *, env=None): 230 """Start the process and wait until it started.""" 231 self._start(args, env=env) 232 self._started = True 233 verbose = self.request.config.getoption('--verbose') 234 235 timeout = 60 if testutils.ON_CI else 20 236 for _ in range(timeout): 237 with self._wait_signal(self.ready, timeout=1000, 238 raising=False) as blocker: 239 pass 240 241 if not self.is_running(): 242 if self.exit_expected: 243 return 244 # _start ensures it actually started, but it might quit shortly 245 # afterwards 246 raise ProcessExited('\n' + _render_log(self.captured_log, 247 verbose=verbose)) 248 249 if blocker.signal_triggered: 250 self._after_start() 251 return 252 253 raise WaitForTimeout("Timed out while waiting for process start.\n" + 254 _render_log(self.captured_log, verbose=verbose)) 255 256 def _start(self, args, env): 257 """Actually start the process.""" 258 executable, exec_args = self._executable_args() 259 if args is None: 260 args = self._default_args() 261 262 procenv = QProcessEnvironment.systemEnvironment() 263 if env is not None: 264 for k, v in env.items(): 265 procenv.insert(k, v) 266 267 self.proc.readyRead.connect(self.read_log) 268 self.proc.setProcessEnvironment(procenv) 269 self.proc.start(executable, exec_args + args) 270 ok = self.proc.waitForStarted() 271 assert ok 272 assert self.is_running() 273 274 def _after_start(self): 275 """Do things which should be done immediately after starting.""" 276 277 def before_test(self): 278 """Restart process before a test if it exited before.""" 279 self._invalid = [] 280 if not self.is_running(): 281 self.start() 282 283 def after_test(self): 284 """Clean up data after each test. 285 286 Also checks self._invalid so the test counts as failed if there were 287 unexpected output lines earlier. 288 """ 289 __tracebackhide__ = lambda e: e.errisinstance(ProcessExited) 290 self.captured_log = [] 291 if self._invalid: 292 # Wait for a bit so the full error has a chance to arrive 293 time.sleep(1) 294 # Exit the process to make sure we're in a defined state again 295 self.terminate() 296 self.clear_data() 297 raise InvalidLine('\n' + '\n'.join(self._invalid)) 298 299 self.clear_data() 300 if not self.is_running() and not self.exit_expected and self._started: 301 raise ProcessExited 302 self.exit_expected = False 303 304 def clear_data(self): 305 """Clear the collected data.""" 306 self._data.clear() 307 308 def terminate(self): 309 """Clean up and shut down the process.""" 310 if not self.is_running(): 311 return 312 313 if quteutils.is_windows: 314 self.proc.kill() 315 else: 316 self.proc.terminate() 317 318 ok = self.proc.waitForFinished(5000) 319 if not ok: 320 cmdline = ' '.join([self.proc.program()] + self.proc.arguments()) 321 warnings.warn(f"Test process {cmdline} with PID {self.proc.processId()} " 322 "failed to terminate!") 323 self.proc.kill() 324 self.proc.waitForFinished() 325 326 def is_running(self): 327 """Check if the process is currently running.""" 328 return self.proc.state() == QProcess.Running 329 330 def _match_data(self, value, expected): 331 """Helper for wait_for to match a given value. 332 333 The behavior of this method is slightly different depending on the 334 types of the filtered values: 335 336 - If expected is None, the filter always matches. 337 - If the value is a string or bytes object and the expected value is 338 too, the pattern is treated as a glob pattern (with only * active). 339 - If the value is a string or bytes object and the expected value is a 340 compiled regex, it is used for matching. 341 - If the value is any other type, == is used. 342 343 Return: 344 A bool 345 """ 346 regex_type = type(re.compile('')) 347 if expected is None: 348 return True 349 elif isinstance(expected, regex_type): 350 return expected.search(value) 351 elif isinstance(value, (bytes, str)): 352 return testutils.pattern_match(pattern=expected, value=value) 353 else: 354 return value == expected 355 356 def _wait_for_existing(self, override_waited_for, after, **kwargs): 357 """Check if there are any line in the history for wait_for. 358 359 Return: either the found line or None. 360 """ 361 for line in self._data: 362 matches = [] 363 364 for key, expected in kwargs.items(): 365 value = getattr(line, key) 366 matches.append(self._match_data(value, expected)) 367 368 if after is None: 369 too_early = False 370 else: 371 too_early = ((line.timestamp, line.msecs) < 372 (after.timestamp, after.msecs)) 373 374 if (all(matches) and 375 (not line.waited_for or override_waited_for) and 376 not too_early): 377 # If we waited for this line, chances are we don't mean the 378 # same thing the next time we use wait_for and it matches 379 # this line again. 380 line.waited_for = True 381 self._log("\n----> Already found {!r} in the log: {}".format( 382 kwargs.get('message', 'line'), line)) 383 return line 384 return None 385 386 def _wait_for_new(self, timeout, do_skip, **kwargs): 387 """Wait for a log message which doesn't exist yet. 388 389 Called via wait_for. 390 """ 391 __tracebackhide__ = lambda e: e.errisinstance(WaitForTimeout) 392 message = kwargs.get('message', None) 393 if message is not None: 394 elided = quteutils.elide(repr(message), 100) 395 self._log("\n----> Waiting for {} in the log".format(elided)) 396 397 spy = QSignalSpy(self.new_data) 398 elapsed_timer = QElapsedTimer() 399 elapsed_timer.start() 400 401 while True: 402 # Skip if there are pending messages causing a skip 403 self._maybe_skip() 404 got_signal = spy.wait(timeout) 405 if not got_signal or elapsed_timer.hasExpired(timeout): 406 msg = "Timed out after {}ms waiting for {!r}.".format( 407 timeout, kwargs) 408 if do_skip: 409 pytest.skip(msg) 410 else: 411 raise WaitForTimeout(msg) 412 413 match = self._wait_for_match(spy, kwargs) 414 if match is not None: 415 if message is not None: 416 self._log("----> found it") 417 return match 418 419 raise quteutils.Unreachable 420 421 def _wait_for_match(self, spy, kwargs): 422 """Try matching the kwargs with the given QSignalSpy.""" 423 for args in spy: 424 assert len(args) == 1 425 line = args[0] 426 427 matches = [] 428 429 for key, expected in kwargs.items(): 430 value = getattr(line, key) 431 matches.append(self._match_data(value, expected)) 432 433 if all(matches): 434 # If we waited for this line, chances are we don't mean the 435 # same thing the next time we use wait_for and it matches 436 # this line again. 437 line.waited_for = True 438 return line 439 return None 440 441 def _maybe_skip(self): 442 """Can be overridden by subclasses to skip on certain log lines. 443 444 We can't run pytest.skip directly while parsing the log, as that would 445 lead to a pytest.skip.Exception error in a virtual Qt method, which 446 means pytest-qt fails the test. 447 448 Instead, we check for skip messages periodically in 449 QuteProc._maybe_skip, and call _maybe_skip after every parsed message 450 in wait_for (where it's most likely that new messages arrive). 451 """ 452 453 def wait_for(self, timeout=None, *, override_waited_for=False, 454 do_skip=False, divisor=1, after=None, **kwargs): 455 """Wait until a given value is found in the data. 456 457 Keyword arguments to this function get interpreted as attributes of the 458 searched data. Every given argument is treated as a pattern which 459 the attribute has to match against. 460 461 Args: 462 timeout: How long to wait for the message. 463 override_waited_for: If set, gets triggered by previous messages 464 again. 465 do_skip: If set, call pytest.skip on a timeout. 466 divisor: A factor to decrease the timeout by. 467 after: If it's an existing line, ensure it's after the given one. 468 469 Return: 470 The matched line. 471 """ 472 __tracebackhide__ = lambda e: e.errisinstance(WaitForTimeout) 473 474 if timeout is None: 475 if do_skip: 476 timeout = 2000 477 elif testutils.ON_CI: 478 timeout = 15000 479 else: 480 timeout = 5000 481 482 timeout //= divisor 483 484 if not kwargs: 485 raise TypeError("No keyword arguments given!") 486 for key in kwargs: 487 assert key in self.KEYS 488 489 existing = self._wait_for_existing(override_waited_for, after, 490 **kwargs) 491 if existing is not None: 492 return existing 493 else: 494 return self._wait_for_new(timeout=timeout, do_skip=do_skip, 495 **kwargs) 496 497 def ensure_not_logged(self, delay=500, **kwargs): 498 """Make sure the data matching the given arguments is not logged. 499 500 If nothing is found in the log, we wait for delay ms to make sure 501 nothing arrives. 502 """ 503 __tracebackhide__ = lambda e: e.errisinstance(BlacklistedMessageError) 504 try: 505 line = self.wait_for(timeout=delay, override_waited_for=True, 506 **kwargs) 507 except WaitForTimeout: 508 return 509 else: 510 raise BlacklistedMessageError(line) 511 512 def wait_for_quit(self): 513 """Wait until the process has quit.""" 514 self.exit_expected = True 515 with self._wait_signal(self.proc.finished, timeout=15000): 516 pass 517 assert not self.is_running() 518