Live logs questions

[aaltat]

Our test automation is contains test which are more acceptance/end to end test like, than traditional unit tests. Also these test contains quite a lot of logging, so that they are easy to debug when errors do happen. If I want logging to logged without buffering to the console,, I need to enable live logging and from pytest.main(), I have these arguments defined: -o, log_cli=True, -o, log_cli_level=INFO, -o, log_cli_date_format=%Y-%m-%d %H:%M:%S, -o, log_cli_format=%(asctime)s,%(msecs)d [%(levelname)s] %(name)s: %(message)s. When I run this tests:

import logging
import time

log = logging.getLogger(__file__)


def test_01():
    time.sleep(5)
    log.info('This is from test01')
    time.sleep(5)
    log.info('This is from test01')
    time.sleep(3)
    assert True

Then I get this output:

------------------------------------------------------------- live log call --------------------------------------------------------------
2020-03-02 22:54:08,936 [INFO   ] C:\repo\test_pytest.py: This is from test01
2020-03-02 22:54:13,464 [INFO   ] C:\repo\test_pytest.py: This is from test01
PASSED                                                                                                                               [1/3]C:\repo\test_pytest.py: This is from test01
C:\repo\test_pytest.py: This is from test01

1. The logging from the test is show two times in the console. Once part of the live log and second time after a test is run. Is there way to prevent logging to happen two times and only preserve logs from live logs? When test is run in CI, I would like to follow in real time how test execution is proceeding, but I would like to prevent logging to happen two times.

2. If the above is someway possible is it someway possible to prevent those -- live log call -- lines to be present in the console logs?

[aaltat]

I found a solution to first question. I was missing -s from the command line options. When added logging looks like this:

src/ccfpsb/tests/test_pytest.py::test_01
------------------------------------------------------------- live log call --------------------------------------------------------------
2020-03-03 19:20:15,578 [       INFO    ] C:\repo\test_pytest.py: This is from test01
2020-03-03 19:20:16,578 [       INFO    ] C:\repo\test_pytest.py: This is from test01
PASSED

Only the the second question remains, is there way to get rid of -- live log call -- lines from the console?

[twmr]

I don't understand why you had to add -s to fix the issue with the double-output. I've just tested it and the output looks good when I call pytest with --log-cli-level=DEBUG filename.

May I ask, why don't you like the -- live log xxx -- messages in the live log output and why can't you use the logs that are written to a file using --log-file=...?

[aaltat]

You are right it was not about -s. I had some code which did add custom root logger handing in one of the my helper modules. Setting that logging caused duplication in the console when running pytest. In short my code in the helper module looked like this:

console = logging.StreamHandler(sys.__stderr__)
console.setFormatter(logging.Formatter("%(name)s: %(message)s"))
console.setLevel(logging.INFO)
logging.root.addHandler(console)
logfile = logging.FileHandler("logfile.log")
logfile.setFormatter(logging.Formatter("%(asctime)s [%(levelname)-8s] %(name)s: %(message)s"))
logging.root.addHandler(logfile)

I have a need for both console logging and log file. When I run my tests in CI, I sometimes want the look the CI console, so that I can follow the progress of the test (example after fixing test or for some other monitoring/debug purpose.) Also I was that logging happens only in the info level to the console. But I also want the log file mainly for two purposes. 1) log file contains logging from other levels too, which may reveal problems better. 2) It is useful to read the test log file and the application logs side by side in a editor. It eases the debugging of the problem.

But after looking at the console logs for few days, in the current format, I have started to like it. It helps to separate the test flow better (setups, running test and tear downs.) So I guess it is OK as it is and not to have configurable option for it.

[aaltat]

Did forget to say that I am happy with the current situation and from my point of view issue can be closed. Unless you want to investigate why that root logger changes causes extra logging.

[aaltat]

Wanted to ask one other thing. I have grown to like the live logging, it is a very nice feature, because it separates the tests from each other. Example live logs output this:

PASSED                                                                  [ 2/12]
path/to/test.py::TestClass::test_00
------------------------------- live log setup --------------------------------
2020-03-16 19:28:00,157 [INFO    ] tests.config: Set something.
-------------------------------- live log call --------------------------------
2020-03-16 19:28:00,172 [INFO    ] test: Test something.
PASSED                                                                  [ 3/12]

And I also divert the output to a log file, with these options: -o, log_file_format=%(asctime)s,%(msecs)-3d [%(levelname)-8s] %(name)s: %(message)s, -o, log_file_date_format=%Y-%m-%d %H:%M:%S, -o, log_file=test.log, -o, log_file_level=DEBUG, -o, console_output_style=count Then then the test.log file contains only:

2020-03-16 19:28:00,157 [INFO    ] tests.config: Set something.
2020-03-16 19:28:00,172 [INFO    ] test: Test something.

lines from the above console output. But is there way to divert those logging which is automatically generated by live logs to also to log file? I write a plugin which calls python logger and sends similar information, but then information duplicated in the console. Which cluttered the console output and did not look nice. So would there be way to divert information to the log file?

[twmr]

Nice, that you like the live logging feature. I use it daily and also like it a lot.

Currently it is not possible to have a similar (to live-log) looking output in the logfile, but I would highly appreciate if the separators + testnames were added to the log file.

[twmr]

Here is a quick and dirty patch that adds the separators to the log-files:

diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py
index 5e60a2321..e2295e8c1 100644
--- a/src/_pytest/logging.py
+++ b/src/_pytest/logging.py
@@ -479,6 +479,47 @@ def pytest_configure(config):
     config.pluginmanager.register(LoggingPlugin(config), "logging-plugin")
 
 
+class LoggingFileHandler(logging.FileHandler):
+
+    def __init__(self, fname, capture_manager):
+        super().__init__(fname, mode='w', encoding='UTF-8')
+        self.capture_manager = capture_manager
+        self._first_record_emitted = False
+        self._when = None
+        self._section_name_shown = False
+        self._test_outcome_written = False
+
+    def reset(self):
+        """Reset the handler; should be called before the start of each test"""
+        self._first_record_emitted = False
+
+    def set_when(self, when):
+        """Prepares for the given test phase (setup/call/teardown)"""
+        self._when = when
+        self._section_name_shown = False
+        if when == "start":
+            self._test_outcome_written = False
+
+    def emit(self, record):
+        ctx_manager = (
+            self.capture_manager.global_and_fixture_disabled()
+            if self.capture_manager
+            else nullcontext()
+        )
+        with ctx_manager:
+            if not self._first_record_emitted:
+                self.stream.write("\n")
+                self._first_record_emitted = True
+            elif self._when in ("teardown", "finish"):
+                if not self._test_outcome_written:
+                    self._test_outcome_written = True
+                    self.stream.write("\n")
+            if not self._section_name_shown and self._when:
+                self.stream.write("---live log {}---\n".format(self._when))
+                self._section_name_shown = True
+            logging.StreamHandler.emit(self, record)
+
+
 class LoggingPlugin:
     """Attaches to the logging module and captures log messages for each test.
     """
@@ -516,9 +557,10 @@ class LoggingPlugin:
 
         log_file = get_option_ini(config, "log_file")
         if log_file:
-            self.log_file_handler = logging.FileHandler(
-                log_file, mode="w", encoding="UTF-8"
-            )  # type: Optional[logging.FileHandler]
+            capture_manager = config.pluginmanager.get_plugin("capturemanager")
+
+            self.log_file_handler = LoggingFileHandler(
+                log_file, capture_manager)
             self.log_file_handler.setFormatter(self.log_file_formatter)
         else:
             self.log_file_handler = None
@@ -590,8 +632,11 @@ class LoggingPlugin:
         if not fname.parent.exists():
             fname.parent.mkdir(exist_ok=True, parents=True)
 
-        self.log_file_handler = logging.FileHandler(
-            str(fname), mode="w", encoding="UTF-8"
+        config = self._config
+        capture_manager = config.pluginmanager.get_plugin("capturemanager")
+
+        self.log_file_handler = LoggingFileHandler(
+            str(fname), capture_manager
         )
         self.log_file_handler.setFormatter(self.log_file_formatter)
 
@@ -610,6 +655,7 @@ class LoggingPlugin:
                 self.log_cli_handler.set_when("collection")
 
             if self.log_file_handler is not None:
+                self.log_file_handler.set_when("collection")
                 with catching_logs(self.log_file_handler, level=self.log_file_level):
                     yield
             else:
@@ -634,6 +680,8 @@ class LoggingPlugin:
         ) as log_handler:
             if self.log_cli_handler:
                 self.log_cli_handler.set_when(when)
+            if self.log_file_handler:
+                self.log_file_handler.set_when(when)
 
             if item is None:
                 yield  # run the test
@@ -694,6 +742,7 @@ class LoggingPlugin:
                 self.log_cli_handler.set_when("sessionfinish")
             if self.log_file_handler is not None:
                 try:
+                    self.log_file_handler.set_when("sessionfinish")
                     with catching_logs(
                         self.log_file_handler, level=self.log_file_level
                     ):
@@ -711,6 +760,7 @@ class LoggingPlugin:
             if self.log_cli_handler:
                 self.log_cli_handler.set_when("sessionstart")
             if self.log_file_handler is not None:
+                self.log_file_handler.set_when("sessionstart")
                 with catching_logs(self.log_file_handler, level=self.log_file_level):
                     yield
             else:

The new LoggingFileHandler class is basically the same as the _LiveLoggingStreamHandler class. This should be cleaned up.

[aaltat]

Oh cool. I looked code for while and I had no idea where to start... I can try those changes in my installation and see how it looks like.

[aaltat]

It worked and looks good. It makes a big difference, at least for me, when reading logs from the file. Now different test sections are clearly visible. Also the test report is in the log file which is nice enhancement.

Would be too much to ask if the test count and name would be also visible in the log? Something like this:

PASSED                                                                  [ 2/12]
path/to/test.py::TestClass::test_00

[aaltat]

I looked at the code and found a way to get the test name in the output file:

diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py
index 5e60a2321..21832ffc7 100644
--- a/src/_pytest/logging.py
+++ b/src/_pytest/logging.py
@@ -479,6 +479,51 @@ def pytest_configure(config):
     config.pluginmanager.register(LoggingPlugin(config), "logging-plugin")
 
 
+class LoggingFileHandler(logging.FileHandler):
+
+    def __init__(self, fname, capture_manager):
+        super().__init__(fname, mode='w', encoding='UTF-8')
+        self.capture_manager = capture_manager
+        self._first_record_emitted = False
+        self._when = None
+        self._item = None
+        self._section_name_shown = False
+        self._test_outcome_written = False
+
+    def reset(self):
+        """Reset the handler; should be called before the start of each test"""
+        self._first_record_emitted = False
+
+    def set_when(self, when, item=None):
+        """Prepares for the given test phase (setup/call/teardown)"""
+        self._when = when
+        self._item = item
+        self._section_name_shown = False
+        if when == "start":
+            self._test_outcome_written = False
+
+    def emit(self, record):
+        ctx_manager = (
+            self.capture_manager.global_and_fixture_disabled()
+            if self.capture_manager
+            else nullcontext()
+        )
+        with ctx_manager:
+            if not self._first_record_emitted:
+                self.stream.write("\n")
+                self._first_record_emitted = True
+            elif self._when in ("teardown", "finish"):
+                if not self._test_outcome_written:
+                    self._test_outcome_written = True
+                    self.stream.write("\n")
+            if not self._section_name_shown and self._when:
+                if self._item is not None:
+                    self.stream.write("{}\n".format(self._item.nodeid))
+                self.stream.write("---- live log {} ----\n".format(self._when))
+                self._section_name_shown = True
+            logging.StreamHandler.emit(self, record)
+
+
 class LoggingPlugin:
     """Attaches to the logging module and captures log messages for each test.
     """
@@ -516,9 +561,9 @@ class LoggingPlugin:
 
         log_file = get_option_ini(config, "log_file")
         if log_file:
-            self.log_file_handler = logging.FileHandler(
-                log_file, mode="w", encoding="UTF-8"
-            )  # type: Optional[logging.FileHandler]
+            capture_manager = config.pluginmanager.get_plugin("capturemanager")
+
+            self.log_file_handler = LoggingFileHandler(log_file, capture_manager)
             self.log_file_handler.setFormatter(self.log_file_formatter)
         else:
             self.log_file_handler = None
@@ -590,9 +635,9 @@ class LoggingPlugin:
         if not fname.parent.exists():
             fname.parent.mkdir(exist_ok=True, parents=True)
 
-        self.log_file_handler = logging.FileHandler(
-            str(fname), mode="w", encoding="UTF-8"
-        )
+        config = self._config
+        capture_manager = config.pluginmanager.get_plugin("capturemanager")
+        self.log_file_handler = LoggingFileHandler(str(fname), capture_manager)
         self.log_file_handler.setFormatter(self.log_file_formatter)
 
     def _log_cli_enabled(self):
@@ -610,6 +655,7 @@ class LoggingPlugin:
                 self.log_cli_handler.set_when("collection")
 
             if self.log_file_handler is not None:
+                self.log_file_handler.set_when("collection")
                 with catching_logs(self.log_file_handler, level=self.log_file_level):
                     yield
             else:
@@ -634,6 +680,8 @@ class LoggingPlugin:
         ) as log_handler:
             if self.log_cli_handler:
                 self.log_cli_handler.set_when(when)
+            if self.log_file_handler:
+                self.log_file_handler.set_when(when, item)
 
             if item is None:
                 yield  # run the test
@@ -694,6 +742,7 @@ class LoggingPlugin:
                 self.log_cli_handler.set_when("sessionfinish")
             if self.log_file_handler is not None:
                 try:
+                    self.log_file_handler.set_when("sessionfinish")
                     with catching_logs(
                         self.log_file_handler, level=self.log_file_level
                     ):
@@ -711,6 +760,7 @@ class LoggingPlugin:
             if self.log_cli_handler:
                 self.log_cli_handler.set_when("sessionstart")
             if self.log_file_handler is not None:
+                self.log_file_handler.set_when("sessionstart")
                 with catching_logs(self.log_file_handler, level=self.log_file_level):
                     yield
             else:

Need to think where I can found the status and test counts.

[aaltat]

I have an idea how to make this happen and I looked the existing tests on the area how to test this. But I have an question about configuration and I do not know how this change should be done in this project. Because this enhancement can/will change what gets logged in the output file, should this be behind configurable option (if yes, should it be enabled or disabled by default), or should this just be enabled and do not provide any ways to configure it, or perhaps some way bundle this with existing options (no idea what it could be)?

[RonnyPfannschmidt]

i believe for correctness, this should be set/unset by the catching_logs context manager
i'll need a good sleep on the api/ux implications for the rest