Capturing logs with log_capture in behave #398
Comments
|
Hi @Tsubanee. I'm not familiar with |
|
Behave allows you to write Gherking scenarios (humanlike language) which are connected to python functions, which are executed as tests. from behave.log_capture import LoggingCapture
...
@then("The Hub callback is called")
def step_impl(context):
reg_pattern = "Super Mighty Log Event!!"
# This returns true if reg_pattern is found in captured logs
log_mess = LoggingCapture.find_event(context.log_capture, reg_pattern)
assert log_mess == TrueWhen I run behave with standard logging there are no logs in terminal (everything is captured by behave), and is displayed only in case of failed test. |
|
Thanks for the example! Could that be due to the default |
|
Sorry for the late answer Delgan. I believe I am doing that already :( |
|
Sorry but I'm unable to reproduce your problem. 😬 For example I created a function using Maybe you need to specify |
|
Hmmm, curious. But, have you added any "monkey patching" to the log capturer from |
|
I'm using the snippets you provided. Here are the files: # features/environment.py
from features.fixtures import log_capture_fix
from behave import use_fixture
def before_all(context):
use_fixture(log_capture_fix, context)
context.config.setup_logging()# features/fixtures.py
import logging
from behave import fixture
from loguru import logger
@fixture
def log_capture_fix(context):
class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
logger.remove()
handler_id = logger.add(PropogateHandler(), format="{message} {extra}")
yield context.log_capture
logger.remove(handler_id)# features/tutorial.feature
Feature: showing off behave
Scenario: run a simple test
Given we have behave installed
When we implement a test
Then behave will test it for us!
Then The Hub callback is called# features/steps/tutorial.py
from behave import *
from behave.log_capture import LoggingCapture
def foo():
from loguru import logger
logger.info("Super Mighty Log Event!!")
@given('we have behave installed')
def step_impl(context):
pass
@when('we implement a test')
def step_impl(context):
assert True is not False
@then('behave will test it for us!')
def step_impl(context):
assert context.failed is False
@then("The Hub callback is called")
def step_impl(context):
foo()
reg_pattern = "Super Mighty Log Event!!"
# This returns true if reg_pattern is found in captured logs
log_mess = LoggingCapture.find_event(context.log_capture, reg_pattern)
assert log_mess == TrueResult of Feature: showing off behave # features/tutorial.feature:1
Scenario: run a simple test # features/tutorial.feature:3
Given we have behave installed # features/steps/tutorial.py:10 0.000s
When we implement a test # features/steps/tutorial.py:14 0.000s
Then behave will test it for us! # features/steps/tutorial.py:18 0.000s
Then The Hub callback is called # features/steps/tutorial.py:24 0.000s
1 feature passed, 0 failed, 0 skipped
1 scenario passed, 0 failed, 0 skipped
4 steps passed, 0 failed, 0 skipped, 0 undefined
Took 0m0.001s |
@then("The Hub callback is called")
def step_impl(context):
foo()
reg_pattern = "Super Mighty Log Event!!"
# This returns true if reg_pattern is found in captured logs
log_mess = LoggingCapture.----> log_mess = LoggingCapture.Is this an error in copying the code or do you have it written like that (which I believe is unlikely since it should throw some error I guess). |
|
@Tsubanee Yep, sorry. Failed copy-paste. 🙂 |
|
Tried again in case I missed something, but it still doesn't work. Part of failing behave output: Btw. this is precisely how I use the logger (we have a team specific wrapper): log.py class InterceptHandler(logging.Handler):
def emit(self, record):
# Get corresponding Loguru level if it exists
try:
level = _logger.level(record.levelname).name
except ValueError:
level = record.levelno
# Find caller from where originated the logged message
frame, depth = logging.currentframe(), 2
while frame.f_code.co_filename == logging.__file__:
frame = frame.f_back
depth += 1
_logger.opt(depth=depth, exception=record.exc_info).log(
level, record.getMessage(), extra={"tracking_id": "#"}
)
def init(to_console=True, to_gcp=False, to_file=""):
global _logger, _to_gcp
# fmt = "{time:YYYY-MM-DD HH:mm:ss} | {level} | {extra[tracking_id]} | {message}"
fmt = "{time:YYYY-MM-DD HH:mm:ss} | {level} | # | {message}"
lvl = "INFO"
diag = False
# if already initialised, return
if _logger:
return
if to_gcp:
_logger = setup_gcp_logging()
_to_gcp = True
else:
import loguru
from loguru import logger
_logger = logger
if to_console or to_file:
_logger.remove()
if to_console:
_logger.add(sys.stderr, format=fmt, level=lvl, diagnose=diag, enqueue=True)
if to_file:
_logger.add(to_file, format=fmt, level=lvl, diagnose=diag, enqueue=True)
# intercept all standard logging
logging.basicConfig(handlers=[InterceptHandler()], level=0)
def info(*args, **kwargs):
init()
kwargs = add_tracking_id(kwargs)
return _logger.info(*args, **kwargs)api_utils.py def log_api_state(api_call_id: str, message: str):
log.init()
log_message = f"[{api_call_id}] {message}"
log.info(log_message)Is it alright if I use Maybe I am somehow misusing this, or missing something important? Lemme know if you have any other idea 🚀 . |
|
I don't think using I don't see anything specially wrong in your snippets, but it's hard to tell without knowledge of your code. Do you think it's possible to modify the |
|
Yep, I ll try doing that. |
|
I recreated the scenario from my app (calling the api which has logs), and then added my wrapepr to the logging. Anyway, here is the full test setup that leads to failed test. requirements.txt #tutorial.py
# features/steps/tutorial.py
from behave import *
from behave.log_capture import LoggingCapture
from fastapi.testclient import TestClient
from funcs.main import app
@given("The caller is sync http client")
def step_impl(context):
context.client = TestClient(app)
@when("We call the path")
def step_impl(context):
context.name = "HULK"
context.response = context.client.get(
"/"+context.name
)
@then("We make sure call worked")
def step_impl(context):
assert context.response.status_code == 200
@then("We have Mighty Message in logs")
def step_impl(context):
reg_pattern = f"Supper Mighty {context.name}"
# This returns true if reg_pattern is found in captured logs
log_mess = LoggingCapture.find_event(context.log_capture, reg_pattern)
assert log_mess == True#environment.py
# features/environment.py
from fixtures import log_capture_fix
from behave import use_fixture
def before_all(context):
use_fixture(log_capture_fix, context)
context.config.setup_logging()#features/tutorial.feature
# features/tutorial.feature
Feature: showing off behave
Scenario: run a simple test
Given The caller is sync http client
When We call the path
Then We make sure call worked
Then We have Mighty Message in logs#funcs/log.py
import sys
import datetime
import logging
_logger = None
class InterceptHandler(logging.Handler):
def emit(self, record):
# Get corresponding Loguru level if it exists
try:
level = _logger.level(record.levelname).name
except ValueError:
level = record.levelno
# Find caller from where originated the logged message
frame, depth = logging.currentframe(), 2
while frame.f_code.co_filename == logging.__file__:
frame = frame.f_back
depth += 1
_logger.opt(depth=depth, exception=record.exc_info).log(
level, record.getMessage(), extra={"tracking_id": "#"}
)
def init(to_console=True, to_gcp=False, to_file=""):
global _logger, _to_gcp
# fmt = "{time:YYYY-MM-DD HH:mm:ss} | {level} | {extra[tracking_id]} | {message}"
fmt = "{time:YYYY-MM-DD HH:mm:ss} | {level} | # | {message}"
lvl = "INFO"
diag = False
# if already initialised, return
if _logger:
return
else:
import loguru
from loguru import logger
_logger = logger
if to_console or to_file:
_logger.remove()
if to_console:
_logger.add(sys.stderr, format=fmt, level=lvl, diagnose=diag, enqueue=True)
if to_file:
_logger.add(to_file, format=fmt, level=lvl, diagnose=diag, enqueue=True)
# intercept all standard logging
logging.basicConfig(handlers=[InterceptHandler()], level=0)
def add_tracking_id(kwargs):
if "tracking_id" not in kwargs:
kwargs["tracking_id"] = "#"
return kwargs
def info(*args, **kwargs):
init()
kwargs = add_tracking_id(kwargs)
return _logger.info(*args, **kwargs)
def exception(*args, **kwargs):
init()
kwargs = add_tracking_id(kwargs)
return _logger.exception(*args, **kwargs)
def error(*args, **kwargs):
init()
kwargs = add_tracking_id(kwargs)
return _logger.error(*args, **kwargs)
def debug(*args, **kwargs):
init()
kwargs = add_tracking_id(kwargs)
return _logger.debug(*args, **kwargs)
if __name__ == "__main__":
init()
exception("test")
info("<-- this has tracking", tracking_id="123")#main.py
from fastapi import FastAPI, Path
from funcs.util import log_api
app = FastAPI()
@app.get("/{message}")
async def groot(message = Path(...)):
log_api(f"Supper Mighty {message}")
return {"message": message}#func/util.py
from funcs.log import init, info
def log_api(message):
init()
info(message)funcs/fixtures.py
# features/fixtures.py
import logging
from behave import fixture
from loguru import logger
@fixture
def log_capture_fix(context):
class PropogateHandler(logging.Handler):
def emit(self, record):
logging.getLogger(record.name).handle(record)
logger.remove()
handler_id = logger.add(PropogateHandler(), format="{message} {extra}")
yield context.log_capture
logger.remove(handler_id)Failed test output |
|
Thanks for the reproducible example! From what I understand, the Can you somehow refactor the code to initialize the |
|
Yeah! Right that might be it 🚀 In hindsight it seems kinda obvious 🤦 . Anyway, thank you very much for helping out Delgan. I will fix it tomorrow to run in correct order during tests, and update here how it went (though I wouldn't expect further problems now :D) UPDATE: Yep. Running the init() at the beggining fo the fixture solved the problem. Once again, thank you very much Delgan :D |
|
I'm closing this issue since it's resolved, then. 👍 |
Problem
I run my test with behave (https://behave.readthedocs.io/en/stable/api.html?highlight=log_capture#logging-capture) and after changing to the loguru my tests fail.
I have read this post Issue 59 (regarding basically the same but with pytest), and I understand that loguru doesn't use standardlib logging which behave log capture probably utilizes, and the way to solve the problem is to propagte the logs to the logging lib
however, I don't understand how to replicate the fix.
I tried using the fixture in an analogous way but it didn't seem to work:
Example of what I tried
environment.py
fixtures.py
Could you help me configure this properly, or point me in the right directions?
The text was updated successfully, but these errors were encountered: