Repository: canonical/operator

Issue:
Actions: errors are captured to debug-log and are not in stderr
Setting stdout, stderr in event.set_results, always ends up with a failed action, but it never explains why it failed.

Consider the following charm:

```python
import logging

import ops

# Log messages can be retrieved using juju debug-log
logger = logging.getLogger(__name__)

VALID_LOG_LEVELS = ["info", "debug", "warning", "error", "critical"]


class ActionTestCharm(ops.CharmBase):
    """Charm the service."""

    def __init__(self, *args):
        super().__init__(*args)
        self.framework.observe(self.on.fail_action_action, self._on_fail_action_action)
        self.framework.observe(self.on.success_action_action, self._on_success_action_action)

    def _on_fail_action_action(self, event):
        event.fail("Fail action failed")

    def _on_success_action_action(self, event):
        event.log("Success action completed successfully")
        event.set_results({"stdout":"fail me"})


if __name__ == "__main__":  # pragma: nocover
    ops.main(ActionTestCharm)  # type: ignore
```

This will always fail (against juju 3.1).

```sh
juju run action-test/leader success-action
Running operation 69 with 1 task
  - task 70 on unit-action-test-0

Waiting for task 70...
08:01:18 Success action completed successfully

ERROR the following task failed:
 - id "70" with return code 1

use 'juju show-task' to inspect the failure
```

If we run the same with bash as our invocation hook rather than python.

```bash
#!/bin/bash
action-set stdout="something something something"

echo Hello
exit 0
```

We get the following:

```sh
juju run bash-test/0 hello
Running operation 103 with 1 task
  - task 104 on unit-bash-test-0

Waiting for task 104...
08:25:21 Hello

Goodbye cruel world
ERROR cannot set reserved action key "stdout"
```

~~I'd expect it to be the same as bash, but clearly, something isn't quite right.~~

Addendum:

Setting the following in bash does reveal the same results as the framework. I guess the problem is framework doesn't expose why it failed, just that it did.

```bash
#!/bin/bash
set -eux
action-set stdout="something something something"

echo Hello
exit 0
```

Discussion:
tonyandrewmeyer: @benhoyt three things here before this can be properly reviewed:

* [ ] I imagine there's some bikeshedding required for the argument name to `setup_root_logging` that controls this behaviour.
* [ ] We need to finalise on what the output would look like (#1078 has examples from actual crashes when doing `juju run`). My preference is on the shorter version, primarily because I think the traceback is more for the Charm author than the action running user. We could switch to the full version, and we can also tweak wording and to some extent spacing.
* [ ] What's your opinion on tests here? I don't think I can test the actual sys.excepthook in the main process. I could add a test like the main ones that have a Charm in a subprocess, get it to crash, and capture stderr. Do you think that's worthwhile? Or have a better idea about how to add an automated test for this?
tonyandrewmeyer: The real pebble tests fail because of the [macaroonbakery issue](https://chat.charmhub.io/charmhub/pl/w8nc98aus3fttxqqtjmmcrbace). The data charm tests fail since 2.9 it seems, although it must be some change on the other side too or we would have caught it before release - looking into that.
tonyandrewmeyer: Notes from talking in person:

> * [ ]  I imagine there's some bikeshedding required for the argument name to `setup_root_logging` that controls this behaviour.

Existing name is fine, `setup_root_logging` probably ought to have been `_setup_root_logging` and this shouldn't impact anyone.

> * [ ]  We need to finalise on what the output would look like ([Actions: errors are captured to debug-log and are not in stderr #1078](https://github.com/canonical/operator/issues/1078) has examples from actual crashes when doing `juju run`). My preference is on the shorter version, primarily because I think the traceback is more for the Charm author than the action running user. We could switch to the full version, and we can also tweak wording and to some extent spacing.

Keep as-is other than one small suggestion.

> * [ ]  What's your opinion on tests here? I don't think I can test the actual sys.excepthook in the main process. I could add a test like the main ones that have a Charm in a subprocess, get it to crash, and capture stderr. Do you think that's worthwhile? Or have a better idea about how to add an automated test for this?

Add a `test_main` test that has a failing action, check for the core pieces rather than character-exact matching.

Patch:
diff --git a/ops/log.py b/ops/log.py
index e167c6d..d64aa4a 100644
--- a/ops/log.py
+++ b/ops/log.py
@@ -38,7 +38,8 @@ class JujuLogHandler(logging.Handler):
         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 setup_root_logging(model_backend: _ModelBackend, debug: bool = False):
         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 9cfb720..7eeeab2 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)


Test patch:
diff --git a/test/charms/test_main/actions.yaml b/test/charms/test_main/actions.yaml
index d16c942..1eca1b7 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 bd4ea79..bb6312d 100755
--- a/test/charms/test_main/src/charm.py
+++ b/test/charms/test_main/src/charm.py
@@ -103,6 +103,7 @@ class Charm(ops.CharmBase):
             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 @@ class Charm(ops.CharmBase):
         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 5eae418..7cfa51c 100644
--- a/test/test_main.py
+++ b/test/test_main.py
@@ -342,7 +342,7 @@ class _TestMain(abc.ABC):
         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 @@ class _TestMainWithDispatch(_TestMain):
 
         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 @@ class TestMainWithDispatch(_TestMainWithDispatch, unittest.TestCase):
         )
         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."""