Merge pull request #1945 from Chris-Peterson444/context-logging

Improve context logging

subiquity/client/client.py

@@ -265,10 +265,9 @@ class SubiquityClient(TuiApplication):
             app_status = await self._status_get(app_state)
 
     def subiquity_event_noninteractive(self, event):
-        if event["SUBIQUITY_EVENT_TYPE"] == "start":
+        event_type = event["SUBIQUITY_EVENT_TYPE"]
-            print("start: " + event["MESSAGE"])
+        message = event["MESSAGE"]
-        elif event["SUBIQUITY_EVENT_TYPE"] == "finish":
+        print(f"{event_type}: {message}")
-            print("finish: " + event["MESSAGE"])
 
     async def connect(self):
         def p(s):
@@ -379,7 +378,9 @@ class SubiquityClient(TuiApplication):
                 # prompting for confirmation will be confusing.
                 os.system("stty sane")
             journald_listen(
-                [status.event_syslog_id], self.subiquity_event_noninteractive, seek=True
+                [status.event_syslog_id],
+                self.subiquity_event_noninteractive,
+                seek=False,
             )
             run_bg_task(self.noninteractive_watch_app_state(status))
 

subiquity/server/controllers/reporting.py

@@ -17,10 +17,18 @@ import copy
 import logging
 
 from curtin.reporter import available_handlers, update_configuration
-from curtin.reporter.events import report_finish_event, report_start_event, status
+from curtin.reporter.events import (
+    ReportingEvent,
+    report_event,
+    report_finish_event,
+    report_start_event,
+    status,
+)
 from curtin.reporter.handlers import LogHandler as CurtinLogHandler
 
 from subiquity.server.controller import NonInteractiveController
+from subiquity.server.event_listener import EventListener
+from subiquitycore.context import Context
 
 
 class LogHandler(CurtinLogHandler):
@@ -39,7 +47,7 @@ INITIAL_CONFIG = {
 NON_INTERACTIVE_CONFIG = {"builtin": {"type": "print"}}
 
 
-class ReportingController(NonInteractiveController):
+class ReportingController(EventListener, NonInteractiveController):
     autoinstall_key = "reporting"
     autoinstall_schema = {
         "type": "object",
@@ -76,3 +84,18 @@ class ReportingController(NonInteractiveController):
         report_finish_event(
             context.full_name(), description, result, level=context.level
         )
+
+    def report_info_event(self, context: Context, message: str):
+        """Report an "info" event."""
+        event = ReportingEvent("info", context.full_name(), message, level="INFO")
+        report_event(event)
+
+    def report_warning_event(self, context: Context, message: str):
+        """Report a "warning" event."""
+        event = ReportingEvent("warning", context.full_name(), message, level="WARNING")
+        report_event(event)
+
+    def report_error_event(self, context: Context, message: str):
+        """Report an "error" event."""
+        event = ReportingEvent("error", context.full_name(), message, level="ERROR")
+        report_event(event)

subiquity/server/controllers/tests/test_reporting.py

@@ -13,11 +13,17 @@
 # You should have received a copy of the GNU Affero General Public License
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
+from unittest.mock import Mock, patch
+
 import jsonschema
+from curtin.reporter.events import status as CurtinStatus
 from jsonschema.validators import validator_for
 
 from subiquity.server.controllers.reporting import ReportingController
+from subiquitycore.context import Context
+from subiquitycore.context import Status as ContextStatus
 from subiquitycore.tests import SubiTestCase
+from subiquitycore.tests.mocks import MockedApplication, make_app
 
 
 class TestReportingController(SubiTestCase):
@@ -29,3 +35,85 @@ class TestReportingController(SubiTestCase):
         )
 
         JsonValidator.check_schema(ReportingController.autoinstall_schema)
+
+
+@patch("subiquity.server.controllers.reporting.report_event")
+class TestReportingCurtinCalls(SubiTestCase):
+    def setUp(self):
+        app: MockedApplication = make_app()
+        self.controller: ReportingController = ReportingController(app)
+        self.context: Context = app.context
+
+    @patch("subiquity.server.controllers.reporting.report_start_event")
+    def test_start_event(self, report_start_event, report_event):
+        self.controller.report_start_event(self.context, "description")
+
+        # Calls specific start event method
+        report_start_event.assert_called_with(
+            self.context.full_name(), "description", level=self.context.level
+        )
+
+        # Not the generic one
+        report_event.assert_not_called()
+
+    @patch("subiquity.server.controllers.reporting.report_finish_event")
+    def test_finish_event(self, report_finish_event, report_event):
+        self.controller.report_finish_event(
+            self.context, "description", ContextStatus.FAIL
+        )
+
+        # Calls specific finish event method
+        report_finish_event.assert_called_with(
+            self.context.full_name(),
+            "description",
+            CurtinStatus.FAIL,
+            level=self.context.level,
+        )
+
+        # Not the generic one
+        report_event.assert_not_called()
+
+        # Test default WARN
+        status = Mock()
+        status.name = "NEW LEVEL"
+        self.controller.report_finish_event(self.context, "description", status)
+
+        report_finish_event.assert_called_with(
+            self.context.full_name(),
+            "description",
+            CurtinStatus.WARN,
+            level=self.context.level,
+        )
+
+    @patch("subiquity.server.controllers.reporting.ReportingEvent")
+    def test_info_event(self, mock_class, report_event):
+        self.controller.report_info_event(self.context, "description")
+
+        mock_class.assert_called_with(
+            "info",
+            self.context.full_name(),
+            "description",
+            level="INFO",
+        )
+
+    @patch("subiquity.server.controllers.reporting.ReportingEvent")
+    def test_warning_event(self, mock_class, report_event):
+        self.controller.report_warning_event(self.context, "description")
+
+        mock_class.assert_called_with(
+            "warning",
+            self.context.full_name(),
+            "description",
+            level="WARNING",
+        )
+
+    @patch("subiquity.server.controllers.reporting.ReportingEvent")
+    def test_error_event(self, mock_class, report_event):
+        self.controller.report_error_event(self.context, "description")
+
+        mock_class.assert_called_with(
+            "error",
+            self.context.full_name(),
+            "description",
+            level="ERROR",
+        )

subiquity/server/event_listener.py

@@ -0,0 +1,44 @@
+# Copyright 2024 Canonical, Ltd.
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as
+# published by the Free Software Foundation, either version 3 of the
+# License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+from abc import ABC, abstractmethod
+from typing import Any
+
+from subiquitycore.context import Context
+
+
+class EventListener(ABC):
+    """Interface for SubiquitySever event listeners"""
+
+    @abstractmethod
+    def report_start_event(self, context: Context, description: str) -> None:
+        """Report a "start" event."""
+
+    @abstractmethod
+    def report_finish_event(
+        self, context: Context, description: str, result: Any
+    ) -> None:
+        """Report a "finish" event."""
+
+    @abstractmethod
+    def report_info_event(self, context: Context, message: str) -> None:
+        """Report an "info" event."""
+
+    @abstractmethod
+    def report_warning_event(self, context: Context, message: str) -> None:
+        """Report a "warning" event."""
+
+    @abstractmethod
+    def report_error_event(self, context: Context, message: str) -> None:
+        """Report an "error" event."""

subiquity/server/server.py

@@ -46,6 +46,7 @@ from subiquity.server.autoinstall import AutoinstallValidationError
 from subiquity.server.controller import SubiquityController
 from subiquity.server.dryrun import DRConfig
 from subiquity.server.errors import ErrorController
+from subiquity.server.event_listener import EventListener
 from subiquity.server.geoip import DryRunGeoIPStrategy, GeoIP, HTTPGeoIPStrategy
 from subiquity.server.nonreportable import NonReportableException
 from subiquity.server.pkghelper import get_package_installer
@@ -53,7 +54,7 @@ from subiquity.server.runner import get_command_runner
 from subiquity.server.snapdapi import make_api_client
 from subiquity.server.types import InstallerChannels
 from subiquitycore.async_helpers import run_bg_task, run_in_thread
-from subiquitycore.context import with_context
+from subiquitycore.context import Context, with_context
 from subiquitycore.core import Application
 from subiquitycore.file_util import copy_file_if_exists, write_file
 from subiquitycore.prober import Prober
@@ -326,7 +327,7 @@ class SubiquityServer(Application):
             log.info("no snapd socket found. Snap support is disabled")
             self.snapd = None
         self.note_data_for_apport("SnapUpdated", str(self.updated))
-        self.event_listeners = []
+        self.event_listeners: list[EventListener] = []
         self.autoinstall_config = None
         self.hub.subscribe(InstallerChannels.NETWORK_UP, self._network_change)
         self.hub.subscribe(InstallerChannels.NETWORK_PROXY_SET, self._proxy_set)
@@ -344,31 +345,77 @@ class SubiquityServer(Application):
         for controller in self.controllers.instances:
             controller.load_state()
 
-    def add_event_listener(self, listener):
+    def add_event_listener(self, listener: EventListener):
         self.event_listeners.append(listener)
 
-    def _maybe_push_to_journal(self, event_type, context, description):
+    def _maybe_push_to_journal(
-        if not context.get("is-install-context") and self.interactive in [True, None]:
+        self,
-            controller = context.get("controller")
+        event_type: str,
+        context: Context,
+        description: Optional[str],
+    ):
+        # No reporting for request handlers
+        if context.get("request", default=None) is not None:
+            return
+
+        install_context: bool = context.get("is-install-context", default=False)
+        msg: str = ""
+        parent_id: str = ""
+        indent: int = context.full_name().count("/") - 2
+
+        # We do filtering on which types of events get reported.
+        # For interactive installs, we only want to report the event
+        # if it's coming from a non-interactive context. The user is aware
+        # of the changes being made in interactive sections so lets skip
+        # reporting those events.
+        #
+        # The exceptions to this are:
+        #     - special sections of the install, which set "is-install-context"
+        #       where we want to report the event anyways
+        #
+        #     - special event types:
+        #       - warn
+        #       - error
+        #
+        # For non-interactive installs (i.e., full autoinstall) we report
+        # everything.
+
+        force_reporting: bool = install_context or event_type in ["warning", "error"]
+
+        # self.interactive=None could be an interactive install, we just
+        # haven't found out yet
+        if self.interactive in [True, None] and not force_reporting:
+            # If the event came from a controller and it's interactive,
+            # or there's no associated controller so we can't be sure,
+            # skip reporting.
+            controller = context.get("controller", default=None)
             if controller is None or controller.interactive():
                 return
-        if context.get("request"):
+
-            return
+        # Create the message out of the name of the reporter and optionally
-        indent = context.full_name().count("/") - 2
+        # the description
-        if context.get("is-install-context") and self.interactive:
+        name: str = context.full_name()
+        if description is not None:
+            msg = f"{name}: {description}"
+        else:
+            msg = name
+
+        # Special case: events from special install contexts which are also
+        # interactive get special formatting
+        if self.interactive and install_context:
             indent -= 1
             msg = context.description
-        else:
+
-            msg = context.full_name()
+        indent_prefix: str = " " * indent
-            if description:
+        formatted_message: str = f"{indent_prefix}{msg}"
-                msg += ": " + description
+
-        msg = "  " * indent + msg
+        if context.parent is not None:
-        if context.parent:
             parent_id = str(context.parent.id)
         else:
             parent_id = ""
+
         journal.send(
-            msg,
+            formatted_message,
             PRIORITY=context.level,
             SYSLOG_IDENTIFIER=self.event_syslog_id,
             SUBIQUITY_CONTEXT_NAME=context.full_name(),
@@ -387,6 +434,21 @@ class SubiquityServer(Application):
             listener.report_finish_event(context, description, status)
         self._maybe_push_to_journal("finish", context, description)
 
+    def report_info_event(self, context: Context, message: str) -> None:
+        for listener in self.event_listeners:
+            listener.report_info_event(context, message)
+        self._maybe_push_to_journal("info", context, message)
+
+    def report_warning_event(self, context: Context, message: str) -> None:
+        for listener in self.event_listeners:
+            listener.report_warning_event(context, message)
+        self._maybe_push_to_journal("warning", context, message)
+
+    def report_error_event(self, context: Context, message: str) -> None:
+        for listener in self.event_listeners:
+            listener.report_error_event(context, message)
+        self._maybe_push_to_journal("error", context, message)
+
     @property
     def state(self):
         return self._state

subiquity/server/tests/test_server.py

@@ -24,14 +24,17 @@ from subiquity.common.types import NonReportableError, PasswordKind
 from subiquity.server.autoinstall import AutoinstallValidationError
 from subiquity.server.nonreportable import NonReportableException
 from subiquity.server.server import (
+    NOPROBERARG,
     MetaController,
     SubiquityServer,
     cloud_autoinstall_path,
     iso_autoinstall_path,
     root_autoinstall_path,
 )
+from subiquitycore.context import Context
 from subiquitycore.tests import SubiTestCase
 from subiquitycore.tests.mocks import make_app
+from subiquitycore.tests.parameterized import parameterized
 from subiquitycore.utils import run_command
 
 
@@ -313,3 +316,143 @@ class TestExceptionHandling(SubiTestCase):
         self.server.make_apport_report.assert_called()
         self.assertIsNotNone(self.server.fatal_error)
         self.assertIsNone(self.server.nonreportable_error)
+
+
+class TestEventReporting(SubiTestCase):
+    async def asyncSetUp(self):
+        opts = Mock()
+        opts.dry_run = True
+        opts.output_base = self.tmp_dir()
+        opts.machine_config = NOPROBERARG
+        self.server = SubiquityServer(opts, None)
+
+    @parameterized.expand(
+        (
+            # A very tedious to read truth table for testing
+            # behavior. A value of None should mean another
+            # option is shadowing the importance of that value
+            # ex: in the is-install-context it doesn't matter
+            # if it came from a controller. Except interactive=None
+            # is a valid value.
+            #
+            #
+            #  -> Special "is-install-context" to force logging
+            # |     -> Install is interactive
+            # |    |      -> Comes from a controller
+            # |    |     |      -> That controller is interactive
+            # |    |     |     |      -> Expected to send
+            # |    |     |     |     |
+            (True, True, None, None, True),
+            (True, False, None, None, True),
+            (True, None, None, None, True),
+            (False, True, None, None, False),
+            (False, True, True, True, False),
+            (False, True, True, False, True),
+            (False, False, False, None, True),
+        )
+    )
+    async def test_maybe_push_to_journal(
+        self,
+        is_install_context,
+        interactive,
+        from_controller,
+        controller_is_interactive,
+        expected_to_send,
+    ):
+        context: Context = Context(
+            self.server, "MockContext", "description", None, "INFO"
+        )
+
+        context.set("is-install-context", is_install_context)
+        self.server.interactive = interactive
+        if from_controller:
+            controller = Mock()
+            controller.interactive = lambda: controller_is_interactive
+            context.set("controller", controller)
+
+        with patch("subiquity.server.server.journal.send") as journal_send_mock:
+            self.server._maybe_push_to_journal(
+                "event_type", context, context.description
+            )
+        if expected_to_send:
+            journal_send_mock.assert_called_once()
+        else:
+            journal_send_mock.assert_not_called()
+
+    @parameterized.expand(
+        (
+            # interactive, pushed to journal
+            (True, False),
+            (None, False),
+            (False, True),
+        )
+    )
+    def test_push_info_events(self, interactive, expect_pushed):
+        """Test info event publication"""
+
+        context: Context = Context(
+            self.server, "MockContext", "description", None, "INFO"
+        )
+        self.server.interactive = interactive
+
+        with patch("subiquity.server.server.journal.send") as journal_send_mock:
+            self.server.report_info_event(context, "message")
+
+        if not expect_pushed:
+            journal_send_mock.assert_not_called()
+        else:
+            journal_send_mock.assert_called_once()
+            # message is the only positional argument
+            (message,) = journal_send_mock.call_args.args
+            self.assertIn("message", message)
+            self.assertNotIn("description", message)
+
+    @parameterized.expand(
+        (
+            # interactive
+            (True,),
+            (None,),
+            (False,),
+        )
+    )
+    def test_push_warning_events(self, interactive):
+        """Test warning event publication"""
+
+        context: Context = Context(
+            self.server, "MockContext", "description", None, "INFO"
+        )
+        self.server.interactive = interactive
+
+        with patch("subiquity.server.server.journal.send") as journal_send_mock:
+            self.server.report_warning_event(context, "message")
+
+        journal_send_mock.assert_called_once()
+        # message is the only positional argument
+        (message,) = journal_send_mock.call_args.args
+        self.assertIn("message", message)
+        self.assertNotIn("description", message)
+
+    @parameterized.expand(
+        (
+            # interactive
+            (True,),
+            (None,),
+            (False,),
+        )
+    )
+    def test_push_error_events(self, interactive):
+        """Test error event publication"""
+
+        context: Context = Context(
+            self.server, "MockContext", "description", None, "INFO"
+        )
+        self.server.interactive = interactive
+
+        with patch("subiquity.server.server.journal.send") as journal_send_mock:
+            self.server.report_error_event(context, "message")
+
+        journal_send_mock.assert_called_once()
+        # message is the only positional argument
+        (message,) = journal_send_mock.call_args.args
+        self.assertIn("message", message)
+        self.assertNotIn("description", message)

subiquitycore/context.py

@@ -118,6 +118,15 @@ class Context:
             c = c.parent
         return default
 
+    def info(self, message: str) -> None:
+        self.app.report_info_event(self, message)
+
+    def warning(self, message: str) -> None:
+        self.app.report_warning_event(self, message)
+
+    def error(self, message: str) -> None:
+        self.app.report_error_event(self, message)
+
 
 def with_context(name=None, description="", **context_kw):
     def decorate(meth):

subiquitycore/tests/mocks.py

@@ -36,6 +36,7 @@ def make_app(model=None):
         app.base_model = model
     else:
         app.base_model = mock.Mock()
+    app.add_event_listener = mock.Mock()
     app.controllers = mock.Mock()
     app.context = Context.new(app)
     app.exit = mock.Mock()