Report invalid units generated during test session (bugfix) (#1560)

Before this commit, if a template generated a unit that was invalid, a message was logged (error for some, debug for some others) and the unit was skipped. The logged message was hard to find, and it was not immediately clear that some jobs had not been generated due to templating errors.

This commit fixes this by introducing a new unit type (InvalidJob) and adding them to the test execution, so that errors in templating are surfaced in the test results as failures, and therefore easier to review and to fix.

This behavior is the new default, but it is possible to use the legacy behavior (to just log the problems without creating "InvalidJobs") by defining setting the `strict_template_expansion` flag to `False` in the `features` section of a configuration file.

* Implement late validation of template jobs

* Added metabox test

* Crash testplan

* Better unit invalid exception

* Full draft implementation of invalid units

* Remove unused imports and lemmas

* Make test positive

* Don't reset the flags, but add and remove from set

* Move SessionState_metadata resume before SessionState

* Make InvalidJob valid enough to run the tests

+ use __index__ instead of UUID

* Add Test for remote and local

* New metabox tests provider

* Check that the backward compatiblity works

* Revert downgrade of warning

* Fix tests for unit and ctrl

* Move warning in use_feature_flags

* Fully roll back downgrade to warning

* Test new filter and wrap function in ctrl.py

Minor: Also log warnings in wrapped units

* Also test observe_results with new flag

* New test for run_job

* Add experimental feature tests

* Verify that the infos are in the exception

* Typo

Co-authored-by: Pierre Equoy <[email protected]>

* Better description

---------

Co-authored-by: Pierre Equoy <[email protected]>

checkbox-ng/plainbox/impl/config.py

@@ -389,6 +389,17 @@ class DynamicSection(dict):
             ),
         },
     ),
+    (
+        "features",
+        {
+            "strict_template_expansion": VarSpec(
+                bool,
+                True,
+                "Invalid units generated by templates will be used and"
+                " reported as failures",
+            )
+        },
+    ),
     (
         "ui",
         {

checkbox-ng/plainbox/impl/ctrl.py

@@ -32,10 +32,6 @@ class to select the best method to execute a command of a particular job.  This
 circumstances.
 """
 
-import abc
-import contextlib
-import errno
-
 try:
     import grp
 except ImportError:
@@ -44,36 +40,25 @@ class to select the best method to execute a command of a particular job.  This
 import json
 import logging
 import os
-import tempfile
-import subprocess
-import sys
-import threading
 from functools import partial
-from subprocess import check_output, CalledProcessError, STDOUT
 
-from plainbox.abc import IJobResult
-from plainbox.abc import ISessionStateController
+from plainbox.abc import IJobResult, ISessionStateController
 from plainbox.i18n import gettext as _
-from plainbox.impl import get_plainbox_dir
-from plainbox.impl.depmgr import DependencyDuplicateError
 from plainbox.impl.depmgr import DependencyMissingError
-from plainbox.impl.resource import ExpressionCannotEvaluateError
-from plainbox.impl.resource import ExpressionFailedError
-from plainbox.impl.resource import ResourceProgramError
-from plainbox.impl.resource import Resource
+from plainbox.impl.resource import (
+    ExpressionCannotEvaluateError,
+    ExpressionFailedError,
+    ResourceProgramError,
+    Resource,
+)
 from plainbox.impl.secure.origin import JobOutputTextSource
-from plainbox.impl.secure.providers.v1 import Provider1
-from plainbox.impl.secure.rfc822 import RFC822SyntaxError
-from plainbox.impl.secure.rfc822 import gen_rfc822_records
-from plainbox.impl.session.jobs import InhibitionCause
-from plainbox.impl.session.jobs import JobReadinessInhibitor
-from plainbox.impl.unit.job import JobDefinition
+from plainbox.impl.secure.rfc822 import RFC822SyntaxError, gen_rfc822_records
+from plainbox.impl.session.jobs import InhibitionCause, JobReadinessInhibitor
 from plainbox.impl.unit.template import TemplateUnit
 from plainbox.impl.unit.unit import MissingParam
 from plainbox.impl.validation import Severity
 from plainbox.suspend_consts import Suspend
-from plainbox.vendor import morris
-from plainbox.vendor import extcmd
+from plainbox.impl.unit.job import InvalidJob
 
 __all__ = [
     "CheckBoxSessionStateController",
@@ -421,6 +406,55 @@ def _parse_and_store_resource(self, session_state, job, result):
         # Replace any old resources with the new resource list
         session_state.set_resource_list(job.id, new_resource_list)
 
+    @staticmethod
+    def _filter_invalid_log(unit):
+        """
+        Used to filter units that are generated but are invalid, will return
+        True if the unit has to be kept, False if it has to be discarded
+        """
+        try:
+            check_result = unit.check()
+        except MissingParam as m:
+            logger.critical(
+                _("Ignoring %s with missing template parameter %s"),
+                unit._raw_data.get("id"),
+                m.parameter,
+            )
+            return False
+
+        errors = [c for c in check_result if c.severity == Severity.error]
+        warnings = (c for c in check_result if c.severity == Severity.warning)
+        for warning in warnings:
+            logger.warning(str(warning))
+
+        if not errors:
+            return True
+
+        for error in errors:
+            logger.error(str(error))
+        logger.critical("Ignoring invalid generated job %s", unit.id)
+        return False
+
+    @staticmethod
+    def _wrap_invalid_units(unit):
+        """
+        Used to wrap invalid units generated by the template
+        """
+
+        try:
+            check_result = unit.check()
+            errors = [c for c in check_result if c.severity == Severity.error]
+            warnings = (
+                c for c in check_result if c.severity == Severity.warning
+            )
+            for warning in warnings:
+                logger.warning(str(warning))
+        except MissingParam as m:
+            errors = [m]
+        if not errors:
+            return unit
+        return InvalidJob.from_unit(unit, errors=errors)
+
     def _instantiate_templates(
         self, session_state, job, result, fake_resources=False
     ):
@@ -432,35 +466,43 @@ def _instantiate_templates(
         # before it was suspended, so don't
         if result.outcome is IJobResult.OUTCOME_NONE:
             return
-        for unit in session_state.unit_list:
-            if isinstance(unit, TemplateUnit) and unit.resource_id == job.id:
-                logger.info(_("Instantiating unit: %s"), unit)
-                for new_unit in unit.instantiate_all(
-                    session_state.resource_map[job.id], fake_resources
-                ):
-                    try:
-                        check_result = new_unit.check()
-                    except MissingParam as m:
-                        logger.debug(
-                            _(
-                                "Ignoring %s with missing "
-                                "template parameter %s"
-                            ),
-                            new_unit._raw_data.get("id"),
-                            m.parameter,
-                        )
-                        continue
-                    # Only ignore jobs for which check() returns an error
-                    if [
-                        c for c in check_result if c.severity == Severity.error
-                    ]:
-                        logger.error(
-                            _("Ignoring invalid generated job %s"), new_unit.id
-                        )
-                    else:
-                        session_state.add_unit(
-                            new_unit, via=job, recompute=False
-                        )
+        # get all templates that use this (resource) job as template_resource
+        template_units = filter(
+            lambda unit: isinstance(unit, TemplateUnit)
+            and unit.resource_id == job.id,
+            session_state.unit_list,
+        )
+        # get the parsed resource (list of dict created from the resource
+        # stdout)
+        parsed_resource = session_state.resource_map[job.id]
+        # get a list of all new units generated from each template
+        # this is an array of arrays units as follows:
+        # [[unit_from_template1, ...], [unit_from_template2, ...]]
+        new_units_lists = (
+            template_unit.instantiate_all(parsed_resource, fake_resources)
+            for template_unit in template_units
+        )
+        # flattening list to make it easier to work with
+        new_units = (
+            new_unit
+            for new_unit_list in new_units_lists
+            for new_unit in new_unit_list
+        )
+
+        if (
+            session_state.metadata.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION
+            in session_state.metadata.flags
+        ):
+
+            new_units = map(self._wrap_invalid_units, new_units)
+        else:
+            new_units = filter(self._filter_invalid_log, new_units)
+
+        for new_unit in new_units:
+            # here they are added unconditionally as they will be checked
+            # before running to make error reporting possible or were already
+            # filtered by non-strict template expansion
+            session_state.add_unit(new_unit, via=job, recompute=False)
         session_state._recompute_job_readiness()
 
 

checkbox-ng/plainbox/impl/execution.py

@@ -38,16 +38,22 @@
 from plainbox.impl.color import Colorizer
 from plainbox.impl.unit.job import supported_plugins
 from plainbox.impl.unit.unit import on_ubuntucore
-from plainbox.impl.result import IOLogRecordWriter
-from plainbox.impl.result import JobResultBuilder
-from plainbox.impl.runner import CommandOutputWriter
-from plainbox.impl.runner import IOLogRecordGenerator
-from plainbox.impl.runner import JobRunnerUIDelegate
-from plainbox.impl.runner import slugify
+from plainbox.impl.result import (
+    IOLogRecordWriter,
+    JobResultBuilder,
+    IOLogRecord,
+)
+from plainbox.impl.runner import (
+    CommandOutputWriter,
+    IOLogRecordGenerator,
+    JobRunnerUIDelegate,
+    slugify,
+)
 from plainbox.impl.jobcache import ResourceJobCache
 from plainbox.impl.secure.sudo_broker import sudo_password_provider
 from plainbox.impl.session.storage import WellKnownDirsHelper
 from plainbox.vendor import extcmd
+from plainbox.impl.unit.job import InvalidJob
 
 logger = logging.getLogger("plainbox.unified")
 
@@ -91,6 +97,25 @@ def __init__(
 
     def run_job(self, job, job_state, environ=None, ui=None):
         logger.info(_("Running %r"), job)
+        self._job_runner_ui_delegate.ui = ui
+
+        if isinstance(job, InvalidJob):
+            self._job_runner_ui_delegate.on_begin("", dict())
+            for error_line in job.error_lines:
+                self._job_runner_ui_delegate.on_chunk(
+                    "stderr", (error_line + "\n").encode("utf8")
+                )
+            self._job_runner_ui_delegate.on_end(1)
+            return JobResultBuilder(
+                outcome=IJobResult.OUTCOME_FAIL,
+                return_code=1,
+                io_log=[
+                    IOLogRecord(
+                        0, "stderr", "\n".join(job.error_lines).encode("utf8")
+                    )
+                ],
+            ).get_result()
+
         if job.plugin not in supported_plugins:
             print(
                 Colorizer().RED(
@@ -108,7 +133,6 @@ def run_job(self, job, job_state, environ=None, ui=None):
                 outcome=IJobResult.OUTCOME_SKIP,
                 comments=_("Job skipped in dry-run mode"),
             ).get_result()
-        self._job_runner_ui_delegate.ui = ui
 
         # for cached resource jobs we get the result using cache
         # if it's not in the cache, ordinary "_run_command" will be run

checkbox-ng/plainbox/impl/session/assistant.py

@@ -513,6 +513,7 @@ def start_new_session(
         self._metadata.app_id = self._app_id
         self._metadata.title = title
         self._metadata.flags = {SessionMetaData.FLAG_BOOTSTRAPPING}
+        self._metadata.update_feature_flags(self._config)
         self._manager.checkpoint()
         self._command_io_delegate = JobRunnerUIDelegate(_SilentUI())
         self._init_runner(runner_cls, runner_kwargs)
@@ -848,7 +849,7 @@ def bootstrap(self):
         UsageExpectation.of(self).allowed_calls = (
             self._get_allowed_calls_in_normal_state()
         )
-        self._metadata.flags = {SessionMetaData.FLAG_INCOMPLETE}
+        self._metadata.flags.add(SessionMetaData.FLAG_INCOMPLETE)
         self._manager.checkpoint()
 
     @raises(UnexpectedMethodCall)
@@ -980,7 +981,8 @@ def finish_bootstrap(self):
         UsageExpectation.of(self).allowed_calls = (
             self._get_allowed_calls_in_normal_state()
         )
-        self._metadata.flags = {SessionMetaData.FLAG_INCOMPLETE}
+        self._metadata.flags.remove(SessionMetaData.FLAG_BOOTSTRAPPING)
+        self._metadata.flags.add(SessionMetaData.FLAG_INCOMPLETE)
         self._manager.checkpoint()
         # No bootstrap is done update the cache of jobs that were run
         # during bootstrap phase

checkbox-ng/plainbox/impl/session/resume.py

@@ -1239,13 +1239,13 @@ def _build_SessionState(self, session_repr, early_cb=None):
                 )
                 session = new_session
         # Restore bits and pieces of state
+        logger.debug(_("Starting to restore metadata..."))
+        self._restore_SessionState_metadata(session.metadata, session_repr)
+        logger.debug(_("restored metadata %r"), session.metadata)
         logger.debug(
             _("Starting to restore jobs and results to %r..."), session
         )
         self._restore_SessionState_jobs_and_results(session, session_repr)
-        logger.debug(_("Starting to restore metadata..."))
-        self._restore_SessionState_metadata(session.metadata, session_repr)
-        logger.debug(_("restored metadata %r"), session.metadata)
         logger.debug(_("Starting to restore mandatory job list..."))
         self._restore_SessionState_mandatory_job_list(session, session_repr)
         logger.debug(_("Starting to restore desired job list..."))

checkbox-ng/plainbox/impl/session/state.py

@@ -77,6 +77,8 @@ class SessionMetaData:
     # and is not following any test plan
     FLAG_TESTPLANLESS = "testplanless"
 
+    FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION = "strict_template_expansion"
+
     def __init__(
         self,
         title=None,
@@ -124,6 +126,12 @@ def title(self, title):
         """set the session title to the given value."""
         self._title = title
 
+    def update_feature_flags(self, config):
+        if config.get_value("features", "strict_template_expansion"):
+            self._flags.add(self.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION)
+        else:
+            logger.warning("Using legacy non-strict template expansion")
+
     @property
     def flags(self):
         """

checkbox-ng/plainbox/impl/session/test_state.py

@@ -1005,6 +1005,40 @@ def test_app_id_kwarg_to_init(self):
             "com.canonical.certification.plainbox",
         )
 
+    def test_update_feature_flags_strict_template_expansion(self):
+        self_mock = MagicMock()
+        self_mock._flags = set()
+        self_mock.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION = (
+            SessionMetaData.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION
+        )
+
+        config_mock = MagicMock()
+        config_mock.get_value.return_value = True
+        SessionMetaData.update_feature_flags(self_mock, config_mock)
+
+        self.assertIn(
+            SessionMetaData.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION,
+            self_mock._flags,
+        )
+
+    @patch("plainbox.impl.session.state.logger")
+    def test_update_feature_flags_strict_template_expansion_warn(self, logger):
+        self_mock = MagicMock()
+        self_mock._flags = set()
+        self_mock.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION = (
+            SessionMetaData.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION
+        )
+
+        config_mock = MagicMock()
+        config_mock.get_value.return_value = False
+        SessionMetaData.update_feature_flags(self_mock, config_mock)
+
+        self.assertNotIn(
+            SessionMetaData.FLAG_FEATURE_STRICT_TEMPLATE_EXPANSION,
+            self_mock._flags,
+        )
+        self.assertTrue(logger.warning.called)
+
 
 class SessionDeviceContextTests(SignalTestCase):
     def setUp(self):