Remove logging from tests

[hackebrot]

Should we keep the logging in the tests? Is it strictly necessary?
https://github.com/hackebrot/qutebrowser/blob/master/qutebrowser/test/log.py

@The-Compiler can you please briefly explain your thoughts behind the named module? Am I right that it is only used in the QApplication of the tests?

qutebrowser/test/__init__.py:26:from qutebrowser.test import log
qutebrowser/test/__init__.py:35:log.init()

[nicoddemus]

Let's hear what @The-Compiler has to say, but just to point out we could install pytest-capturelog too.

[The-Compiler]

Qt uses qWarning a lot internally when something is wrong, where Python probably would use exceptions instead - and in qutebrowser, there are some places where I log an error and recover on recoverable exceptions.

Currently those are printed as "LOG WARNING ..." for example, and qutebrowser's buildbot notices that pattern and shows "warnings" instead of "success" (example / stdio).

I think capturelog would be cool for the debug logs, but ideally also tests would show that output (or fail entirely, that works as well), when there's any logging output with level warnings or higher which isn't in a with self.assertLogs(...): (or equivalent) context manager.

[hackebrot]

@nicoddemus Do you think we can imitate the current behaviour with pytest-capturelog ❓

[nicoddemus]

Not directly, because as @The-Compiler mentioned Qt has its own logging system.

I will see the specific uses in the code base, but it seems like the ideal solution would be to implement functionality similar to pytest-capturelog into pytest-qt itself.

[hackebrot]

Should we close this one? 😶

[nicoddemus]

I think the current solution using pytest-capturelog is good enough... @The-Compiler, thoughts?

[The-Compiler]

Hmm, it doesn't seem to work properly so far.

I'd like log outputs in the format LOG warning ... so it gets picked up by the CI and shown as warning if there's any unexpected log output. This format also gets initialized in tests/log.py:init but it doesn't seem to get applied for some reason...

The change I did to get logging:

diff --git a/qutebrowser/utils/utils.py b/qutebrowser/utils/utils.py
index b866420..98b7678 100644
--- a/qutebrowser/utils/utils.py
+++ b/qutebrowser/utils/utils.py
@@ -29,7 +29,7 @@ import functools
 import contextlib
 import itertools

-from PyQt5.QtCore import Qt
+from PyQt5.QtCore import Qt, qWarning
 from PyQt5.QtGui import QKeySequence, QColor
 import pkg_resources

@@ -39,6 +39,8 @@ from qutebrowser.utils import qtutils, log

 def elide(text, length):
     """Elide text so it uses a maximum of length chars."""
+    qWarning("warning")
+    log.misc.error("log")
     if length < 1:
         raise ValueError("length must be >= 1!")
     if len(text) <= length:

The output:

==================================================================== test session starts =====================================================================
platform linux -- Python 3.4.2 -- py-1.4.26 -- pytest-2.7.0
qt-api: pyqt5
rootdir: /home/florian/proj/qutebrowser/git, inifile: tox.ini
plugins: capturelog, qt, mock
warning
log
[...]
collected 1467 items 

[...]
tests/utils/test_utils.py ....................................................................................................

I really don't get what's happening there... why do I get the logging output while collecting the tests?

[nicoddemus]

Hmm is elide being called during parametrization?

[The-Compiler]

It seems it's called when importing stuff (as there's debug logging going on):

  /home/florian/proj/qutebrowser/git/tests/mainwindow/conftest.py(28)<module>()
-> from qutebrowser.config.config import ConfigManager
  <frozen importlib._bootstrap>(2237)_find_and_load()
  <frozen importlib._bootstrap>(2226)_find_and_load_unlocked()
  <frozen importlib._bootstrap>(1200)_load_unlocked()
  <frozen importlib._bootstrap>(1129)_exec()
  <frozen importlib._bootstrap>(1471)exec_module()
  <frozen importlib._bootstrap>(321)_call_with_frames_removed()
  /home/florian/proj/qutebrowser/git/qutebrowser/config/config.py(39)<module>()
-> from qutebrowser.config.parsers import ini, keyconf
  <frozen importlib._bootstrap>(2284)_handle_fromlist()
  <frozen importlib._bootstrap>(321)_call_with_frames_removed()
  <frozen importlib._bootstrap>(2237)_find_and_load()
  <frozen importlib._bootstrap>(2226)_find_and_load_unlocked()
  <frozen importlib._bootstrap>(1200)_load_unlocked()
  <frozen importlib._bootstrap>(1129)_exec()
  <frozen importlib._bootstrap>(1471)exec_module()
  <frozen importlib._bootstrap>(321)_call_with_frames_removed()
  /home/florian/proj/qutebrowser/git/qutebrowser/config/parsers/keyconf.py(55)<module>()
-> class KeyConfigParser(QObject):
  /home/florian/proj/qutebrowser/git/qutebrowser/config/parsers/keyconf.py(154)KeyConfigParser()
-> def bind(self, key, command, *, mode=None, force=False):
  /home/florian/proj/qutebrowser/git/qutebrowser/commands/cmdutils.py(161)__call__()
-> handler=func, **self._kwargs)
  /home/florian/proj/qutebrowser/git/qutebrowser/commands/command.py(117)__init__()
-> count = self._inspect_func()
  /home/florian/proj/qutebrowser/git/qutebrowser/commands/command.py(235)_inspect_func()
-> full=False)
  /home/florian/proj/qutebrowser/git/qutebrowser/utils/debug.py(220)format_call()
-> return '{}({})'.format(name, _format_args(args, kwargs))
  /home/florian/proj/qutebrowser/git/qutebrowser/utils/debug.py(182)_format_args()
-> arglist = [utils.compact_text(repr(arg), 200) for arg in args]
  /home/florian/proj/qutebrowser/git/qutebrowser/utils/debug.py(182)<listcomp>()
-> arglist = [utils.compact_text(repr(arg), 200) for arg in args]
  /home/florian/proj/qutebrowser/git/qutebrowser/utils/utils.py(67)compact_text()
-> out = elide(out, elidelength)
> /home/florian/proj/qutebrowser/git/qutebrowser/utils/utils.py(43)elide()
-> qWarning("warning")

So let's not worry about that - but why doesn't capturelog capture the things logged during the test then?

[nicoddemus]

My guess is that it only displays the logging output if a test fails, which is the same behavior exhibited by pytest regarding stdout/stderr capture.

[The-Compiler]

Oh, right. I considered opening a PR against pytest-capturelog to add something like a --always-print-logs option (ideally with a level what to capture, and a level what to always print), but looking at the PRs and issues it seems all pretty dead...

Maybe that's a good reason to switch to pytest-catchlog then. In the latest commit they even mention:

A far better approach would be to replace this option with an

    --report-logs=[never,failed,always]

option though.

I'll open an issue there to see if using separate levels for that would be a welcome addition and if it's active.

Then the other missing bit would be a message handler for pytest-qt so it uses logging -
@nicoddemus, would you be okay if I opened a PR adding that?

[nicoddemus]

Oh, that might be the reason of why it was forked then.

About logging for pytest-qt, I was thinking to provide a separate fixture similar to caplog (capqt?), and provide a separate output section for Qt messages like this:

-------------------------- Captured Qt ----------------------------
qWarning: Oh noes!
-------------------------- Captured log ---------------------------
test_pytest_catchlog.py    26 INFO     text going to logger
------------------------- Captured stdout -------------------------
text going to stdout
------------------------- Captured stderr -------------------------
text going to stderr
==================== 2 failed in 0.02 seconds =====================

Were you thing along the same lines?

[The-Compiler]

Finally closing this one 😉

[hackebrot]

😤 👍