Closed dougthor42 closed 5 years ago
Lovely bug report, thanks! 😃
I guess the caplog
fixture makes use of the standard logging
module to capture output. However, as loguru
doesn't rely on the logging
module and instead implement its own loggers / handlers manager, caplog
is not notified of new log entries. For this reason, I don't think there is much I can do about it.
I can think of three possible solutions, but this should be done on the user side:
caplog
with capsys
(but may conflict with actual expected output in stderr
/ stdout
)caplog
with a custom fixture which adds a caputring sink to Loguru's loggerconftest.py
which would propagate logs to a standard logging
loggerWhat do you think?
Ah, I wasn't aware the loguru
didn't use the stdlib logging
module. I guess I could have checked that first...
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.
Ah, I wasn't aware the
loguru
didn't use the stdliblogging
module. I guess I could have checked that first...
Well, this is actually not stated explicitly anywhere as far as I know. Good catch, I should add a word about this.
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.
Would fit pretty well in the documentation page about migrating from logging
to loguru
I think.
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}")
Do you think using the sample in the Readme would work for your tests?
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 conftest.py
works:
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 _caplog
Technically you don't even need to add from _pytest.logging import caplog as _caplog
and can just:
@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 remove()
the added sink at the end of each test. Based on your snippet, I'm wondering if this is not addind a new sink each time you run a test.
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.
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)
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. I might look into this anyway, since the code snippet can be improved in general, and I think it might be useful to expose loguru's data additionally.. will likely come back to this later then.
@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:
--------------------------------- Captured Log ---------------------------------
DEBUG prometheus_adaptive_cards.distribution.utils:utils.py:93 18:13:01 DEBUG utils:extract_url:93 Start to extract url from target config and common attrs. {}
WARNING prometheus_adaptive_cards.distribution.utils:utils.py:134 18:13:01 WARNING utils:extract_url:134 No URL extracted. {'target': {'url': None, 'expansion_url': 'hallo/{common_labels[namespace]}/fefe', 'url_from_label': None, 'url_from_annotation': None}}
--------------------------------- Captured Out ---------------------------------
My guess is that the issue comes from Unstructured.construct()
- where are you pulling that from? Can you show me the imports?
The Unstructured
is part of my settings model, I create an instance to get the default format string I use in the actual application. Here are the imports / the conftest itself:
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_settings
The 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 = True
When I try to print the record msg I see the actual string I would like to see. It seems like the .handle()
call is the culprit.
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 PropogateHandler
rather than on the loguru logger
:
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.
This 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 False
$ pytest test_2.py
========================================================= test session starts =========================================================
platform linux -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
rootdir: /home/dthor/temp/loguru-pytest
collected 1 item
test_2.py F [100%]
============================================================== FAILURES ===============================================================
_______________________________________________________________ test_a ________________________________________________________________
def test_a():
logger.debug("foo")
> assert False
E assert False
test_2.py:32: AssertionError
-------------------------------------------------------- Captured stdout setup --------------------------------------------------------
hallo
---------------------------------------------------------- Captured log call ----------------------------------------------------------
DEBUG test_2:test_2.py:31 11:01:14 DEBUG test_2:test_a:31 foo {}
======================================================= short test summary info =======================================================
FAILED test_2.py::test_a - assert False
========================================================== 1 failed in 0.15s ==========================================================
diff --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:
$ pytest test_2.py
========================================================= test session starts =========================================================
platform linux -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
rootdir: /home/dthor/temp/loguru-pytest
collected 1 item
test_2.py F [100%]
============================================================== FAILURES ===============================================================
_______________________________________________________________ test_a ________________________________________________________________
def test_a():
logger.debug("foo")
> assert False
E assert False
test_2.py:32: AssertionError
-------------------------------------------------------- Captured stdout setup --------------------------------------------------------
hallo
---------------------------------------------------------- Captured log call ----------------------------------------------------------
DEBUG test_2:test_2.py:31 foo
======================================================= short test summary info =======================================================
FAILED test_2.py::test_a - assert False
========================================================== 1 failed in 0.15s ==========================================================
I see, completely missed that we can set the formatter on PropogateHandler
itself. But I've run into two issues:
Here's the output:
============================================= FAILURES =============================================
______________________________________________ test_a ______________________________________________
def test_a():
logger.debug("foo")
> assert False
E assert False
single.py:33: AssertionError
-------------------------------------- Captured stdout setup ---------------------------------------
hallo
--------------------------------------- Captured stderr call ---------------------------------------
--- Logging error in Loguru Handler #1 ---
Record was: {'elapsed': datetime.timedelta(microseconds=14877), 'exception': None, 'extra': {}, 'file': (name='single.py', path='/home/jfn/source/playground/test_loguru_pytest/single.py'), 'function': 'test_a', 'level': (name='DEBUG', no=10, icon='🐞'), 'line': 32, 'message': 'foo', 'module': 'single', 'name': 'single', 'process': (id=943984, name='MainProcess'), 'thread': (id=139993484752704, name='MainThread'), 'time': datetime(2020, 11, 10, 21, 42, 25, 65855, tzinfo=datetime.timezone(datetime.timedelta(seconds=3600), 'CET'))}
Traceback (most recent call last):
File "/home/jfn/.pyenv/versions/3.9.0/lib/python3.9/site-packages/loguru/_handler.py", line 177, in emit
self._sink.write(str_record)
File "/home/jfn/.pyenv/versions/3.9.0/lib/python3.9/site-packages/loguru/_simple_sinks.py", line 60, in write
self._handler.handle(record)
File "/home/jfn/.pyenv/versions/3.9.0/lib/python3.9/logging/__init__.py", line 948, in handle
self.emit(record)
File "/home/jfn/source/playground/test_loguru_pytest/single.py", line 19, in emit
self.setFormatter(logging.Formatter(fmt=m))
File "/home/jfn/.pyenv/versions/3.9.0/lib/python3.9/logging/__init__.py", line 570, in __init__
self._style.validate()
File "/home/jfn/.pyenv/versions/3.9.0/lib/python3.9/logging/__init__.py", line 423, in validate
raise ValueError("Invalid format '%s' for '%s' style" % (self._fmt, self.default_format[0]))
ValueError: Invalid format '<green>{time:HH:mm:ss}</green> <level>{level}</level> <cyan>{module}:{function}:{line}</cyan> {message} <dim>{extra}</dim>' for '%' style
--- End of logging error ---
===================================== short test summary info ======================================
FAILED single.py::test_a - assert False
======================================== 1 failed in 0.07s =========================================
Hi!
Maybe I can help you clarify. Loguru will first create the string according to it's own format
and regardless of the Formatter
from standard logging
.
logger.add(PropagateHandler(), format="[{{time:HH:mm:ss}}] {message}")
logger.info("Test")
# => '[22:12:08] Test'
Then, the formatted message is sent to the PropogateHandler
. To do so, the loguru
record is converted to a standard LogRecord
.
log_record = LogRecord(msg="[22:12:08] Test", level="INFO", ...)
If no Formatter
is assigned to the PropagateHandler
, the standard logging
will use %(message)s
by default and hence display the message according to the loguru
format.
Formatter().format(log_record)
# => '[22:12:08] Test'
Supposing you use a custom Formatter
, you should make sure that the loguru
format is equals to "{message}"
to avoid duplication.
Formatter("%(asctime)s %(message)s").format(log_record)
# => '2020-11-10 22:12:08,312 [22:12:08] Test'
However, you can't the loguru
formatter style (which uses {}
) to configure a standard Formatter
(which uses %
). Also, the fields does not use the same names ("asctime" != "time"
).
What am I even trying to achieve :thinking: 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 False
Notice that I set propagate
to False. Without this the logger seems to propagate the record up. And somewhere "up there" the message gets formatted again.
Here is the output:
❯ pytest single.py
======================================= test session starts ========================================
platform linux -- Python 3.9.0, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
rootdir: /home/jfn/source/playground/test_loguru_pytest
collected 1 item
single.py F [100%]
============================================= FAILURES =============================================
______________________________________________ test_a ______________________________________________
def test_a():
logger.debug("foo")
> assert False
E assert False
single.py:39: AssertionError
-------------------------------------- Captured stdout setup ---------------------------------------
hallo
--------------------------------------- Captured stderr call ---------------------------------------
23:11:04 DEBUG single:test_a:38 foo {}
===================================== short test summary info ======================================
FAILED single.py::test_a - assert False
======================================== 1 failed in 0.06s =========================================
Here is how the output looks like when I enable propagation:
-------------------------------------- Captured stdout setup ---------------------------------------
hallo
--------------------------------------- Captured stderr call ---------------------------------------
23:13:08 DEBUG single:test_a:38 foo {}
---------------------------------------- Captured log call -----------------------------------------
DEBUG single:single.py:38 23:13:08 DEBUG single:test_a:38 foo {}
===================================== short test summary info ======================================
FAILED single.py::test_a - assert False
======================================== 1 failed in 0.07s =========================================
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 23:13:08 DEBUG single:test_a:38 foo {}
show up below Captured log call
Edit: Simplified example a bit
Okay nevermind Pytest has it's own log format configuration :man_facepalming:
What am I even trying to achieve?
It sounds like you're just interested in having pytest capture log output on failures. Is that correct? If so, none of this PropogateHandler
mumbo jumbo needs to be done - pytest will already capture loguru output for tests. The "Captured stderr call" section might not be formatted the same way, but I don't know if that matters to you.
from loguru import logger
def test_foo():
print("hallo")
logger.debug("foo")
assert False
$ pytest test_foo.py
============================================ test session starts =============================================
platform linux -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
rootdir: /home/dthor/temp/loguru-pytest
collected 1 item
test_foo.py F [100%]
================================================== FAILURES ==================================================
__________________________________________________ test_foo __________________________________________________
def test_foo():
print("hallo")
logger.debug("foo")
> assert False
E assert False
test_foo.py:6: AssertionError
-------------------------------------------- Captured stdout call --------------------------------------------
hallo
-------------------------------------------- Captured stderr call --------------------------------------------
2020-11-10 14:32:31.733 | DEBUG | test_foo:test_foo:5 - foo
========================================== short test summary info ===========================================
FAILED test_foo.py::test_foo - assert False
============================================= 1 failed in 0.14s ==============================================
The core of this issue is specific to pytest's caplog
fixture, which you only need if you want to assert what's being logged. Meaning, you need the PropogateHandler
if you want to do this:
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 @logger.catch
decorator. That function can throw exception and by that i need to write some log message. Also I need to test it: want to check if tested function throw any exception.
# tested_function.py
from loguru import logger
@logger.catch(message="oops!", default=False)
def tested_function(a: int, b: int) -> int:
return a/b
Now when i try to write test, i also get exceptions like theme author:
# test_tested_function.py
import pytest
def test():
with pytest.raises(Exception):
_ = tested_function(9, 0)
Also as @dougthor42 mentioned, commenting of @logger.catch(...
help to test function.
I try to add conftest.py
to my test directory with code example like in docs, but that not helped at all.
Maybe for my task i need PropogateHandler
hack too ...
Or i added conftest.py
not in proper places in project and by that this not work ...
Can you give some hint for me:
conftest.py
or PropogateHandler
?PropogateHandler
or fixture from conftest.py
to make test()
working?Hi @SomeAkk.
The catch()
decorator does not propagate exceptions by default. It will simply create a logging record and send it to the handlers as any other logged message. You need to specify reraise=True
if you want to be able to explicitly catch it with try / except
or with pytest.raises()
.
However, a little hack is possible to achieve what you want. That is, having a behavior similar to reraise=False
in production but being able to switch to reraise=True
during testing. Since the message is sent to each configured handler, you can add an error_handler()
sink that will be in charge of re-raising the error. Be careful, it must also be added with the parameter catch=False
parameter because Loguru prevents otherwise the propagation of the error.
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:
============================= test session starts ==============================
platform darwin -- Python 3.7.9, pytest-5.4.3, py-1.9.0, pluggy-0.13.1 -- /Users/SomeAkk/...
cachedir: .pytest_cache
rootdir: ...
collecting ... collected 1 item
test_tested_function.py::Test::test PASSED [100%]
2020-12-04 18:26:04.582 | ERROR | test_tested_function:61 - oops!
Traceback (most recent call last):
File "/Applications/PyCharm.app/.../_jb_pytest_runner.py", line 43, in <module>
sys.exit(pytest.main(args, plugins_to_load + [Plugin]))
│ │ │ │ │ │ └ <class '__main__.Plugin'>
...
... traceback ...
...
ZeroDivisionError: ...
============================== 1 passed in 0.28s ===============================
Process finished with exit code 0
@SomeAkk Maybe that is because of the other configured handler that you would first need to remove()
?
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
is to override the caplog
fixture this way:
@pytest.fixture
def caplog(caplog):
handler_id = logger.add(caplog.handler, format="{message}")
yield caplog
logger.remove(handler_id)
Using PropagateHandler
could result in dead-lock if inadvertently combined with InterceptHandler
see #474.
I am trying to use this with multiprocessing, but am not having any luck. Is there something I should be looking out for there?
Please, note the documentation has been updated. The recommended way to integrate Loguru with
pytest
is to override thecaplog
fixture this way:@pytest.fixture def caplog(caplog): handler_id = logger.add(caplog.handler, format="{message}") yield caplog logger.remove(handler_id)
Using
PropagateHandler
could result in dead-lock if inadvertently combined withInterceptHandler
see #474.
@Delgan Thank you so much! Your snippet helped me avoid deadlock!
Please, note the documentation has been updated. The recommended way to integrate Loguru with
pytest
is to override thecaplog
fixture this way:@pytest.fixture def caplog(caplog): handler_id = logger.add(caplog.handler, format="{message}") yield caplog logger.remove(handler_id)
Using
PropagateHandler
could result in dead-lock if inadvertently combined withInterceptHandler
see #474.
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.
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?
caplog.records[0].msg: headers for csv file parsed as ['protein1', 'protein2', 'neighborhood', 'fusion', 'cooccurence', 'coexpression', 'experimental', 'database', 'textmining', 'combined_score']
caplog.records[0].levelname: DEBUG
@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
caplog
fixture 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
loguru
as a drop-in replacement for the stdliblogging
package and have tests that use thecaplog
fixture still work.Actual Result
Drop-in replacement causes tests that use the
caplog
pytest fixture to fail.Steps to Reproduce
Base test file
Without Loguru:
With Loguru:
Adjust
test_demo.py
by commenting out stdliblogging
and uncommentingloguru
:Version information