Binding without creating a new logger

[mooncake4132]

I'm wondering if we can have new APIs that can bind and unbind structured arguments in place (i.e. without creating a new logger). Maybe an add_extra and a remove_extra method? I also think it'll be useful if Logger._extra can be promoted to a public member for viewing (a getter property would suffice).

The motivation here is that I want to be able to do from loguru import logger from all my modules and get the structured arguments I've set elsewhere. I can workaround this issue by keeping my own logger registry or adding values to _extra directly but I think it'll be nice if this can be officially supported.

[Delgan]

Hello @mooncake4132.

I tried to implement the .configure() with your use case in mind.

You can do logger.configure(extra={"foo": "bar"}), then all logged messages from any of your modules will contain the "foo" key in their "extra" record dict.

Making extra part of the public API is something I considered in the past. I chose not to do that because I want to keep the API as minimalist as possible, and a public .extra attribute doesn't add much that cannot already be done using .bind().

[mooncake4132]

Thanks for the reply!

I thought about using .configure() but I only know the values I want to add as I go (I don't know all the values in the beginning). This means I cannot use configure as it does not allow me to add an extra to the existing extra dictionary.

.bind() works but it creates a new logger. This is the use case I have in mind:

entry.py

from loguru import logger
from .utils import some_small_util_function()


# Process loop
while True:
  logger.bind('request_id', 'xxx-xxx-xxx')
  some_small_util_function()
  ...
  logger.unbind('request_id')

utils.py

from loguru import logger


def some_small_util_function():
   logger.info('test')

The logger.info call in utils.py would not contain the request_id value in extra because .bind() creates a new logger (and the result was discarded).

If you want to keep the API minimalist that's absolutely fine. I can easily work around the issue through inheritance and having my own logger registry 😃

[Delgan]

Thanks for the code samples, it helps a lot to visualize the problem and think about a proper solution!

I don't know what to think of this kind of contextual logging.

On one hand I see that this can be super useful, on the other hand I'm worried this will break as soon as you introduce multithreading.

This looks too much like using global variables across modules in my opinion, like:

1. Modify the global variable
2. Run code in another module with rely on this global variable
3. Modify back the global variable

If logs emitted by some_small_util_function() should contain request_id context, then this context should be passed to the function explicitly. Maybe by refactoring your functions into a class:

class Utils:

    def __init__(self, request_id):
        self.logger = logger.bind(request_id=request_id)

    def some_small_util_function(self):
        self.logger.info("Test")

And use it like:

# Process loop
while True:
    utils = Utils(request_id="xxx.xxx.xxx")
    utils.some_small_util_function()

I agree that this doesn't look perfect as the function normally does not need the context, except for logging which is orthogonal to utils functionalities.

How would you implement this using standard logging module (if you already did it)?

[mooncake4132]

What you suggested is actually what we have today. However, as we have more and more modules and functions, we find ourselves passing loggers around way too often. So we want to move away from this model.

You do have a point with concurrent executions (i.e. threading or async tasks). Our solution is to use a proxy logger, which will ensure each concurrent environment only accesses its own logger. This is what we came up with (some parts left out):

import asyncio
import threading

import aiotask_context


_tls = threading.local()


class LoggerProxy:
    def __getattr__(self, key):
        return getattr(self._get_context_logger(), key)

    def _get_context_logger(self):
        if asyncio._get_running_loop() is None:
            if not getattr(_tls, 'proxy_logger', None):
                _tls.proxy_logger = loguru.logger.bind()

            return _tls.proxy_logger
        else:
            proxy_logger = aiotask_context.get('proxy_logger')
            if not proxy_logger:
                proxy_logger = loguru.logger.bind()
                aiotask_context.set('proxy_logger', proxy_logger)

            return proxy_logger


logger = LoggerProxy()

*aiotask_context from here

[Delgan]

Thanks once again for the code snippet, very instructive.

So, this means that for add_extra() / remove_extra() to be safe, Loguru would also need to provide some kind of LoggerProxy() class or method.

It's a complex problem, because in addition to the context per thread, a context for asyncio is also needed as you pointed out.

I don't know if and how I would implement this, but I will think about it, because as your use case demonstrates, it can be very useful and convenient.

In the meantime, you can also add a bind() method to LoggerProxy so that it update the local logger, right?

Also, it may worth looking at alternative libraries which seems to provide support for context logging across threads. I think to eliot and structlog. I did not look very deeply, but they may interest you.

[mooncake4132]

Yes, I've already secretly added add_extra(), remove_extra, and a extra property to our proxy logger (with some tests in case you changed the _extra interface we'll be able to find out as it's not a public API 😉)

Thanks for the discussion!

[Delgan]

Thanks to you, as I said this is an interesting use case, so I will see if I can integrate it to Loguru elegantly. 🙂

[kerma]

Maybe open the issue/feature again? I ended up here desperately trying to achieve the same.

I have the exact same problem @mooncake4132 had. I've had this for years tbh while using Python loggers. The ugly workaround for me as well has been passing logger objects around, but this gets so tedious fast.

The problem is really painful if you work in an microservices environment and you pass some contextual data between those things. Request-ID or Trace-ID, user info etc. Having 100+ services makes it quite necessary to log something down. If those logs are collected to some central place (like ELK stack) it's really convenient to search all of them via this contextual info.

@Delgan if you have an idea and willingness to implement this I can try to help with a PR.

[Delgan]

Hey @kerma!

You are right, I left the issue closed because I did not have yet a precise idea about the solution to implement, but it always remained half-open in my mind. So, let's re-open it now. :)

I have not yet taken the time to think about it a lot. However, I feel it's possible to solve this issue as well as #72 and #108 by adding just one new method to the Loguru's API.

I thought of something like a .context() function, allowing to isolate some parts of the logger, also possibly dealing with thread local storage. This is still very approximate in my mind, as I said I did not think deeply about this. I will try to focus more on this, there is surely something to be done.

For example, would this be ok if you have to use it like this in your inner functions,
imagining that the context for "foobar" is set somehow earlier?

def some_small_util_function():
    logger.context("foobar").info('test')

[kerma]

Hey @Delgan, thanks for the reopen.

The .context() would work within the same package. Not so much if I'm also dealing with multiple libraries. But this is probably a niche problem I have.

Ideally I'd like to use the logger in a way that "it just works".

logger.info("startup")
kls = Someclass()
logger.set_context("some_id", kls.parse_id())
logger.info("with id")
kls.other()

Given that Someclass also uses logger in other() function the output could be something like:

INFO  startup
INFO  some_id=123 with id
DEBUG some_id=123 calling other()

I guess the question is what happens if I call the logger with context when the context is not yet set? Ideally this should just work as well. But we'd need some mechanism for debugging.

[superzarzar]

Hi @Delgan,
If you're looking for an easy way to implement the context method, why not use opentracing?
It handles multi threading for you, giving you an id that is unique for your current scope.
This way, you can open a with clause in which everything has the same context.
When a user attempts to write a log, you look for 'additional parameters in the current context, not needing to pass around the logger.

snippet of what I have in mind:

with logger.context(param_name="param_value"):
logger.info('Some info') # the extra parameters will appear in the log
"""
anything here, including sub-methods will automatically append the parameters as extra to the
log
"""

[Delgan]

Ok, sorry it took so long!
As I discussed it in a previous comment, I was trying to find a convenient API to solve this problem along with two others ones I linked. It tooks me a few days of head scratching before I finally come to the conclusion that no such "all-in-one" solution was possible. :)

So, taking into consideration what the three of you advised, I think a very simple .contextualize() method would do the job fine:

def other():
    logger.info("Calling other()")

with logger.contextualize(id=123):
    other()

There would be no need to re-call any method from inside other(), it will work out-of-the-box as you requested @kerma, and it's so much more elegant.

As you suggested, @superzarzar, the new method will be used a context manager to automatically set and unset the values. It's common sense, and very elegant too. However, I would like to avoid using opentracing as it is a huge dependency. I thought of using the built-in contextvars module, it should work fine, right? It seems to perfectly fit ours needs at it handle both threads and asyncio contexts, as @mooncake4132 implemented it.
The only downside is that contextvars is only available for Python 3.7+, so a backported third library will be optionally needed.

[Delgan]

Fixed on master, finally. 🎉

It uses contextvars for Python 3.7+ and relies on the aiocontextvars backport for earlier versions.

I will close this issue once the next Loguru release is published.

[Delgan]

The new contextualize() method is available in v0.4.0 just released. 👍