From e0f02a74d76bae844c0c704c530055bd55ee4be7 Mon Sep 17 00:00:00 2001 From: Chris Peterson Date: Tue, 5 Mar 2024 19:07:39 -0800 Subject: [PATCH 1/5] server: add tests for publishing journal events Currently there is a lot of state used to determine which events get published to the journal. This is a baseline before changing behavor. --- subiquity/server/tests/test_server.py | 53 +++++++++++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/subiquity/server/tests/test_server.py b/subiquity/server/tests/test_server.py index 4fd562afc..0eaec7bee 100644 --- a/subiquity/server/tests/test_server.py +++ b/subiquity/server/tests/test_server.py @@ -24,14 +24,17 @@ 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,53 @@ async def test_not_suppressed_apport_reporting(self): 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 incomprehensible truth table for testing code behavior + # This is probably collapsable, but I need a baseline + (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() From c25e28ef2cd97ffff96fff7019fc8b841f146ade Mon Sep 17 00:00:00 2001 From: Chris Peterson Date: Tue, 5 Mar 2024 20:32:44 -0800 Subject: [PATCH 2/5] server: refactor _maybe_push_to_journal --- subiquity/server/server.py | 75 +++++++++++++++++++++------ subiquity/server/tests/test_server.py | 16 +++++- 2 files changed, 74 insertions(+), 17 deletions(-) diff --git a/subiquity/server/server.py b/subiquity/server/server.py index e0e5ac17b..424fdea11 100644 --- a/subiquity/server/server.py +++ b/subiquity/server/server.py @@ -53,7 +53,7 @@ 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 @@ -347,28 +347,73 @@ def load_serialized_state(self): def add_event_listener(self, listener): 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 + # + # + # For non-interactive installs (i.e., full autoinstall) we report + # everything. + + force_reporting: bool = install_context + + # 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: + + # Otherwise it came from the server + + # 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(), diff --git a/subiquity/server/tests/test_server.py b/subiquity/server/tests/test_server.py index 0eaec7bee..d43035151 100644 --- a/subiquity/server/tests/test_server.py +++ b/subiquity/server/tests/test_server.py @@ -328,8 +328,20 @@ async def asyncSetUp(self): @parameterized.expand( ( - # A very incomprehensible truth table for testing code behavior - # This is probably collapsable, but I need a baseline + # 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), From 980411a67043a0c5fffefc22d07b6db8e83fb3b3 Mon Sep 17 00:00:00 2001 From: Chris Peterson Date: Wed, 20 Mar 2024 16:03:11 -0700 Subject: [PATCH 3/5] reporting: add new logging type events Adds new reporting type events "INFO", "WARNING", and "ERROR" to be used for context logging. These can be invoked with the new `.info`, `.warning`, and `.error` methods on the context object accordingly. Useful for things like warning/errors on autoinstall configuartions. --- subiquity/server/controllers/reporting.py | 24 ++++- .../controllers/tests/test_reporting.py | 88 +++++++++++++++++++ subiquity/server/server.py | 22 ++++- subiquity/server/tests/test_server.py | 78 ++++++++++++++++ subiquitycore/context.py | 9 ++ subiquitycore/tests/mocks.py | 1 + 6 files changed, 218 insertions(+), 4 deletions(-) diff --git a/subiquity/server/controllers/reporting.py b/subiquity/server/controllers/reporting.py index 90ad1ee70..c4d8bdab5 100644 --- a/subiquity/server/controllers/reporting.py +++ b/subiquity/server/controllers/reporting.py @@ -17,10 +17,17 @@ 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 subiquitycore.context import Context class LogHandler(CurtinLogHandler): @@ -76,3 +83,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) diff --git a/subiquity/server/controllers/tests/test_reporting.py b/subiquity/server/controllers/tests/test_reporting.py index 56ae4c196..aa692aa7f 100644 --- a/subiquity/server/controllers/tests/test_reporting.py +++ b/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 . +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", + ) diff --git a/subiquity/server/server.py b/subiquity/server/server.py index 424fdea11..cdee8ff0f 100644 --- a/subiquity/server/server.py +++ b/subiquity/server/server.py @@ -372,11 +372,14 @@ def _maybe_push_to_journal( # - 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 + 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 @@ -388,8 +391,6 @@ def _maybe_push_to_journal( if controller is None or controller.interactive(): return - # Otherwise it came from the server - # Create the message out of the name of the reporter and optionally # the description name: str = context.full_name() @@ -432,6 +433,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 diff --git a/subiquity/server/tests/test_server.py b/subiquity/server/tests/test_server.py index d43035151..292980f57 100644 --- a/subiquity/server/tests/test_server.py +++ b/subiquity/server/tests/test_server.py @@ -378,3 +378,81 @@ async def test_maybe_push_to_journal( 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) diff --git a/subiquitycore/context.py b/subiquitycore/context.py index 07c94d71c..bd1ca641a 100644 --- a/subiquitycore/context.py +++ b/subiquitycore/context.py @@ -118,6 +118,15 @@ def get(self, key, default=None): 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): diff --git a/subiquitycore/tests/mocks.py b/subiquitycore/tests/mocks.py index 748b97b55..a936b15f9 100644 --- a/subiquitycore/tests/mocks.py +++ b/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() From 0eb05d31e1d7cbd565e5a81d74102b47e57b626e Mon Sep 17 00:00:00 2001 From: Chris Peterson Date: Wed, 20 Mar 2024 16:04:42 -0700 Subject: [PATCH 4/5] client: support log-like events in non-interactive installs This changes the journal listener callback in the non-interactive scenario to support all types of events, not just start and finish events. This also modifies the journal listener in the non-interactive scenario to not seek all the way to the newest entry. In non-interactive installs, the server can get pretty far into the installation by the time the client can connect, so any important warnings/errors that the server reports before then wouldn't be printed to the console by the client otherwise. --- subiquity/client/client.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/subiquity/client/client.py b/subiquity/client/client.py index 88b7fde3d..d16080bec 100644 --- a/subiquity/client/client.py +++ b/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)) From ed8971f0b2eb125e7c835000bf6e9624f031b44d Mon Sep 17 00:00:00 2001 From: Chris Peterson Date: Fri, 22 Mar 2024 07:50:23 -0700 Subject: [PATCH 5/5] server: Create an interface for server event listeners --- subiquity/server/controllers/reporting.py | 3 +- subiquity/server/event_listener.py | 44 +++++++++++++++++++++++ subiquity/server/server.py | 5 +-- 3 files changed, 49 insertions(+), 3 deletions(-) create mode 100644 subiquity/server/event_listener.py diff --git a/subiquity/server/controllers/reporting.py b/subiquity/server/controllers/reporting.py index c4d8bdab5..b962b628f 100644 --- a/subiquity/server/controllers/reporting.py +++ b/subiquity/server/controllers/reporting.py @@ -27,6 +27,7 @@ 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 @@ -46,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", diff --git a/subiquity/server/event_listener.py b/subiquity/server/event_listener.py new file mode 100644 index 000000000..ac6af0860 --- /dev/null +++ b/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 . +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.""" diff --git a/subiquity/server/server.py b/subiquity/server/server.py index cdee8ff0f..638378646 100644 --- a/subiquity/server/server.py +++ b/subiquity/server/server.py @@ -46,6 +46,7 @@ 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 @@ -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,7 +345,7 @@ 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(