How to implement structured logging through indentation?

[jaksiprejak]

I'd like to implement a context manager that will add some indentation to the log messages sent from within its scope.

Something like this:

from loguru import logger

# ... configure the logger in any way

logger.info('this is the "root" level')
logger.info('and so is this')

with indent_logs(logger, indent_size=4):
    logger.info("I'm at the first level")

    with indent_logs(logger, indent_size=2):
        logger.info("I'm on the second level")

    logger.info('back on level 1')

logger.info('back at root')

Which would output:

2021-04-09 14:04:14.335 | INFO     | __main__:<module>:29 - this is the "root" level
2021-04-09 14:04:14.335 | INFO     | __main__:<module>:30 - and so is this
2021-04-09 14:04:14.336 | INFO     | __main__:<module>:33 -     I'm at the first level
2021-04-09 14:04:14.336 | INFO     | __main__:<module>:36 -       I'm on the second level
2021-04-09 14:04:14.336 | INFO     | __main__:<module>:38 -     back on level 1
2021-04-09 14:04:14.336 | INFO     | __main__:<module>:40 - back at root

But I'm unsure of what is the safest way to modify the logger so that all handlers and configurations are affected properly.

Any advice?

[jaksiprejak]

I've come up with this, but it feels pretty hacky:

@contextmanager
def indent_logs(loggr, indent_size):
    old_log = loggr._log
    original_log = getattr(old_log, '_original_log', old_log)
    old_indent_size = getattr(old_log, '_indent_size', 0)
    new_indent_size = old_indent_size + indent_size
    try:
        def new_log(level_id, static_level_no, from_decorator, options, message, args, kwargs):
            message = f'{ " " * new_indent_size }{message}'
            original_log(level_id, static_level_no, from_decorator, options, message, args, kwargs)

        new_log._indent_size = new_indent_size
        new_log._original_log = original_log
        loggr._log = new_log
        yield
    finally:
        loggr._log = old_log

Is there a better way? Or if not, is this at least safe from everything other than the API changes?

[Delgan]

Interestingly, this still looks like an use case that could be elegantly implemented once #318 is in place.

In the meantime, what do you think of using a custom format function while configuring your handlers and combining it with contextualize()?

def formatter(record):
    indentation = " " * record["extra"].get("indent_size", 0)
    return "{time} | {level} | " + identation + "{message}\n{exception}"

logger.add(sys.stderr, format=formatter)


logger.info('this is the "root" level')

with logger.contextualize(indent_size=4):
    logger.info("I'm at the first level")

You could also replace contextualize() with a custom contextmanager.

[jaksiprejak]

I'm not at a computer to test, but perhaps I'm missing something...
Won't that overwrite whatever formatter the logger had?

I'm looking for a more generic solution, i.e. one that will work regardless of how the logger is configured or how many sinks it has. Hence my hacky solution above.

[Delgan]

You're right. I assumed you could modify the handlers of your application. Currently there is no way to modify the formatted message generically.

One possibility is to use patch() although it's discouraged to modify the message this way (it may result in surprising behavior if opt(colors=True)):

@contextmanager
def indent_logs(indent_size):
    yield logger.patch(lambda r: r.update(message=" " * indent_size + r["message"]))

logger.info('this is the "root" level')

with indent_logs(4) as logger:
    logger.info("I'm at the first level")

Note however that indenting logs can't always work perfectly. The first part of the logged message is not guaranteed to always be the same size (it changes depending on the calling function and the line number), and so it can cause vertical misalignment of the messages.

[jaksiprejak]

Yes, you're right that indentation won't work if the pre-message part of the log lines are variable length. I should have mentioned that my log format has fixed length.

Your solution with patch() does not work when nesting. Also it does not reset the indentation after exiting the context.

I've also realised that my function does not work with opt(), however I can live with that for now unless you have a better solution?

[Delgan]

Oops, sorry for the incorrect workaround suggestion. I still think that patch() can be interesting, but the indentation level has to be stored somewhere before being reset. I used a ContextVars so that it works with multiple threads, what do you think?

from contextlib import contextmanager
from loguru import logger
from contextvars import ContextVar

logger_indentation = ContextVar('logger_indentation', default=0)

@contextmanager
def indent_logs(indent_size):
    val = logger_indentation.get()
    logger_indentation.set(val + indent_size)
    yield
    logger_indentation.set(val)

def patcher(record):
    indentation = logger_indentation.get()
    record.update(message=" " * indentation + record["message"])

logger = logger.patch(patcher)
logger.info('this is the "root" level')

with indent_logs(4):
    logger.info("I'm at the first level")
    with indent_logs(2):
        logger.info("In second level")
    logger.info("Back to level 1")

logger.info("Back root")

2021-04-24 12:49:26.778 | INFO     | __main__:<module>:19 - this is the "root" level
2021-04-24 12:49:26.779 | INFO     | __main__:<module>:22 -     I'm at the first level
2021-04-24 12:49:26.779 | INFO     | __main__:<module>:24 -       In second level
2021-04-24 12:49:26.779 | INFO     | __main__:<module>:25 -     Back to level 1
2021-04-24 12:49:26.779 | INFO     | __main__:<module>:27 - Back root

The downside contrary to your solution is that it requires to create a new logger object. It could be returned by the contextmanager instead, on your preferences.

[ma-sadeghi]

Hi @Delgan, is this being actively pursued? It'd be great if loguru supports context-aware indented messages right out of the box. Thanks :)

Related SO thread: https://stackoverflow.com/questions/5498907/python-indentation-context-level-to-log-prefix-length

[Delgan]

Hi @ma-sadeghi.

I don't think adding such new method to the logger is truly required. The implementation using a custom format or contextmanager look simple enough. They let the user choose some technical details without them being enforced by Loguru (to apply it generically or to one sink only, which symbol to use for alignment, what to do for multi-line messages or different size prefixes, context manager or automatic indentation via .getouterframes, etc.).

The discussed solutions could be integrated in the documentation though. Do the previously suggested snippets generate the output you want or do you think they can be improved?

[edagnin]

@Delgan Loving the logger you've built :)

I think my question could be related to this one, so just posting it here too..

I had an "issue" where when using \n for new lines in the logging module, the logs look something like this:

15/Mar/2022 15:3:7 - INFO - helpers.api_requests.request_factory  : ---------------- Request ----------------
Headers       :   {"Accept": "*/*",
                   "Accept-Encoding": "gzip, deflate",
                   "Connection": "keep-alive",
                   "Content-Length": "20",
                   "User-Agent": "python-requests/2.27.1",
                   "cookie": "foo=bar; bar=baz",
                   "x-pretty-print": "2"}
URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
Method        :   POST
Body          :   {"foo": "bar"}

And I think it looks terrible like this..

So, with the python logging lib (and the help of people waaaay more smarter than myself :) ) I've ended up the below class:

class MultiLineFormatter(logging.Formatter):

    # Get the header length of a given record
    def get_header_length(self, record):
        return len(super().format(logging.LogRecord(name=record.name,
                                                    level=record.levelno,
                                                    pathname=record.pathname,
                                                    lineno=record.lineno,
                                                    msg='',
                                                    args=(),
                                                    exc_info=None)))

    def format(self, record):
        # Format a record with added indentation
        indent = ' ' * self.get_header_length(record)
        head, *trailing = super().format(record).splitlines(True)

        # return
        return head + ''.join(indent + line for line in trailing)

The above class helps keep the indentation of the logged messages to be more like this:

22/Mar/2022 15:20:37 - INFO     - test_this                       : ---------------- Request ----------------
                                                                    Headers       :   {"Accept": "*/*",
                                                                                       "Accept-Encoding": "gzip, deflate",
                                                                                       "Connection": "keep-alive",
                                                                                       "Content-Length": "20",
                                                                                       "User-Agent": "python-requests/2.27.1",
                                                                                       "cookie": "foo=bar; bar=baz",
                                                                                       "x-pretty-print": "2"}
                                                                    URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
                                                                    Method        :   POST
                                                                    Body          :   {"foo": "bar"}

And then for extremely long strings, like this:

---------------- Response ----------------
Headers       :   {"Access-Control-Allow-Credentials": "true",
                   "Access-Control-Allow-Headers": "host,connection,accept-encoding,x-forwarded-for,cf-ray,x-forwarded-proto,cf-visitor,user-agent,accept,cookie,x-pretty-print,cf-connecting-ip,cdn-loop,x-request-id,x-forwarded-port,via,connect-time,x-request-start,total-route-time,content-length",
                   "Access-Control-Allow-Methods": "POST"

I have this function:

def format_long_string(message: str, line_width: int = 90) -> str:
    try:
        # get length
        str_length = round(message.index(':') / 2) + 3

        # prepare text
        body = '\n'.join(
                ['\n'.join(textwrap.wrap(text=line, width=line_width, subsequent_indent=' ' * str_length))
                 for line in message.splitlines() if line.strip() != ''])

    except ValueError:
        # prepare text
        body = '\n'.join(
                ['\n'.join(textwrap.wrap(text=line, width=line_width))
                 for line in message.splitlines() if line.strip() != ''])

    return body

Which displays the text like this:

22/Mar/2022 15:20:37 - INFO     - test_this                       : ---------------- Response ----------------
                                                                    Headers       :   {"Access-Control-Allow-Credentials": "true",
                                                                                       "Access-Control-Allow-Headers": "host,connection,accept-
                                                                                                   encoding,x-forwarded-for,cf-ray,x-forwarded-proto,cf-
                                                                                                   visitor,user-agent,accept,cookie,x-pretty-print,cf-
                                                                                                   connecting-ip,cdn-loop,x-request-id,x-forwarded-
                                                                                                   port,via,connect-time,x-request-start,total-route-
                                                                                                   time,content-length",
                                                                                       "Access-Control-Allow-Methods": "POST"}

And to get all of this to work, I need to create my own custom_logger function which will do the logging:

Define Logger:

LOG_MAP = {'info': logging.Logger.info,
           'debug': logging.Logger.debug,
           'error': logging.Logger.error}


def logger_config(log_level: str = 'info', logger: logging.Logger = logging.getLogger(__name__)) -> logging.Logger:
    # set format
    logger_format = MultiLineFormatter(fmt='%(asctime)-8s - %(levelname)-8s - %(name)-30s  : %(message)s',
                                       datefmt='%y/%b/%Y %H:%M:%S', )

    # request logger
    console = logging.StreamHandler()
    console.setLevel(LOG_MAP[log_level])

    # apply formatter to console logger
    console.setFormatter(logger_format)

    # prevent double logs in console
    console.propagate = False

    # return
    return logger

Custom Logger:

def custom_logger(log_message: str):
    logger_config().info(format_long_string(message=log_message))

So here I have a way of getting multi-line indentation aligned and have long strings wrapped, but there's 2 issues with this approach:

1. This is a lot of config just to get this implemented
2. I lose the flexibility of the logger since I am needing to make use of the custom_logger function to wrap longer text

• Is there currently an implementation for this with your logger?
• Or is there a way to extend at the very least, the MultiLineFormatter class to your logger?

Losing the text wrapping is okay, but for readability, the MultiLineFormatter helps a lot.

[Delgan]

Hi @edagnin. :)

Have you thought about using a dynamic formatter with Loguru?

By doing a quick test, I get the following result:

import sys

from loguru import logger


def formatter(record):
    base_format = "{time} {level} {name} {message} " + " " * 10
    base = base_format.format_map(record)
    lines = str(record["extra"].get("data", "")).splitlines()
    indent = "\n" + " " * len(base)
    reformatted = base + indent.join(lines)
    record["extra"]["reformatted"] = reformatted
    return "{extra[reformatted]}\n{exception}"


logger.remove()
logger.add(sys.stderr, format=formatter)


data = """---------------- Request ----------------
Headers       :   {"Accept": "*/*",
                   "Accept-Encoding": "gzip, deflate",
                   "Connection": "keep-alive",
                   "Content-Length": "20",
                   "User-Agent": "python-requests/2.27.1",
                   "cookie": "foo=bar; bar=baz",
                   "x-pretty-print": "2"}
URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
Method        :   POST
Body          :   {"foo": "bar"}"""

logger.info("Default message")
logger.bind(data=data).info("Message with data")

2022-03-15T21:48:51.694763+0100 INFO __main__ Default message           
2022-03-15T21:48:51.695066+0100 INFO __main__ Message with data           ---------------- Request ----------------
                                                                          Headers       :   {"Accept": "*/*",
                                                                                             "Accept-Encoding": "gzip, deflate",
                                                                                             "Connection": "keep-alive",
                                                                                             "Content-Length": "20",
                                                                                             "User-Agent": "python-requests/2.27.1",
                                                                                             "cookie": "foo=bar; bar=baz",
                                                                                             "x-pretty-print": "2"}
                                                                          URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
                                                                          Method        :   POST
                                                                          Body          :   {"foo": "bar"}

[edagnin]

@Delgan
Thank you so much for the quick reply AND the working solution! :)

I tested and works as you have shown, my only question is whether there's a way to achieve the same output without the need to use logger.bind?

I thought perhaps when this is done: logger.add(sys.stderr, format=formatter) that we're setting the logging formatter for the logger itself..

Also, why do we need to this: logger.remove() before adding the formatter?

[Delgan]

@edagnin You're welcome. ;)

I tested and works as you have shown, my only question is whether there's a way to achieve the same output without the need to use logger.bind?

I used bind() as a way to differentiate the data from the message. It's not mandatory, you can use logger.info("Message data: {}", data) instead for example and adjust the formatter to make indentation based on record["message"] instead of record["extra"]["data"]. The difference is that indentation will be aligned with "Message data:" instead of being aligned with the beginning of the actual data.

I thought perhaps when this is done: logger.add(sys.stderr, format=formatter) that we're setting the logging formatter for the logger itself..

The exists the configure() method that it applied more globally but I don't know if this will be useful to you. The patcher function can be used to construct an indented message the same way it's done in the formatter.

Also, why do we need to this: logger.remove() before adding the formatter?

I used remove() to discard the default handler (which exists for convenience) and thus avoid duplicating the logs displayed on sys.stderr.

[edagnin]

@Delgan I just really want to say thank you for your replies, it truly is appreciated!

I am in the process of replacing our logging with loguru and your replies are helping tremendously. :)

I used bind() as a way to differentiate the data from the message....

Okay cool, this makes sense yes, so I would actually also prefer using the bind approach

The exists the configure() method....

Yeah, I looked at this, but I couldn't figure out how to actually get a formatter applied. But you've already given a better implementation using bind.

I used remove() to discard the default handler (which exists for convenience) and thus avoid duplicating the logs displayed on sys.stderr.

Okay, so this is similar to this: console.propagate = False which is what I wanted to confirm.

Final question, what does this return statement do:

return "{extra[reformatted]}\n{exception}"

I would have thought this: record["extra"]["reformatted"] = reformatted is the final step

Also, I am using this:

class PropagateHandler(logging.Handler):

    def emit(self, record):
        logging.getLogger(record.name).handle(record)

# add to python default logger for HTML report
logger.add(PropagateHandler(), format=formatter)

But it doesn't seem that the format is carried through to the HTML report.. Do you have any suggestions perhaps?

[Delgan]

Thanks for your gratitude, @edagnin. :)

Okay, so this is similar to this: console.propagate = False which is what I wanted to confirm.

This is kind of similar. The difference is that Loguru uses only one logger which receives all logs, so which logs are outputted depend solely on the handlers configuration.

Final question, what does this return statement do:

return "{extra[reformatted]}\n{exception}"

I would have thought this: record["extra"]["reformatted"] = reformatted is the final step

The function must return the string format that will be used by Loguru to serialize the messages.

The record["extra"]["reformatted"] = reformatted assign your already formatted message to the record["extra"] dict so it can be re-used later. By returning "{extra[reformatted]}\n{exception}", Loguru will format the message by roughly calling returned_format.format(**record) and you should end up with the intended message you're looking for.

The "\n{exception}" is a suffix to complete the message format. Line-ending and possible "{exception}" are usually added automatically when format is a str but not when it's a function, to give you entire control over formatting.

Also, I am using this:

class PropagateHandler(logging.Handler):

    def emit(self, record):
        logging.getLogger(record.name).handle(record)

# add to python default logger for HTML report
logger.add(PropagateHandler(), format=formatter)

But it doesn't seem that the format is carried through to the HTML report.. Do you have any suggestions perhaps?

What is the HTML report you're referring? Aren't you seeing any logs reported at all, or aren't they formatted as expected?

This might be related to the standard Handler or Logger existing in your application. They can be a bit tricky to set up and it's best to understand how they work: Basic Logging Tutorial.

[edagnin]

Awesome, thank you for the feedback!

I've pretty much implemented your logger throughout our testing framework and it's working great!

On the HTML report, I am using pytest-html to generate the report.

Essentially this report just receives logs from the logger and puts it into a nice HTML report. I haven't configured anything other than telling it where to place the report.

With loguru, it is propagating the logs to the HTML report however, it's not in the same format as the log files.

So in your previous answer, you provided this formatter:

def formatter(record):
    base_format = "{time} {level} {name} {message} " + " " * 10
    base = base_format.format_map(record)
    lines = str(record["extra"].get("data", "")).splitlines()
    indent = "\n" + " " * len(base)
    reformatted = base + indent.join(lines)
    record["extra"]["reformatted"] = reformatted
    return "{extra[reformatted]}\n{exception}"

And I am using it for our logs.. So The log file itself (and console) I can see this format applied like this:

22/Mar/2022 15:20:37 - INFO     - test_this                       : ---------------- Response ----------------
                                                                    Headers       :   {"Access-Control-Allow-Credentials": "true",
                                                                                       "Access-Control-Allow-Headers": "host,connection,accept-
                                                                                                   encoding,x-forwarded-for,cf-ray,x-forwarded-proto,cf-
                                                                                                   visitor,user-agent,accept,cookie,x-pretty-print,cf-
                                                                                                   connecting-ip,cdn-loop,x-request-id,x-forwarded-
                                                                                                   port,via,connect-time,x-request-start,total-route-
                                                                                                   time,content-length",
                                                                                       "Access-Control-Allow-Methods": "POST"}

However, in the HTML report, it's like the format wasn't applied. So we see this:

15/Mar/2022 15:3:7 - INFO - helpers.api_requests.request_factory  : ---------------- Request ----------------
Headers       :   {"Accept": "*/*",
                   "Accept-Encoding": "gzip, deflate",
                   "Connection": "keep-alive",
                   "Content-Length": "20",
                   "User-Agent": "python-requests/2.27.1",
                   "cookie": "foo=bar; bar=baz",
                   "x-pretty-print": "2"}
URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
Method        :   POST
Body          :   {"foo": "bar"}

Obviously this isn't of your concern, so I will see if I can figure it out, but if you do have some kind of insight or solution, please do share :)

Maybe loguru could have a HTML report built in! XD

[Delgan]

@edagnin Well, let me know if you think this is due to Loguru. I tested it birefly and it looked to work fine:

[edagnin]

My apologies, the issue was on my side..

I am still fine-tuning a few things and I had created this fixture:

@pytest.fixture(autouse=True)
def update_logger():
    # prevent double logs
    logger.remove()

    # set logging
    logger.add(Path(os.environ.get('reports_dir'), 'Execution_Log.log'),
               format=formatter)
    logger.add(sys.stderr, format=formatter)

    # add to python default logger for HTML report
    logger.add(PropagateHandler(), format=formatter)

With test like this:

def test_again():
    # logger.remove()                                <----- Notice this is commented out
    # logger.add(sys.stderr, format=formatter)       <----- Notice this is commented out 

    data = """---------------- Request ----------------
    Headers       :   {"Accept": "*/*",
                       "Accept-Encoding": "gzip, deflate",
                       "Connection": "keep-alive",
                       "Content-Length": "20",
                       "User-Agent": "python-requests/2.27.1",
                       "cookie": "foo=bar; bar=baz",
                       "x-pretty-print": "2"}
    URL           :   http://mockbin.com/request/test/1/mock?foo=bar&foo=baz
    Method        :   POST
    Body          :   {"foo": "bar"}"""

    logger.bind(data=data).info('')

And I discovered when I have the fixture I get results like this:

Not really sure why this would duplicate the log and "change" the formatter style, but at least I found the cause of my issue.

I think up to this point, you've been more than helpful and thank you for that. With loguru, there's a ton of config off our hands! :)

EDIT:

I see it's doing this:

------------------------------Captured stderr call------------------------------

Which is what the setting is set for here:

# set logging
logger.add(sys.stderr, format=formatter)

And THEN, it's doing this:

-------------------------------Captured log call--------------------------------

Which is duplicating the output.

[Delgan]

@edagnin Maybe you don't need the PropagateHandler and can instead re-implement caplog or re-implement reportlog.

[edagnin]

@Delgan Thank you for your help!

I have done a bit of a cleanup and everything is working as expected.

I didn't end using your last suggestions, since after I did the cleanup it was working AND I am not using the PropagateHandler since it's working without that too.

So, with that said! Thank you for your help, genuinely appreciated! I hope this issue with all of its replies helps the next person too! :)