Loguru: Log structured things

[xeor]

I am choosing between loguru or structlog for a new project. I've settled now on loguru, but there is one thing that really bothers me is how to log structured objects like dicts.

I found https://github.com/Delgan/loguru/issues/2, which ended up being labeled as wont-fix.

Just throwing it out, but before I start making a PR for an idea, what is the thoughts about something like this for a solution:

• Using pipe for structured logs, example a_dict | logger.info('message here')
  
  
  
  • We can use the pythons __ror__ function to implement something that looks like a unix-pipe
  
  
  • logger.info can work as normal, no api changes
  
  
  • The structured log can be handled by a function, a serializer to make it into a log-line
  
  
• Maybe also a_var = some_func() | logger.info('a_var assigned')
  
  
  
  • If the logger/pipe construct returns the output back, this idea can be used in normal assignments as well.
  
  

I didn't start to write much code yet, but I think this might be possible to implement.

Thoughts?

[Delgan]

Hi @xeor!

Well, I generally quite appreciate this kind of syntactic sugar, but I don't think it's appropriate to add this to the logger. Operator overload allows you to do very nice things, but it is often not the most relevant solution (though often the less verbose). In particular, I find the syntax very "orthogonal" to the usual use of the logger.

Currently, "idiomatic" structured logging in Loguru is done using .bind(a_dict) or .bind(**a_dict). Do you think this is too verbose? There is only one method starting with b so IDE auto-completion should handle it fine I guess. :smile:

[xeor]

Thanks for the reply!

Yes, it feels a little too verbose and maybe even miss-guided...? It makes additional info I want (from an object) not a first-class-citizen anymore..

But when I think about it, maybe this is something that can go in the recipes bin, if it turns out nice.. :)

[Delgan]

I tried for a long time to find a satisfactory API to solve #2, but I never found one that suited me. Of course it would be better to have it directly integrated into Loguru, but otherwise it would be a good idea to add it to the recipes list, indeed. It looks we need to somehow wrap every logging methods or maybe just _log().

[xeor]

I'll finish up a test first and see if it is useful, works or is just flawed :) I'm not sure how the best design is, but I'll post it here when I'm done..

Each log-level is defined on it's own, like https://github.com/Delgan/loguru/blob/e2a337a40d1fb627d88cbe05d61b733b0ff1c92e/loguru/_logger.py#L1901.. That might be a problem. Not sure how this whole idea works with type-hinting yet.

[xeor]

I've played with this idea some more, but there are some limitations, which makes the whole idea a little moot. There looks to be no way to do this using the syntax above.
Alternative i'm considering:

• When using the pipe, no message or level will be supported
• Using different function names that support this

I think the best way is alt1.. But then it has nothing to do with loguru.. It's kinda a cool idea still, so this is what I got so far if anyone wants to build something on it.

class LogHandler:
    def _format(self, record):
        if 'var' in record['extra']:
            return loguru._defaults.LOGURU_FORMAT + ' {extra[var]}\n'
        return loguru._defaults.LOGURU_FORMAT + '\n'

    def __ror__(self, obj):
        if isinstance(obj, dict):
            self.logger = logger.bind(var=obj)
        self.logger = self.logger.opt(depth=1)
        self.logger.debug('Object')
        return obj

    def __call__(self, *args, **kwargs):
        return getattr(logger, self.level)(*args, **kwargs)

    def __getattr__(self, level):
        handler = LogHandler()
        handler.level = level
        return handler

    def setup(self):
        logger.remove()
        logger.add(sys.stdout, format=self._format)
        logging.basicConfig(handlers=[InterceptHandler()], level=0)


log = LogHandler()
log.setup()

{'a': 111, 'b': 222, 'c': [1, 2, 3]} | log
{'a': 333, 'b': 444} | log
var = {'a': 555} | log
print(f'var is still {var}')
log.info('test without pipe')

outputs

2020-04-17 22:21:42.909 | DEBUG    | __main__:<module>:95 - Object {'a': 111, 'b': 222, 'c': [1, 2, 3]}
2020-04-17 22:21:42.909 | DEBUG    | __main__:<module>:96 - Object {'a': 333, 'b': 444}
2020-04-17 22:21:42.909 | DEBUG    | __main__:<module>:97 - Object {'a': 555}
var is still {'a': 555}
2020-04-17 22:21:42.909 | INFO     | __main__:__call__:79 - test without pipe

[Delgan]

Thank you for taking the time to try and find a working implementation. You had to face the problems I was afraid of: as logger.log() returns None, it's difficult to create elegant combinations. Also, how do you log a message associated with a dict using your solution? That's why I was talking about "wrapping" every methods, for example if we want to mimic structlog behavior:

from loguru import logger
from functools import partialmethod


def structured(_, level, message, **kwargs):
    formatted = " ".join("{}={}".format(key, value) for key, value in kwargs.items())
    formatted = message + " " + formatted
    logger.opt(depth=1).log(level, formatted)


logger.__class__.info = partialmethod(structured, "INFO")

logger.info("Test", foo="bar", baz=123)
# => '2020-04-18 12:03:51.737 | INFO     | __main__:<module>:12 - Test foo=bar baz=123'

But in the end, I think I prefer your solution using an external object. It seems that Loguru is not fully adapted for this kind of logging calls, unfortunately. If this way of doing structured logging is necessary, the `structlog' library is logically the most suitable.

[xeor]

The main problem was what I tried getting an answer on (https://stackoverflow.com/questions/61267515/optional-ror-data-in-python-class) after a while..
The whole idea also felt very flaky if this would support every log-level.

Oh well... It was worth a try :)

I'm not sure if the solution is worthy of anything other than this issue.. It's useful, but probably not something you should use a lot. A better solution for simple debugging like this would be https://github.com/gruns/icecream

[Delgan]

Yes, if it's about debugging, better use icecram or pysnooper! Anyway, it looks complicated to integrate elegant solution to Loguru, thanks for trying. ;)

[benhowes]

I was just wondering if there's a case for having an extra/bind argument to log for the case that you're logging an event where you only want that variable in that single place, e.g.

logger.bind(response_time=3).info("completed request")

could become:

logger.info("completed request", bind={"response_time": 3})

Then that can be added to the extra object at log time? The .bind() syntax isn't bad, but creating a new logger for a single log event seems a bit heavy handed.

[Delgan]

@benhowes I intentionally chose not to have any "magical" arguments. The logging functions must matches the behavior of str.format(*args, **kwargs), nothing more, nothing less. There is one special case that happens if opt(record=True) but this is the only one. Special cases should be kept to a minimum in order to avoid possible edge cases like logger.info("Value: {bind}", bind=123).

If you're worried about the overhead introduced by bind(), don't be. :slightly_smiling_face:
There are things internally that are quite heavier when a message is logged. Hopefully, it will be drastically improved once I find time to re-implement it in C.

[benhowes]

@Delgan thanks for the follow-up! I'll stick with bind().

[Delgan]

@xeor @benhowes Good news: loguru now supports "structured logging" out of the box!

The **kwargs arguments are automatically added to the extra dict. This can be disabled using .opt(capture=False). :+1: