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.

Sign up for GitHub

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

Merged
merged 13 commits into from
Jan 23, 2025
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
13 commits
Select commit Hold shift + click to select a range
a1dfa23
Capture warnings via the logging system.
tonyandrewmeyer Dec 10, 2024
dd74ea6
Adjust the stack level dynamically.
tonyandrewmeyer Dec 10, 2024
19067bc
Use a logging.warning, and wrap it so it happens later.
tonyandrewmeyer Dec 10, 2024
bfdb2d4
Clarify comment.
tonyandrewmeyer Dec 10, 2024
bda9c1a
Remove unnecessary change.
tonyandrewmeyer Dec 10, 2024
2aba608
Remove unnecessary change.
tonyandrewmeyer Dec 10, 2024
1e1c724
Go back to issuing a real warning.
tonyandrewmeyer Dec 11, 2024
138fc56
Remove the ops.main.main deprecation warning, as per Charm-Tech discu…
tonyandrewmeyer Dec 18, 2024
3a7437a
Capture warnings via the logging system.
tonyandrewmeyer Dec 10, 2024
a589f26
Adjust showwarning, not formatwarning.
tonyandrewmeyer Dec 18, 2024
3bd3f98
Customising showwarning means actually doing, not formatting.
tonyandrewmeyer Dec 18, 2024
5c5b87a
Match the upstream signature.
tonyandrewmeyer Jan 20, 2025
dfb4a7a
Keep validating that the legacy calls work, just don't verify they ha…
tonyandrewmeyer Jan 22, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 20 additions & 2 deletions ops/log.py
View file
Open in desktop
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[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)
Copy link
Contributor

Choose a reason for hiding this comment

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

what do you think about using warnings.formatwarning(...) to replicate what showwarning does, that is tries to load the source code and show where the warning was issued?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I don't like unstructured log entries that have newlines in them, and I don't think it's ideal to have code snippets in the Juju debug log. However, we do both of those for exceptions already, so perhaps that doesn't matter. However, I don't think it's that useful for warnings. The default warnings formatter looks like:

/tmp/fw.py:4: DeprecationWarning: Don't call foo(), use the new bar() instead
  warnings.warn("Don't call foo(), use the new bar() instead", DeprecationWarning)

That second line is telling me nothing that the first line hasn't already. Maybe the line has something other than the warnings.warn call that provides extra context, but in my experience that's unusual.

That would currently show something like:

unit-my-charm-0: 10:07:20 INFO unit.my-charm/0.juju-log charm.py:42: DeprecationWarning: Don't call foo(), use the new bar() instead

I feel like that's a better form for an unstructured log message.

Copy link
Contributor

Choose a reason for hiding this comment

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

I guess that depends on whether the end user looks at single messages are series of messages.

Don't call foo(), use the new bar() instead is great if there's a single call to foo(), and not so much if there are hundreds, or if there's no obvious call, as in a case of being called via getattr(<computed>)().

I can see benefits for both alternatives, I guess.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Don't call foo(), use the new bar() instead is great if there's a single call to foo(), and not so much if there are hundreds, or if there's no obvious call, as in a case of being called via getattr(<computed>)().

But you still have the filename and the line number. You don't have the exact line of code, but assuming you have access to it, it's trivial to open that file and go to that line number. You don't get a full traceback with the default formatter, so you only have the line the warning was pointing at - which is hopefully using a stacklevel that is one up from the actual warning.warn call.

For example:

# charm.py
class MyCharm(ops.CharmBase):
    ...
    def _on_something(self, event):
        self.foo() # first one
        ...

    def _on_something_else(self, event):
        self.foo() # second one

    def foo(self):
        warnings.warn("don't foo(), do bar()", DeprecationWarning, stacklevel=2)

When _on_something is called, there will be a Juju log entry that points you at charm.py to the line with "# first one", and when on_something_else is called, there will be a Juju log entry that points you at charm.py to the line with "# second one".

If we include the actual code, like the default formatter, then you'd also have in the Juju debug log those actual lines of code, but I don't think this really gains you much (especially when it's a warning aimed at the developer, who will have access to the code) - and it saves having a multi-line log entry.


warnings.showwarning = custom_showwarning
tonyandrewmeyer marked this conversation as resolved.
Show resolved Hide resolved

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
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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: 4 additions & 8 deletions test/test_main_invocation.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -52,8 +52,7 @@ def test_top_level_import(charm_env: None):
def test_top_level_import_legacy_call(charm_env: None):
import ops

tonyandrewmeyer marked this conversation as resolved.
Show resolved Hide resolved
with pytest.deprecated_call():
ops.main.main(ops.CharmBase)
ops.main.main(ops.CharmBase)

with pytest.raises(TypeError):
ops.main.main() # type: ignore
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
12 changes: 11 additions & 1 deletion testing/src/scenario/_ops_main_mock.py
View file
Open in desktop
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