Logging within the environment.py and Fixtures.py doesn't output

[MichaelAGill]

I have tried using context.log(), and I have tried creating my own logger, faffing around with the BasicConfig() with and without formatters. But I cannot get logs within the environment.py or fixtures.py to output to the console.

Is this possible? I would like it for both debugging and general logging purposes. However, if there is an error within these files, the only output I receive to aid me in fixing the problem is a short HOOK-ERROR log.

An example of this is having a fixture that runs before_tag() with a log that should output details of a request response. I also have logging within the steps that are executed within the feature files, which output correctly, but in order of execution I should have another log I called in the fixture.py file listed above the other logs upon finding an error.

Thank you in advance :)

Edit: I should probably add some code examples...

This is how my logger is defined within the environment.py

def before_all(context):
    context.tlog = logging.getLogger("McloudProxyTests")

This is an example of a fixture in fixtures.py that I would want to use logging with

@fixture
def post_user_proxy(context):

    # Posting a user to the proxy
    url = helper.build_url(context.base_address, "users")
    headers = helper.auth_header(context.token)
    data = {"profile": {"nickname": "Test User"}}

    with context.vcr.use_cassette("users_post_cassette.json"):
        context.user_resp = context.session.post(url=url, headers=headers, json=data)

    # Storing the user uuid for use on scenarios that require it
    try:
        context.user_uuid = context.user_resp.json()["uuid"]
    except KeyError as error:
        helper.log_handle(
            context=context,
            severity=logging.ERROR,
            message="KeyError: {}".format(error)
        )
        raise error

The log_handle simply parses the response into its individual components and logs them as formatted data

def log_handle(context, severity=logging.DEBUG, message=None, response=None, payload=None):

    # define all string formatters that colour the text in the console. f_white will be used to reset the text back to white.
    f_yellow, f_blue, f_pink, f_green, f_turqoise, f_white = \
        "\033[2;0;33m", "\033[2;0;34m", "\033[1;0;35m", "\033[1;0;32m", "\033[1;0;36m", "\033[0m"  

    try:
        if message:
            context.tlog.log(level=severity, msg="{}{}{}".format(f_yellow, message, f_white))

        if payload:
            context.tlog.log(level=severity, msg="{}Payload: {}{}".format(f_blue, pformat(payload), f_white))

        if response is not None:
            context.tlog.log(level=severity, msg="{}Status Code: {}{}".format(f_pink, response, f_white))
            context.tlog.log(level=severity, msg="{}URL: {}{}".format(f_green, response.url, f_white))
            context.tlog.log(level=severity, msg="{}{}".format(f_turqoise, pformat(response.content)))
    except TypeError as error:
        context.tlog.log(
            level=logging.ERROR,
            msg="An error occurred while trying to log the response: {}".format(error)
        )
        raise

[meeky333]

bump

[jenisys]

The logging module is somewhat tricky (which seems to be not well known). MEANING: logging.basicConfig() only really works on the first call.

HINT: before_all() is somewhat special because it allows you to setup the logging on your own. By using the logging.getLogger() you implicitly call logging.basicConfig(). You should place a line: context.config.setup_logging() before you try to access the logger.

SEE ALSO: features/log*.feature

[BrambleRamble]

I also noticed that logging from environment.py behaved differently. What's the motivation for this choice of behaviour please?

I've been having fun with logging generally in the last couple of weeks, and have been commenting on #695 since that matched my original problem. It would be interested to know what logging behaviour is most useful to the majority of people, because I can certainly relate to the sentiments about configuring logging in the original post here.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[BrambleRamble]

Before this is closed, I'd appreciate an answer to the question I asked above please, if only to understand better.

[jenisys]

@BrambleRamble I think, I have already answered it above (before you even asked it). And you have not specified what you mean with logging behaves differently in "environment.py".

[BrambleRamble]

Hello, it's been a while! Thanks for the reply.

At this stage, I'd suggest considering adding searchable documentation for the basics of incorporating logging correctly into Behave, ideally with a small example of where and how to plumb it in (i.e. summarising the recommendations discussed here and making them more concrete). Based on this issue and #695 , I think that would be a helpful springboard for enabling people to refer to the logging docs and achieve whatever custom logging behaviour they want.

I think bad plumbing probably also underlay the issue I had with logging behaving differently in different files. I can try reproducing this but I think it's likely that, if I plumb in logging more "correctly" by following the suggested new documentation, this issue won't recur.

[bittner]

I'd suggest considering adding searchable documentation

Searching works again in the documentation. Sorry for the inconvenience!

[BrambleRamble]

@bittner Thanks, that definitely helps! 😁 I will try re-following those instructions afresh to see if I can improve my logging behaviour, but I don't think this issue needs to be kept open in the meantime.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[jenisys]

Reopen