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