Pytest's caplog fixture doesn't seem to work #59
Comments
|
Lovely bug report, thanks! 😃 I guess the I can think of three possible solutions, but this should be done on the user side:
What do you think? |
|
Ah, I wasn't aware the Anyway, between the 3 I'm thinking the easiest one would be the 3rd option. I'll see what I can come up with and, if I find something, submit a PR to update docs with the results. |
Well, this is actually not stated explicitly anywhere as far as I know. Good catch, I should add a word about this.
Would fit pretty well in the documentation page about migrating from Do you think using the sample in the Readme would work for your tests? class PropagateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
logger.add(PropagateHandler(), format="{message}") |
I'll look into it. I was actually just writing up a quick update with the following that works to first order.: import pytest
import logging
_logger = logging.getLogger()
from loguru import logger
def handle(msg):
# Convert to the loglevel, assume DEBUG for TRACE and SUCCESS custom levels.
level = getattr(logging, msg.record['level'], 10)
message = msg.record['message']
_logger.log(level, message)
# add a sink to logger to propogate lots to standard logging logger.
logger.add(handle)
... # rest of the code from this Issue |
|
Looks like adding this to import logging
import pytest
from _pytest.logging import caplog as _caplog
from loguru import logger
@pytest.fixture
def caplog(_caplog):
class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
logger.add(PropogateHandler(), format="{message}")
yield _caplogTechnically you don't even need to add @pytest.fixture
def caplog(caplog):but I really don't like that naming collision. I'll write up some docs for it come Monday or Tuesday and submit the PR. Discussion can continue there. |
|
That's great, thanks @dougthor42! I think you should maybe handler_id = logger.add(PropogateHandler(), format="{message}")
yield _caplog
logger.remove(handler_id) |
|
I wasn't able to force it to add multiple sinks, but I agree that explicitly removing it after is the safe way to go. I'll make sure to include that. |
|
Do you think it makes sense for loguru to ship a pytest plugin that would do this? (I just came here from the docs, have not read up on it, but think it is possible, and would be willing to do it) |
|
Hi @blueyed.
Thanks for your proposition. However, I don't wish for Loguru to expose such plugin, the code snippet in the documentation is sufficient enough as a workaround. |
|
Cool. |
|
@blueyed Improvements of the documentation are much welcome, thanks! |
|
@dougthor42, is there a way to configure the handler to emit the loguru message without it adding it's own info to the string? What I'm doing atm is the following: class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
@pytest.fixture(scope="session", autouse=True)
def setup_logging_for_pytest():
logger.remove()
print("hallo")
_ = logger.add(PropogateHandler(), format=(Unstructured.construct()).fmt)But my logs end up looking like this: |
|
My guess is that the issue comes from |
|
The import re
from typing import Literal, Optional, Pattern
from loguru import logger
from pydantic import AnyUrl, BaseModel, ValidationError, parse_obj_as, validator
from prometheus_adaptive_cards.config.settings_raw import setup_raw_settingsThe settings class: class Unstructured(BaseModel):
fmt: str = "<green>{time:HH:mm:ss}</green> <level>{level}</level> <cyan>{module}:{function}:{line}</cyan> {message} <dim>{extra}</dim>"
colorize: bool = TrueWhen I try to print the record msg I see the actual string I would like to see. It seems like the class PropogateHandler(logging.Handler):
def emit(self, record):
print(record.getMessage())
logging.getLogger(record.name).handle(record) |
|
But I guess it's not that big of a deal. When I initialize the logging in the conftest just like I would in my application main and then run pytest from the CLI I can see the logs captured in the stdout section in addition to the mangled logs in the cap log section |
|
Ah ok. Yes, your format string looks fine. Well, I don't know exactly why, but you need to set your formatter on the class PropogateHandler(logging.Handler):
def emit(self, record):
# Set the formatter on the PropogateHandler
self.setFormatter(logging.Formatter(fmt=Unstructured.construct()).fmt))
logging.getLogger(record.name).handle(record)and when adding the sink to loguru, set the format to just the message: _ = logger.add(PropogateHandler(), format="{message}")I wonder if this (setting the PropogateHandler formatter) is the more general solution, meaning docs should be updated. Full ExampleThis shows that I'm able to duplicate your results: # test_2.py
import logging
import pytest
from loguru import logger
# same as Unstructured.construct()).fmt
m = (
"<green>{time:HH:mm:ss}</green>"
" <level>{level}</level>"
" <cyan>{module}:{function}:{line}</cyan>"
" {message}"
" <dim>{extra}</dim>"
)
class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
@pytest.fixture(scope="session", autouse=True)
def setup_logging_for_pytest():
logger.remove()
print("hallo")
_ = logger.add(PropogateHandler(), format=m)
def test_a():
logger.debug("foo")
assert FalseMake the changesdiff --git a/test_2.py b/test_2.py
index 887804d..4e878c2 100644
--- a/test_2.py
+++ b/test_2.py
@@ -16,6 +16,7 @@ m = (
class PropogateHandler(logging.Handler):
def emit(self, record):
+ self.setFormatter(logging.Formatter(fmt=m))
logging.getLogger(record.name).handle(record)
@@ -24,7 +25,7 @@ def setup_logging_for_pytest():
logger.remove()
print("hallo")
- _ = logger.add(PropogateHandler(), format=m)
+ _ = logger.add(PropogateHandler(), format="{message}")
def test_a():And see that things are no longer duplicated: |
|
I see, completely missed that we can set the formatter on
Here's the output: |
|
Hi! Maybe I can help you clarify. Loguru will first create the string according to it's own logger.add(PropagateHandler(), format="[{{time:HH:mm:ss}}] {message}")
logger.info("Test")
# => '[22:12:08] Test'Then, the formatted message is sent to the log_record = LogRecord(msg="[22:12:08] Test", level="INFO", ...)If no Formatter().format(log_record)
# => '[22:12:08] Test'Supposing you use a custom Formatter("%(asctime)s %(message)s").format(log_record)
# => '2020-11-10 22:12:08,312 [22:12:08] Test'However, you can't the |
|
What am I even trying to achieve 🤔 Okay so thanks to @Delgan's post I managed to propagate Loguru's formatted message 1:1 to a Python logger which then outputs it to std error and Pytest seems to capture it. Here is the full script based on @dougthor42: import logging
import pytest
from loguru import logger
# same as Unstructured.construct()).fmt
m = (
"<green>{time:HH:mm:ss}</green>"
" <level>{level}</level>"
" <cyan>{module}:{function}:{line}</cyan>"
" {message}"
" <dim>{extra}</dim>"
)
pytest_logger = logging.getLogger("pytest")
ch = logging.StreamHandler()
ch.setFormatter(logging.Formatter('%(message)s'))
pytest_logger.addHandler(ch)
pytest_logger.propagate = False
class PropogateHandler(logging.Handler):
def emit(self, record):
pytest_logger.handle(record)
@pytest.fixture(scope="session", autouse=True)
def setup_logging_for_pytest():
logger.remove()
_ = logger.add(PropogateHandler(), format=m)
def test_a():
logger.debug("foo")
assert FalseNotice that I set Here is the output: Here is how the output looks like when I enable propagation: I don't know why pytest does not recognize it as a log call in the propagation deactivated example, but I'm happy with it ending up in stderr as well. Though I would like to Edit: Simplified example a bit |
|
Okay nevermind Pytest has it's own log format configuration 🤦♂️ |
It sounds like you're just interested in having pytest capture log output on failures. Is that correct? If so, none of this from loguru import logger
def test_foo():
print("hallo")
logger.debug("foo")
assert FalseThe core of this issue is specific to pytest's from loguru import logger
def test_foo(caplog):
print("hallo")
logger.debug("foo")
assert "foo" in caplog.text" # This won't work without the PropogateHandler hack |
|
Hello, i am also have problems with pytest and loguru when try to test function with Now when i try to write test, i also get exceptions like theme author: Also as @dougthor42 mentioned, commenting of Maybe for my task i need Can you give some hint for me:
|
|
Hi @SomeAkk. The However, a little hack is possible to achieve what you want. That is, having a behavior similar to def error_handler(message):
exc = message.record["exception"]
if exc is not None:
_, val, _ = exc
raise val
# Add this during testing
logger.add(error_handler, catch=False) |
|
@Delgan looks great - test is passed, thx for that hack One minor problem that all error backtrace is fall in std, but not critical at all i thing: |
|
@SomeAkk Maybe that is because of the other configured handler that you would first need to |
|
Thank you all for code samples, they're incredibly useful. I just want to share my own, in case any of you find it useful: # conftest.py
import logging
import pytest
from loguru import logger
@pytest.fixture
def caplog(caplog):
"""
override and wrap the caplog fixture with one of our own
"""
logger.remove() # remove default handler, if it exists
logger.enable("") # enable all logs from all modules
logging.addLevelName(5, "TRACE") # tell python logging how to interpret TRACE logs
class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
logger.add(PropogateHandler(), format="{message} {extra}", level="TRACE") # shunt logs into the standard python logging machinery
caplog.set_level(0) # Tell logging to handle all log levels
yield caplog |
|
Please, note the documentation has been updated. The recommended way to integrate Loguru with @pytest.fixture
def caplog(caplog):
handler_id = logger.add(caplog.handler, format="{message}")
yield caplog
logger.remove(handler_id)Using |
|
I am trying to use this with multiprocessing, but am not having any luck. Is there something I should be looking out for there? |
@Delgan |
So I've added this snippet to my conftest.py as suggested in the docs, but I notice some interesting behavior where the logger clearly emits the proper level of log, and the expected content, but for some reason is not being interpreted as such by caplog. Pytest Errors> assert caplog.records[0].levelname == 'WARNING'
E AssertionError: assert 'DEBUG' == 'WARNING'
E - WARNING
E + DEBUG
tests/unit/test_csvreader.py:64: AssertionError
----------------------------------- Captured stderr call -----------------------------------
2023-03-28 19:20:50 | WARNING | koza.io.reader.csv_reader | Additional column(s) in source file csv file
{'combined_score'}
Checking if new column(s) inserted at end of the row
...
> assert caplog.records[1].msg.startswith(
'Additional columns located within configured fields'
)
E assert False
E + where False = <built-in method startswith of str object at 0x7f98ee9014d0>('Additional columns located within configured fields')
E + where <built-in method startswith of str object at 0x7f98ee9014d0> = "Additional column(s) in source file csv file\n\t{'cooccurence'}\n\tChecking if new column(s) inserted at end of the row".startswith
E + where "Additional column(s) in source file csv file\n\t{'cooccurence'}\n\tChecking if new column(s) inserted at end of the row" = <LogRecord: koza.io.reader.csv_reader, 30, /mnt/dev/dev/TISLab/koza/src/koza/io/reader/csv_reader.py, 243, "Additional column(s) in source file csv file\n {'cooccurence'}\n Checking if new column(s) inserted at end of the row">.msg
tests/unit/test_csvreader.py:75: AssertionError
----------------------------------- Captured stderr call -----------------------------------
2023-03-28 19:20:50 | WARNING | koza.io.reader.csv_reader | Additional column(s) in source file csv file
{'cooccurence'}
Checking if new column(s) inserted at end of the row
2023-03-28 19:20:50 | WARNING | koza.io.reader.csv_reader | Additional columns located within configured fields
given: ['protein1', 'protein2', 'neighborhood', 'fusion', 'coexpression', 'experimental', 'database', 'textmining', 'combined_score']
found: ['protein1', 'protein2', 'neighborhood', 'fusion', 'cooccurence', 'coexpression', 'experimental', 'database', 'textmining', 'combined_score']
additional columns: {'cooccurence'}I did try to print some contents of caplog to stdout, and apart from the wrong level, it seems like the message is being parsed as not a string? |
|
@glass-ships Please open a new issue with fully reproducible example if possible. |
|
By the way, there is a plugin for that: https://github.com/mcarans/pytest-loguru |
Summary
Pytest's
caplogfixture is a critical part of testing. I'd love to move to loguru, but loguru doesn't seem to work withcaplog.I'm not sure if this is user error (perhaps it's documented somewhere? I haven't been able to find it.), if it is some design oversight/choice, or if the problem is actually on pytest's end.
Expected Result
Users should be able to use
loguruas a drop-in replacement for the stdlibloggingpackage and have tests that use thecaplogfixture still work.Actual Result
Drop-in replacement causes tests that use the
caplogpytest fixture to fail.Steps to Reproduce
Base test file
Without Loguru:
With Loguru:
Adjust
test_demo.pyby commenting out stdlibloggingand uncommentingloguru:Version information
$ python --version Python 3.6.7 (.venv) Previous Dir: /home/dthor 10:10:03 dthor@Thorium /home/dthor/temp/loguru $ pip list Package Version ---------------------- ----------- ansimarkup 1.4.0 atomicwrites 1.3.0 attrs 18.2.0 better-exceptions-fork 0.2.1.post6 colorama 0.4.1 loguru 0.2.5 more-itertools 6.0.0 pip 19.0.3 pkg-resources 0.0.0 pluggy 0.8.1 py 1.8.0 Pygments 2.3.1 pytest 4.3.0 setuptools 40.8.0 six 1.12.0 (.venv) Previous Dir: /home/dthor 10:10:07 dthor@Thorium /home/dthor/temp/loguru $ uname -a Linux Thorium 4.4.0-17763-Microsoft #253-Microsoft Mon Dec 31 17:49:00 PST 2018 x86_64 x86_64 x86_64 GNU/Linux (.venv) Previous Dir: /home/dthor 10:11:33 dthor@Thorium /home/dthor/temp/loguru $ lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionicThe text was updated successfully, but these errors were encountered: