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

@@ -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

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)

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:

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

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."""