KeyError: "Attempt to overwrite 'args' in LogRecord"

[kornicameister]

Expected result:

I am able to use args as keyword to denote argument to string interpolation when using loguru

Actual result:

Opposite of above ;-).In fact it seems that if you try to specify whatever is originally available in Record from logging of python, python will think you are crazy to put such things in record.

Facts

• loguur.__version__ = 0.5.0
• python --version = Python 3.7.6
• lsb_release -sd = Linux Mint 19.3 Tricia
• context = application

Reproduce

git clone https://github.com/kornicameister/axion.git /tmp/axion --depth 1 ; \
cd /tmp/axion ; \
git checkout c9d85e76bd48719aab7edded1d4287a52ecb145e \
command -v tox && tox -e "py37-test" -- -k test_not_empty_signature || echo "need tox" ; \
cd - \
rm -rf /tmp/axion

Root cause

Relevant line that causes issue available here

Alternatively, it might be caused by conftest#caplog here, but this is unlikely given that only one test fails ;-)

[Delgan]

Hi @kornicameister, thanks for the detailed bug report!

Since version 0.5.0 of Loguru, keyword arguments when calling a logging function are automatically added to the extra dict. This feature has been requested multiple times to facilitate structured logging.

I didn't think it could have that side effect. This happens because if you use a handler from the standard logging library, the extra dict is used to update the LogRecord. This happens also if logger.bind(name="name") is used for example.

Unfortunately there's not much I can do. While using a standard Handler, one have to be careful not to use "forbidden" keywords. Possible workarounds:

• Rename args to args_
• Use f-strings to format the message
• Specify logger.opt(capture=False)

Also, I noticed in your code base you're using opt(record=True) but I'm not sure you need it if you don't use logger.info("Current thread: {record[thread]}") for example.

[kornicameister]

@Delgan so there's no way to..hmm..., filter such keywords right inside of particular handler?
Right before they go any way deeper?

---

Apart misuse in my codebase, would you mind elaborating in my repository? I a little bit intrigued but wouldn't want to make an offtopic here, if you don't mind.

[Delgan]

so there's no way to..hmm..., filter such keywords right inside of particular handler?
Right before they go any way deeper?

Hum... I prefer not to automatically strip out keywords because I think it risks to just shift the problem away (people might wonder where the expected values have gone).

However, instead of using LogRecord(..., extra=extra) I could probably create the instance with LogRecord(..., extra={"extra": extra}). The Loguru's extra dict will no longer automatically populate LogRecord attributes but will stay accessible with LogRecord.extra. I don't think this will result in usability loss, and on the contrary this will prevent users to be bitten by "Attempt to overwrite" errors. 🤔

Apart misuse in my codebase, would you mind elaborating in my repository? I a little bit intrigued but wouldn't want to make an offtopic here, if you don't mind.

Do you want me to open a new ticket in your repository to discuss loguru usage being made?

[kornicameister]

Hum... I prefer not to automatically strip out keywords because I think it risks to just shift the
problem away (people might wonder where the expected values have gone).

That's fair point. I wouldn't want that either.

The Loguru's extra dict will no longer automatically populate LogRecord attributes but will stay
accessible with LogRecord.extra.

That makes sense, if a point is just to store it for further use and that's rather internal detail, it should be quite safe to provide such change.

Another useful feature/chage, can be developing a little mypy or flake plugin, although I'd say mypy and its hinting of f-string makes more sense. Just a thought, but quite intriguing that could prevent users from putting arguments into their messages without counterparts in extras. TBH you could even take this further with extension in type toward Callable if there is a lazy=True for opt set but latter can be hard to implement if logger.opt(lazy=true) does not happen on same line or something. Just a thought for feature ;-), if you want :)

Do you want me to open a new ticket in your repository to discuss loguru usage being made?

Only if you want and have time to do that. I will probably look into it myself sometime in near future. I had a brief though I might be misusing loguru because of something I read in docs and is interpreted in wrong way. On the other hand, I wanted to avoid discussing about "me" and my codebase here to focus on loguru and those args :D

[Delgan]

There exists type hints for loguru, anyone should be able to benefit from it using mypy, right?

I opened kornicameister/axion#328 to discuss usage of loguru in your project. :)

[kornicameister]

type hints do say say that you can logger.debug with first argumen being str and rest of arguments is of typing.Any. And that's fine because that's pretty much all you can tell to mypy or similar tool about method signature 'cause everything else that you put in those messages are kwargs that are well...typing.Any.

My idea was something along this line:

logger.opt(..).debug(
  '{a} / {b} = {c}, # Error: Message defines "c" placeholder but it is missing in extras, found [a, b] though
  a=4,
  b=2,
)

or

logger.opt(..).debug(
  '{a} * {b} = {c}, 
  a=4,
  b=2,
  c=8,
  d=16,  # Warning: Message does not define d variable
)

or

logger.opt(..).info(
  'My name is {n}', 
  n=lamba _: "kornicameister",  # Error: Expected Callable[[], typing.Any], got Callable[[typing.Any], typing.Any]
)

what about that 🍭 :D

[Delgan]

Oh, I see! Sure, that would be neat. But I don't think that's possible knowing the limitations of Python type hints. Maybe the problem can be circumvented with a mypy plugin but that's really outside my area of knowledge. 😁

[kornicameister]

I am hyped to try it out, but gotta finish a git video tutorial first :/. Maybe I will play around. In that repo I linked I've been playing with type hinting totally outside of Python trying to bridge two worlds together :). Might be that little experience I do have can be helpful here.

You know what? I will try to do something here
If there's something to show, that's useful, I will let you know ;-)

[Delgan]

Great, thanks! But if it's too complicated, don't worry. ;)

[kornicameister]

it's rather simple introspection of particular function calls, so it should be actually quite simple ;-)

[Delgan]

So, I modified the way the LogRecord is filled with extra.

The main downside is that it's no longer possible to use Formatter("[%(some_extra_field)s] %(message)s") with standard logging handler, but I think it's certainly less of a problem than the "Attempt to overwrite" error was.

Closing thie issue consequently. Discussion about mypy plugins moved here: #277