Capture warnings via the logging system.

ops/log.py

@@ -18,12 +18,18 @@
 import sys
 import types
 import typing
+import warnings
 
 from ops.model import _ModelBackend
 
 
+# We do this on module import because some warnings are issued before we set up
+# the framework, and we need to capture those as well.
+logging.captureWarnings(True)
+
+
 class JujuLogHandler(logging.Handler):
-    """A handler for sending logs to Juju via juju-log."""
+    """A handler for sending logs and warnings to Juju via juju-log."""
 
     def __init__(self, model_backend: _ModelBackend, level: int = logging.DEBUG):
         super().__init__(level)
@@ -48,8 +54,8 @@ def setup_root_logging(
 
       logging.getLogger().setLevel(logging.INFO)
 
-    Warnings issued by the warnings module will be captured via stderr and also
-    end up in juju-log.
+    Warnings issued by the warnings module are redirected to the logging system
+    and forwarded to juju-log, too.
 
     Args:
         model_backend: a ModelBackend to use for juju-log
@@ -59,6 +65,19 @@ def setup_root_logging(
     logger = logging.getLogger()
     logger.setLevel(logging.DEBUG)
     logger.addHandler(JujuLogHandler(model_backend))
+
+    def custom_warning_formatter(
+        message: typing.Union[str, Warning],
+        category: typing.Type[Warning],
+        filename: str,
+        lineno: int,
+        _: typing.Optional[str] = None,
+    ) -> str:
+        """Like the default formatter, but don't include the code."""
+        return f'{filename}:{lineno}: {category.__name__}: {message}'
+
+    warnings.formatwarning = custom_warning_formatter
+
     if debug:
         handler = logging.StreamHandler()
         formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(message)s')

test/charms/test_main/actions.yaml

@@ -43,3 +43,5 @@ log-info:
   description: log a message at Info level
 log-debug:
   description: log a message at Debug level
+warn:
+  description: generate a deprecation warning

test/charms/test_main/src/charm.py

@@ -17,6 +17,7 @@
 import os
 import sys
 import typing
+import warnings
 
 import ops
 
@@ -65,6 +66,7 @@ def __init__(self, *args: typing.Any):
             on_log_warning_action=[],
             on_log_info_action=[],
             on_log_debug_action=[],
+            on_warn_action=[],
             on_secret_changed=[],
             on_secret_remove=[],
             on_secret_rotate=[],
@@ -113,6 +115,7 @@ def __init__(self, *args: typing.Any):
             self.framework.observe(self.on.log_warning_action, self._on_log_warning_action)
             self.framework.observe(self.on.log_info_action, self._on_log_info_action)
             self.framework.observe(self.on.log_debug_action, self._on_log_debug_action)
+            self.framework.observe(self.on.warn_action, self._on_warn_action)
 
         self.framework.observe(self.on.collect_metrics, self._on_collect_metrics)
         self.framework.observe(self.on.custom, self._on_custom)
@@ -304,6 +307,9 @@ def _on_log_info_action(self, event: ops.ActionEvent):
     def _on_log_debug_action(self, event: ops.ActionEvent):
         logger.debug('insightful debug')
 
+    def _on_warn_action(self, event: ops.ActionEvent):
+        warnings.warn('feature x is deprecated, use feature y instead', DeprecationWarning)
+
     def _on_get_model_name_action(self, event: ops.ActionEvent):
         self._stored._on_get_model_name_action.append(self.model.name)
 

test/test_main.py

@@ -895,6 +895,30 @@ def test_logger(self, fake_script: FakeScript):
             self._simulate_event(fake_script, event_spec)
             assert calls in fake_script.calls(clear=True)
 
+        # Test warnings are captured and sent to the Juju debug-log,
+        event_spec = EventSpec(
+            ops.ActionEvent,
+            'warn_action',
+            env_var='JUJU_ACTION_NAME',
+            set_in_env={'JUJU_ACTION_UUID': '5'},
+        )
+        self._simulate_event(fake_script, event_spec)
+        calls = fake_script.calls(clear=True)
+
+        calls_without_message = [call[:-1] for call in calls]
+        expected_without_message = ['juju-log', '--log-level', 'WARNING', '--']
+        assert expected_without_message in calls_without_message
+
+        idx = calls_without_message.index(expected_without_message)
+        warning_message = calls[idx][-1]
+        pattern = (
+            r'^.*:(\d+):\s+DeprecationWarning:\s+'
+            + re.escape('feature x is deprecated, use feature y instead')
+            + '$'
+        )
+        if not re.match(pattern, warning_message):
+            pytest.fail(f'Warning was not sent to debug-log: {calls!r}')
+
     @pytest.mark.usefixtures('setup_charm')
     def test_excepthook(self, fake_script: FakeScript):
         with pytest.raises(subprocess.CalledProcessError):

testing/src/scenario/_ops_main_mock.py

@@ -3,6 +3,7 @@
 # See LICENSE file for licensing details.
 
 import dataclasses
+import logging
 import marshal
 import re
 import sys
@@ -139,6 +140,9 @@ def _setup_root_logging(self):
         # Ops sets sys.excepthook to go to Juju's debug-log, but that's not
         # useful in a testing context, so we reset it here.
         super()._setup_root_logging()
+        # Ops also sets up logging to capture warnings, but we want the normal
+        # output.
+        logging.captureWarnings(False)
         sys.excepthook = sys.__excepthook__
 
     def _make_storage(self, _: _Dispatcher):