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

Improve context logging

subiquity/client/client.py

@@ -265,10 +265,9 @@ async def noninteractive_watch_app_state(self, initial_status):
             app_status = await self._status_get(app_state)
 
     def subiquity_event_noninteractive(self, event):
-        if event["SUBIQUITY_EVENT_TYPE"] == "start":
-            print("start: " + event["MESSAGE"])
-        elif event["SUBIQUITY_EVENT_TYPE"] == "finish":
-            print("finish: " + event["MESSAGE"])
+        event_type = event["SUBIQUITY_EVENT_TYPE"]
+        message = event["MESSAGE"]
+        print(f"{event_type}: {message}")
 
     async def connect(self):
         def p(s):
@@ -379,7 +378,9 @@ def header_func():
                 # 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 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 @@ def publish_event(self, event):
 NON_INTERACTIVE_CONFIG = {"builtin": {"type": "print"}}
 
 
-class ReportingController(NonInteractiveController):
+class ReportingController(EventListener, NonInteractiveController):
     autoinstall_key = "reporting"
     autoinstall_schema = {
         "type": "object",
@@ -76,3 +84,18 @@ def report_finish_event(self, context, description, result):
         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 @@ def test_valid_schema(self):
         )
 
         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,14 +46,15 @@
 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
 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 @@ def __init__(self, opts, block_log_dir):
             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 @@ def load_serialized_state(self):
         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):
-        if not context.get("is-install-context") and self.interactive in [True, None]:
-            controller = context.get("controller")
+    def _maybe_push_to_journal(
+        self,
+        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
-        indent = context.full_name().count("/") - 2
-        if context.get("is-install-context") and self.interactive:
+
+        # Create the message out of the name of the reporter and optionally
+        # the description
+        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()
-            if description:
-                msg += ": " + description
-        msg = "  " * indent + msg
-        if context.parent:
+
+        indent_prefix: str = " " * indent
+        formatted_message: str = f"{indent_prefix}{msg}"
+
+        if context.parent is not None:
             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 @@ def report_finish_event(self, context, description, status):
             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