Extend ops.log to capture warnings

[tonyandrewmeyer]

Although charms can simply use the logging module for everything, warnings generated with the warnings module have some nice filtering functionality and are generally the more Pythonic way to indicate (e.g.) that something is deprecated. Unit tests generally have all warnings enabled (at least for unittest - I'm not sure about pytest).

The framework could catch warnings emitted by charms and appropriately direct those to the Juju debug log.

[benhoyt]

Good idea, thanks for the suggestion!

[IronCore864]

I have done some research into the current ops.log module and its handlers. Is this what we want?

Code (drastically simplified ops.log):

import warnings
import logging


class MyLogHandler(logging.Handler):
    def emit(self, record):
        # pretend to send it to juju log (model_backend.juju_log)
        print(f"======= From my log handler: {record.getMessage()}=======")


# important stuff
def showwarning(message, category, filename, lineno, file=None, line=None):
    logger.warning(message)


# important stuff 2
warnings.showwarning = showwarning

if __name__ == "__main__":
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    logger.addHandler(MyLogHandler())

    logger.info("This is a log.")

    warnings.warn("This is a warning.")

Result:

$ python3 main.py 
======= From my log handler: This is a log.=======
======= From my log handler: This is a warning.=======

This is achieved by overriding showwarning() which does the printing of warning messages.

---

If we want to keep the warnings in the output, another approach is to use logging.captureWarnings(True) which redirects all warnings to the logging package:

import warnings
import logging

# important stuff
logging.captureWarnings(True)

class MyLogHandler(logging.Handler):
    def emit(self, record):
        # pretend to send it to juju log (model_backend.juju_log)
        print(f"======= From my log handler: {record.getMessage()}=======")


if __name__ == "__main__":
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    logger.addHandler(MyLogHandler())    

    logger.info("This is a log.")

    warnings.warn("This is a warning.")

Result:

$ python3 main.py 
======= From my log handler: This is a log.=======
======= From my log handler: /Users/tiexin/work/log-warning-test/main.py:21: UserWarning: This is a warning.
  warnings.warn("This is a warning.")
=======

[tonyandrewmeyer]

captureWarnings might be sufficient - I think it would be a good baseline, and if we decide that we don't need anything above that, then it's a very straightforward solution.

We definitely want to distinguish the class of warning (DeprecationWarning, PendingDeprecationWarning, etc). The first example doesn't do that, but captureWarnings does (UserWarning is the default class).

Do we want the full filename & line number in debug-log? I think we likely do want to have the module and line number, but it seems like the exact position of the charm code might be noise (and debug-log is already so noisy). Similarly, is it valuable to have the code that triggered the warning in debug-log, rather than just the location, the class, and the passed message?

I think we would want to make sure that the debug-log output did not contain newlines (the default formatwarning will, if I recall correctly).

In terms of other considerations:

• filtering - I guess we would leave this to the charm to manage themselves? The charm.py or the Charm's __init__ could set up whatever filtering was wanted. It would miss anything that ops itself generated earlier than that, but if we keep in mind that those are unfilterable, that's probably ok.
• if charmers want to change the disposition of warnings so that some turn into exceptions (e.g. running tests or maybe in some sort of dev environment) do we also leave that to the charm code itself? Do we want Harness to default to something other than just logging?

[tonyandrewmeyer]

I missed that stderr is already captured by Juju, which means that since the default filter of default::DeprecationWarning:__main__ is presumably active, if a charm generates a warning, it will already end up in Juju's debug log (verified now on both machine and k8s).

I suspect I missed this when I originally opened the ticket because I regularly run debug log like juju debug-log --include-module=unit.[unit-name].juju-log to filter out much of the noise, and it's not included there (since it's not coming from juju-log). I wasn't aware/had forgotten that stderr would end up in debug-log.

So this can be closed as invalid.

I do think that:

• redirecting the warnings to juju-log is nicer and more explicit
• a custom formatter would be nicer than the default one, for our purposes (however, not so much nicer that a lot of effort would be worthwhile, particularly since the stderr capture sends each line separately to debug-log).
• testing that this occurs (whether via stderr or juju-log) would be worthwhile
• documenting that this occurs would be worthwhile (e.g. I don't see any mention of stderr capture in the logging how-to guide, and there's no mention of the warnings module)

Very sorry for requesting something that already exists!

[IronCore864]

As we talked about, there seems to be no need to change anything since currently, the warnings are already in the Juju debug log. Closing PR #1240, will add a description in the logging doc.