quteproc: mark expected errors as such

Fixes #1611

This marks errors that are expected by a test with an "(Expected)"
marker and white color (instead of red).

The formatting of the log messages has been deferred to _render_log,
since the .expected attribute is not correctly set right after we read
the message.

tests/end2end/fixtures/quteprocess.py

@@ -92,9 +92,10 @@ class LogLine(testprocess.Line):
         self.message = msg_match.group('message')
 
         self.expected = is_ignored_qt_message(self.message)
+        self.use_color = False
 
     def __str__(self):
-        return self.formatted_str(colorized=False)
+        return self.formatted_str(colorized=self.use_color)
 
     def formatted_str(self, colorized=True):
         """Return a formatted colorized line.
@@ -113,7 +114,18 @@ class LogLine(testprocess.Line):
         r.module = self.module
         r.funcName = self.function
 
-        formatter = log.ColoredFormatter(log.EXTENDED_FMT, log.DATEFMT, '{',
+        format_str = log.EXTENDED_FMT
+        # Mark expected errors with (Expected) so it's less confusing for tests
+        # which expect errors but fail due to other errors.
+        if self.expected and self.loglevel >= log.LOG_LEVELS['ERROR']:
+            new_color = '{' + log.LOG_COLORS['DEBUG'] + '}'
+            format_str = format_str.replace('{log_color}', new_color)
+            format_str = re.sub(r'{levelname:(\d*)}',
+                                # Leave away the padding because (Expected) is
+                                # longer anyway.
+                                r'{levelname} (Expected)', format_str)
+
+        formatter = log.ColoredFormatter(format_str, log.DATEFMT, '{',
                                          use_colors=colorized)
         result = formatter.format(r)
         # Manually append the stringified traceback if one is present
@@ -186,11 +198,8 @@ class QuteProc(testprocess.Process):
             else:
                 raise
 
-        if self._config.getoption('--color') != 'no':
-            line_to_log = log_line.formatted_str()
-        else:
-            line_to_log = log_line.formatted_str(colorized=False)
-        self._log(line_to_log)
+        log_line.use_color = self._config.getoption('--color') != 'no'
+        self._log(log_line)
 
         start_okay_message_load = (
             "load status for <qutebrowser.browser.webview.WebView tab_id=0 "

tests/end2end/fixtures/test_quteprocess.py

@@ -176,11 +176,11 @@ def test_log_line_parse(data, attrs):
         assert actual == expected, name
 
 
-@pytest.mark.parametrize('data, colorized, expected', [
+@pytest.mark.parametrize('data, colorized, expect_error, expected', [
     (
         {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
          'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
-        False,
+        False, False,
         '{timestamp} DEBUG    foo        bar:qux:10 quux',
     ),
     # Traceback attached
@@ -189,7 +189,7 @@ def test_log_line_parse(data, attrs):
          'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux',
          'traceback': 'Traceback (most recent call last):\n    here be '
          'dragons'},
-        False,
+        False, False,
         '{timestamp} DEBUG    foo        bar:qux:10 quux\n'
         'Traceback (most recent call last):\n'
         '    here be dragons',
@@ -198,14 +198,38 @@ def test_log_line_parse(data, attrs):
     (
         {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
          'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
-        True,
+        True, False,
         '\033[32m{timestamp}\033[0m \033[37mDEBUG   \033[0m \033[36mfoo     '
         '   bar:qux:10\033[0m \033[37mquux\033[0m',
     ),
-], ids=['normal', 'traceback', 'colored'])
-def test_log_line_formatted(data, colorized, expected):
+    # Expected error
+    (
+        {'created': 0, 'levelname': 'ERROR', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 40, 'message': 'quux'},
+        False, True,
+        '{timestamp} ERROR (Expected) foo        bar:qux:10 quux',
+    ),
+    # Expected other message (i.e. should make no difference)
+    (
+        {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
+        False, True,
+        '{timestamp} DEBUG    foo        bar:qux:10 quux',
+    ),
+    # Expected error colorized (shouldn't be red)
+    (
+        {'created': 0, 'levelname': 'ERROR', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 40, 'message': 'quux'},
+        True, True,
+        '\033[32m{timestamp}\033[0m \033[37mERROR (Expected)\033[0m \033[36mfoo'
+        '        bar:qux:10\033[0m \033[37mquux\033[0m',
+    ),
+], ids=['normal', 'traceback', 'colored', 'expected error', 'expected other',
+        'expected error colorized'])
+def test_log_line_formatted(data, colorized, expect_error, expected):
     line = json.dumps(data)
     record = quteprocess.LogLine(line)
+    record.expected = expect_error
     ts = datetime.datetime.fromtimestamp(data['created']).strftime('%H:%M:%S')
     expected = expected.format(timestamp=ts)
     assert record.formatted_str(colorized=colorized) == expected

tests/end2end/fixtures/testprocess.py

@@ -78,6 +78,7 @@ class Line:
 def _render_log(data, threshold=100):
     """Shorten the given log without -v and convert to a string."""
     # pylint: disable=no-member
+    data = [str(d) for d in data]
     is_exception = any('Traceback (most recent call last):' in line
                        for line in data)
     if (len(data) > threshold and