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?