logging full warning message

[KarinaMarks]

Hi @Delgan ,

Thanks for the great package! I'm swapping from the core logging package to loguru in a python package I am developing. In general the swap has been really easy - but I'm having a problem with warnings/error messages.

I have made a minimal example of the conversion I am trying to make and the log outputs. From the logging package:

import logging

def make_logging_warnings():
    logging.basicConfig(filename="output.log", 
            format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
            level=logging.INFO)
    logger = logging.getLogger()

    logger.info("Let's start logging")
    try:
        raise UserWarning("I'm warning you!")
    except UserWarning:
        logger.warning('Warning encountered in function:', exc_info=True)

make_logging_warnings()

Which returns the following log:

2019-01-09 12:37:55,666 root         INFO     Let's start logging
2019-01-09 12:37:55,666 root         WARNING  Warning encountered in function:
Traceback (most recent call last):
  File "<ipython-input-1-59e413187e43>", line 12, in make_logging_warnings
    raise UserWarning("I'm warning you!")
UserWarning: I'm warning you!

Converting this into loguru the warning traceback doesn't seem to work:

from loguru import logger

def make_loguru_warnings():
    logger.add("output.log", level='INFO')

    logger.info("Let's start logging")
    try:
        raise UserWarning("I'm warning you!")
    except UserWarning:
        logger.warning('Warning encountered in function:', exc_info=True)

make_loguru_warnings()

I get the output:

2019-01-09 12:40:17.751 | INFO     | __main__:make_loguru_warnings:6 - Let's start logging
2019-01-09 12:40:17.754 | WARNING  | __main__:make_loguru_warnings:10 - Warning encountered in function:

See how I'm missing the traceback here?

I have a similar issue with errors, but they're giving too much information back in loguru - I think this is to do with better_exceptions, can this be turned off?

To make the above code work for errors I have just changed:

• UserWarning("I'm warning you!") to AssertionError("You're not assertive!")
• logger.warning("Warning encountered in function: ", exc_info=True) to logger.exception("Error encountered in function: ")

I get the following logs for both packages:

From logging

2019-01-09 12:44:06,843 root         INFO     Let's start logging
2019-01-09 12:44:06,843 root         ERROR    Error encountered in function:
Traceback (most recent call last):
  File "<ipython-input-2-759d24f4d830>", line 9, in make_logging_errors
    raise AssertionError("You're not assertive")
AssertionError: You're not assertive

From loguru

2019-01-09 12:45:36.377 | INFO     | __main__:make_loguru_errors:6 - Let's start logging
2019-01-09 12:45:36.379 | ERROR    | __main__:make_loguru_errors:10 - Error encountered in function:
Traceback (most recent call last):

  File "C:\Users\kmarks\AppData\Local\Continuum\miniconda3\envs\cm\Scripts\ipython-script.py", line 10, in <module>
    sys.exit(start_ipython())
    |   |    -> <function start_ipython at 0x00000181A3133598>
    |   -> <built-in function exit>
    -> <module 'sys' (built-in)>

  File "C:\Users\kmarks\AppData\Local\Continuum\miniconda3\envs\cm\lib\site-packages\IPython\__init__.py", line 125, in start_ipython
    return launch_new_instance(argv=argv, **kwargs)
           |                   |    |       -> {}
           |                   |    -> None
           |                   -> None
           -> <bound method Application.launch_instance of <class 

            .... + loads more lines .....

  File "<ipython-input-3-e3410db626c5>", line 12, in <module>
    make_loguru_errors()
    -> <function make_loguru_errors at 0x00000181A3DEA0D0>
> File "<ipython-input-3-e3410db626c5>", line 8, in make_loguru_errors
    raise AssertionError("You're not assertive")
          -> <class 'AssertionError'>

AssertionError: You're not assertive

I see information on using the backtrace=True/False argument, but that still gives much more information on the error than I am looking for. I am guessing the error problem is to do with better_exceptions? I'm not sure about the warning one. I would really appreciate some help with this.

Thanks!

[Delgan]

Hey @KarinaMarks, glad you like Loguru. 👍

Thanks for the explanations and the detailed examples, it helps a lot to understand the problem!

So, as you noticed, logger.warning("Message", exc_info=True) doesn't generate any special output. This is because each logging method is actually equivalent to str.format(). Thus, arguments present in the string are formatted, otherwise ignored.
The solution to log exception information with a different level is to use the .opt() function. You could use it like this: logger.opt(exception=True).warning('Warning encountered in function:').

About the actual formatting of these exceptions. As you understood, this is partly related to better_exceptions. This package is used to improve the formatted exceptions by different means, in particular, it displays the value of each variable. You can indeed disable this behavior by configuring your sink with backtrace=False.

The second thing is that the exceptions are displayed entirely. The place where the error was caught is marked with a small > at the beginning of the line, but the rest of the traceback upward is also displayed. I thought this was useful to have this in all cases, this is why there is no option to disable this. However, I realize this can also be too verbose, I did not know that Miniconda and such tools added layers on top of user code.

I guess the best solution is to make backtrace=False to disable both better_exceptions enhancements and full-exception formatting. It would also be easier to reason about and explain. I will do like that for the next release.

If you have other questions or need some clarifications, don't hesitate. 😉

[blueyed]

@Delgan
Thanks for the detailed explanation.
I think it would be useful to have a section in the docs containing (part of) this, explaining how to migrate from logging.
(I've also noticed myself that old-style formatting (logger.info("foo: %s", bar)) is a problem in this regard, and wondered even if loguru could support it, but then rather replaced all instances of it.)

[Delgan]

@blueyed I definitely could add some documentation about this, thanks for the idea!

The % style formatting is kind of deprecated in Python 3, Loguru only supports braces formatting: logger.info("foo: {}", bar).

[randallpittman]

@Delgan

The % style formatting is kind of deprecated in Python 3, Loguru only supports braces formatting: logger.info("foo: {}", bar).

Just a note from a lurker. The particular %-formatting that logging uses isn't deprecated because, unlike f-strings etc., the arguments are not evaluated regardless of whether that particular log level is enabled. I think you've solved that problem with lazy=True, but I'm just getting familiar with loguru.

Useful to know for a potential logging-->loguru guide.

EDIT: I was incorrect to say that the arguments are not evaluated. What is true is that string interpolation does not take place in logging's logger.info('count is now: %d', count_val).

[Delgan]

@randallpittman Thanks for your remark!

But I'm not sure to understand. What do you mean by "the arguments are not evaluated"?

One thing for sure is that the formatting is not processed if the log level is not high enough. In such case, logger.info("foo: %s", bar) is probably slightly more efficient than logger.info("foo: %s" % bar). But the same optimisation is done using braces in Loguru, logger.info("foo: {}", bar) does not call .format() if not necessary.

The lazy option is closer to the .isEnabledFor() optimization for built-in logging, it can avoid computing the arguments. But these are evaluated anyway as long as you pass them to a function, even with % formatting.

[randallpittman]

@Delgan Hmm, I think I was half wrong. I was thinking the arguments didn't get computed if you used the logger.debug("foo: %s", bar) form from logging, but that's not true. But what is true is that the string interpolation doesn't take place with that form. So in the case of gazillions of debug messages, that interpolation could be a significant performance hit. And yes, logurudoes have the same optimization with logger.info("foo: {}", bar).

[Delgan]

@randallpittman Yes, I guess this particularly saves time for objects with non-trivial __str__() method.

[Delgan]

Ok, this is fixed in the v0.2.5 I just released.

Setting backtrace=False for the sink should now produce stack traces entirely equivalent to the built-in ones.

I will write the "logging --> loguru guide" and ping you once it's done. 👍

[Delgan]

@blueyed @randallpittman Just to let you know, I added a small guide about migrating from logging to loguru in the documentation.

I will probably add more snippets in the future.

[chrisgeru]

Not sure if we can use f-strings:

• Interpolation (%): not-safe
• .format(): safe
• f-string: ?

[Delgan]

@chrisgeru What do you mean by a formatting function being safe or not?