From d0f1d3cde9b99d736a01b430b9e54dd7956e9b71 Mon Sep 17 00:00:00 2001 From: Tony Meyer Date: Fri, 15 Dec 2023 16:17:07 +1300 Subject: [PATCH] feat: when handling actions, print uncaught exceptions to stderr (#1087) When handling an action and an exception is not caught, output basic information about the problem to stderr, and let the user know that a full traceback (that the Charm author probably wants, rather than the user running the action) is in debug-log. --- ops/log.py | 8 +++++++- ops/main.py | 6 +++++- test/charms/test_main/actions.yaml | 2 ++ test/charms/test_main/src/charm.py | 8 +++++++- test/test_main.py | 22 +++++++++++++++++++--- 5 files changed, 40 insertions(+), 6 deletions(-) diff --git a/ops/log.py b/ops/log.py index e167c6d1a..d64aa4a8d 100644 --- a/ops/log.py +++ b/ops/log.py @@ -38,7 +38,8 @@ def emit(self, record: logging.LogRecord): self.model_backend.juju_log(record.levelname, self.format(record)) -def setup_root_logging(model_backend: _ModelBackend, debug: bool = False): +def setup_root_logging(model_backend: _ModelBackend, debug: bool = False, + exc_stderr: bool = False): """Setup python logging to forward messages to juju-log. By default, logging is set to DEBUG level, and messages will be filtered by Juju. @@ -49,6 +50,7 @@ def setup_root_logging(model_backend: _ModelBackend, debug: bool = False): Args: model_backend: a ModelBackend to use for juju-log debug: if True, write logs to stderr as well as to juju-log. + exc_stderr: if True, write uncaught exceptions to stderr as well as to juju-log. """ logger = logging.getLogger() logger.setLevel(logging.DEBUG) @@ -65,5 +67,9 @@ def except_hook(etype: typing.Type[BaseException], logger.error( "Uncaught exception while in charm code:", exc_info=(etype, value, tb)) + if exc_stderr: + print(f"Uncaught {etype.__name__} in charm code: {value}", + file=sys.stderr) + print("Use `juju debug-log` to see the full traceback.", file=sys.stderr) sys.excepthook = except_hook diff --git a/ops/main.py b/ops/main.py index 9cfb7201e..7eeeab267 100644 --- a/ops/main.py +++ b/ops/main.py @@ -379,7 +379,11 @@ def main(charm_class: Type[ops.charm.CharmBase], model_backend = ops.model._ModelBackend() debug = ('JUJU_DEBUG' in os.environ) - setup_root_logging(model_backend, debug=debug) + # For actions, there is a communication channel with the user running the + # action, so we want to send exception details through stderr, rather than + # only to juju-log as normal. + handling_action = ('JUJU_ACTION_NAME' in os.environ) + setup_root_logging(model_backend, debug=debug, exc_stderr=handling_action) logger.debug("ops %s up and running.", ops.__version__) # type:ignore dispatcher = _Dispatcher(charm_dir) diff --git a/test/charms/test_main/actions.yaml b/test/charms/test_main/actions.yaml index d16c94204..1eca1b7ed 100644 --- a/test/charms/test_main/actions.yaml +++ b/test/charms/test_main/actions.yaml @@ -17,6 +17,8 @@ get-model-name: description: Return the name of the model get-status: description: Return the Status of the unit +keyerror: + description: Raise a KeyError (to see crash output) log-critical: description: log a message at Critical level log-error: diff --git a/test/charms/test_main/src/charm.py b/test/charms/test_main/src/charm.py index bd4ea799c..bb6312dae 100755 --- a/test/charms/test_main/src/charm.py +++ b/test/charms/test_main/src/charm.py @@ -103,6 +103,7 @@ def __init__(self, *args: typing.Any): self.framework.observe(self.on.foo_bar_action, self._on_foo_bar_action) self.framework.observe(self.on.get_model_name_action, self._on_get_model_name_action) self.framework.observe(self.on.get_status_action, self._on_get_status_action) + self.framework.observe(self.on.keyerror_action, self._on_keyerror_action) self.framework.observe(self.on.log_critical_action, self._on_log_critical_action) self.framework.observe(self.on.log_error_action, self._on_log_error_action) @@ -235,10 +236,15 @@ def _on_foo_bar_action(self, event: ops.ActionEvent): self._stored.on_foo_bar_action.append(type(event).__name__) self._stored.observed_event_types.append(type(event).__name__) - def _on_get_status_action(self, event: ops.CollectStatusEvent): + def _on_get_status_action(self, event: ops.ActionEvent): self._stored.status_name = self.unit.status.name self._stored.status_message = self.unit.status.message + def _on_keyerror_action(self, event: ops.ActionEvent): + # Deliberately raise an uncaught exception, so that we can observe the + # behaviour when an action crashes. + raise KeyError("'foo' not found in 'bar'") + def _on_collect_metrics(self, event: ops.CollectMetricsEvent): self._stored.on_collect_metrics.append(type(event).__name__) self._stored.observed_event_types.append(type(event).__name__) diff --git a/test/test_main.py b/test/test_main.py index 5eae41889..7cfa51ce1 100644 --- a/test/test_main.py +++ b/test/test_main.py @@ -342,7 +342,7 @@ def _prepare_actions(self): actions_dir_name = 'actions' actions_dir = self.JUJU_CHARM_DIR / actions_dir_name actions_dir.mkdir() - for action_name in ('start', 'foo-bar', 'get-model-name', 'get-status'): + for action_name in ('start', 'foo-bar', 'get-model-name', 'get-status', 'keyerror'): self._setup_entry_point(actions_dir, action_name) def _read_and_clear_state(self, @@ -1028,6 +1028,8 @@ def test_hook_and_dispatch_with_failing_hook(self): self.stdout.seek(0) self.assertEqual(self.stdout.read(), b'') + self.stderr.seek(0) + self.assertEqual(self.stderr.read(), b'') calls = fake_script_calls(typing.cast(unittest.TestCase, self)) hook = Path('hooks/install') expected = [ @@ -1153,10 +1155,24 @@ def _call_event(self, rel_path: Path, env: typing.Dict[str, str]): ) subprocess.run( [sys.executable, str(dispatch)], - # stdout=self.stdout, - # stderr=self.stderr, + stdout=self.stdout, + stderr=self.stderr, check=True, env=env, cwd=str(self.JUJU_CHARM_DIR)) + def test_crash_action(self): + self._prepare_actions() + self.stderr = tempfile.TemporaryFile('w+t') + self.addCleanup(self.stderr.close) + fake_script(typing.cast(unittest.TestCase, self), 'action-get', "echo '{}'") + with self.assertRaises(subprocess.CalledProcessError): + self._simulate_event(EventSpec( + ops.ActionEvent, 'keyerror_action', + env_var='JUJU_ACTION_NAME')) + self.stderr.seek(0) + stderr = self.stderr.read() + self.assertIn('KeyError', stderr) + self.assertIn("'foo' not found in 'bar'", stderr) + class TestMainWithDispatchAsScript(_TestMainWithDispatch, unittest.TestCase): """Here dispatch is a script that execs the charm.py instead of a symlink."""