fix: remove ops.main.main deprecation warning, and avoid warnings in …

…action output (#1496)

Background:
* A `warnings.warn` call outputs to stderr by default.
* Juju captures stderr and when executing an action provides it to the
user.
* We emit a DeprecationWarning when charms call `main()` other than
`import ops ... ops.main()`
* DeprecationWarnings are ignored by default, *except* for issues in the
`__main__` module.
* A warning like this is meant to be discovered during tests - but unit
tests typically do not call `main()` or execute the `charm.py` file, so
they will not trigger this warning. That means that we're relying on
integration tests.

The above means that, currently, the deprecation warning is included in
the action output - this warning is intended for the developer of the
charm, not the user of the charm, so we want to change this.

Firstly, the `ops.main.main` deprecation warning is removed. It's too
awkward to have a warning that gets emitted before the framework is set
up. Instead, we'll rely on `charmcraft analyse` and static checks.

However, while that will solve the specific issue in #1460, we do also
want to avoid any future leakage of warnings into action output if there
are other warnings emitted that originate in the `__main__` model.

To that, rather than rely on Juju capturing the warning via stderr, we
use the logging package to capture all warnings and redirect them to
logging calls. These are then directed to Juju's debug-log via the
existing mechanism. While we are doing this, we minimise the output to
include references to the filename and line, but not the actual code
itself (which may be sensitive).

When running (Scenario) tests, we ensure that the warning and logging
systems use their default behaviour, so that pytest and other tools can
work as expected.

Fixes #1460

ops/log.py

@@ -18,12 +18,13 @@
 import sys
 import types
 import typing
+import warnings
 
 from ops.model import _ModelBackend
 
 
 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)
@@ -41,13 +42,16 @@ def emit(self, record: logging.LogRecord):
 def setup_root_logging(
     model_backend: _ModelBackend, debug: bool = False, exc_stderr: bool = False
 ):
-    """Setup python logging to forward messages to juju-log.
+    """Setup Python logging to forward messages to juju-log.
 
     By default, logging is set to DEBUG level, and messages will be filtered by Juju.
     Charmers can also set their own default log level with::
 
       logging.getLogger().setLevel(logging.INFO)
 
+    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
         debug: if True, write logs to stderr as well as to juju-log.
@@ -56,6 +60,20 @@ def setup_root_logging(
     logger = logging.getLogger()
     logger.setLevel(logging.DEBUG)
     logger.addHandler(JujuLogHandler(model_backend))
+
+    def custom_showwarning(
+        message: typing.Union[Warning, str],
+        category: typing.Type[Warning],
+        filename: str,
+        lineno: int,
+        file: typing.Optional[typing.TextIO] = None,
+        line: typing.Optional[str] = None,
+    ):
+        """Direct the warning to Juju's debug-log, and don't include the code."""
+        logger.warning('%s:%s: %s: %s', filename, lineno, category.__name__, message)
+
+    warnings.showwarning = custom_showwarning
+
     if debug:
         handler = logging.StreamHandler()
         formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(message)s')

ops/main.py

@@ -11,9 +11,9 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
+
 """Support legacy ops.main.main() import."""
 
-import warnings
 from typing import Optional, Type
 
 import ops.charm
@@ -37,9 +37,4 @@ def main(charm_class: Type[ops.charm.CharmBase], use_juju_for_storage: Optional[
 
     See `ops.main() <#ops-main-entry-point>`_ for details.
     """
-    warnings.warn(
-        'Calling `ops.main.main()` is deprecated, call `ops.main()` instead',
-        DeprecationWarning,
-        stacklevel=2,
-    )
     return _main.main(charm_class=charm_class, use_juju_for_storage=use_juju_for_storage)

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,9 +307,12 @@ 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)
 
 
 if __name__ == '__main__':
-    ops.main(Charm)  # type: ignore
+    ops.main(Charm)

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):

test/test_main_invocation.py

@@ -52,8 +52,7 @@ def test_top_level_import(charm_env: None):
 def test_top_level_import_legacy_call(charm_env: None):
     import ops
 
-    with pytest.deprecated_call():
-        ops.main.main(ops.CharmBase)
+    ops.main.main(ops.CharmBase)
 
     with pytest.raises(TypeError):
         ops.main.main()  # type: ignore
@@ -71,8 +70,7 @@ def test_submodule_import(charm_env: None):
 def test_submodule_import_legacy_call(charm_env: None):
     import ops.main
 
-    with pytest.deprecated_call():
-        ops.main.main(ops.CharmBase)
+    ops.main.main(ops.CharmBase)
 
     with pytest.raises(TypeError):
         ops.main.main()  # type: ignore
@@ -90,8 +88,7 @@ def test_import_from_top_level_module(charm_env: None):
 def test_import_from_top_level_module_legacy_call(charm_env: None):
     from ops import main
 
-    with pytest.deprecated_call():
-        main.main(ops.CharmBase)
+    main.main(ops.CharmBase)
 
     with pytest.raises(TypeError):
         main.main()  # type: ignore
@@ -100,8 +97,7 @@ def test_import_from_top_level_module_legacy_call(charm_env: None):
 def test_legacy_import_from_submodule(charm_env: None):
     from ops.main import main
 
-    with pytest.deprecated_call():
-        main(ops.CharmBase)
+    main(ops.CharmBase)
 
     with pytest.raises(TypeError):
         main()  # type: ignore

testing/src/scenario/_ops_main_mock.py

@@ -3,9 +3,11 @@
 # See LICENSE file for licensing details.
 
 import dataclasses
+import logging
 import marshal
 import re
 import sys
+import warnings
 from typing import TYPE_CHECKING, Any, Dict, FrozenSet, List, Sequence, Set
 
 import ops
@@ -136,9 +138,17 @@ def _load_charm_meta(self):
         return ops.CharmMeta.from_yaml(metadata, actions_metadata)
 
     def _setup_root_logging(self):
+        # The warnings module captures this in _showwarning_orig, but we
+        # shouldn't really be using a private method, so capture it ourselves as
+        # well.
+        original_showwarning = warnings.showwarning
+        super()._setup_root_logging()
+        # Ops also sets up logging to capture warnings, but we want the normal
+        # output.
+        logging.captureWarnings(False)
+        warnings.showwarning = original_showwarning
         # 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()
         sys.excepthook = sys.__excepthook__
 
     def _make_storage(self, _: _Dispatcher):