Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: remove ops.main.main deprecation warning, and avoid warnings in action output #1496

Open
wants to merge 11 commits into
base: main
Choose a base branch
from
22 changes: 20 additions & 2 deletions ops/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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.
Expand All @@ -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[str, Warning],
category: typing.Type[Warning],
filename: str,
lineno: int,
*_: typing.Any,
**__: typing.Any,
):
"""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
Comment on lines +72 to +75
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would this suppress warnings from third-party libraries in charmers' tests?

It might still be beneficial for actions, but could risk charmers overlooking issues in other libraries they use.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would this suppress warnings from third-party libraries in charmers' tests?

This doesn't really suppress the warnings, it just changes them to go through the logging system (I suppose if your log level is higher than warning then they are effectively suppressed, but I would argue that you have asked for that to happen).

This would apply to any warnings including third-party libraries, yes. However, I think that's the behaviour we want - if some third-party library generated a warning during an action, then I think that should end up in the Juju debug-log (or Loki or anywhere else people have directed the logging to) and should not end up in the action output.

This wouldn't happen with charm unit tests, because we (at least in Scenario) have a custom log/warning setup there - we don't do the special-casing for actions, and the debug-log entries end up in a side-effect collection in the context object. It would happen with integration tests but I'd argue that's what we want: the same behaviour as when the charm is run in production. I don't think people notice warnings in integration tests, but I think they often do in unit tests, so that's where it's important they show up.

If charms run their integration tests so that the charm is run with -W error (last time I looked, no-one does this, but I think it would be a good idea) then it does still apply (I manually checked this case when creating the PR), so the charm would crash, failing the test.


if debug:
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(message)s')
Expand Down
7 changes: 1 addition & 6 deletions ops/main.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
2 changes: 2 additions & 0 deletions test/charms/test_main/actions.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -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
8 changes: 7 additions & 1 deletion test/charms/test_main/src/charm.py
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
import os
import sys
import typing
import warnings

import ops

Expand Down Expand Up @@ -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=[],
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
24 changes: 24 additions & 0 deletions test/test_main.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down
12 changes: 0 additions & 12 deletions test/test_main_invocation.py
Original file line number Diff line number Diff line change
Expand Up @@ -52,9 +52,6 @@ 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)

with pytest.raises(TypeError):
ops.main.main() # type: ignore

Expand All @@ -71,9 +68,6 @@ 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)

with pytest.raises(TypeError):
ops.main.main() # type: ignore

Expand All @@ -90,18 +84,12 @@ 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)

with pytest.raises(TypeError):
main.main() # type: ignore


def test_legacy_import_from_submodule(charm_env: None):
from ops.main import main

with pytest.deprecated_call():
main(ops.CharmBase)

with pytest.raises(TypeError):
main() # type: ignore
12 changes: 11 additions & 1 deletion testing/src/scenario/_ops_main_mock.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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):
Expand Down
Loading