Added a debug option for observability into depsolving

closes pulp#2343
pulp#2343

CHANGES/2343.feature

@@ -0,0 +1 @@
+Added a debug option for greater visibility into dependency solving.

pulp_rpm/app/depsolving.py

@@ -4,6 +4,8 @@
 
 from pulp_rpm.app import models
 
+from django.conf import settings
+
 
 logger = logging.getLogger(__name__)
 
@@ -578,13 +580,14 @@ def get_units_from_solvables(self, solvables):
 class Solver:
     """A Solver object that can speak in terms of Pulp units."""
 
-    def __init__(self):
+    def __init__(self, debug=False):
         """Solver Init."""
         self._finalized = False
         self._pool = solv.Pool()
         self._pool.setarch()  # prevent https://github.com/openSUSE/libsolv/issues/267
         self._pool.set_flag(solv.Pool.POOL_FLAG_IMPLICITOBSOLETEUSESCOLORS, 1)
         self.mapping = UnitSolvableMapping()
+        self.debug = debug
 
     def finalize(self):
         """Finalize the solver - a finalized solver is ready for depsolving.
@@ -779,28 +782,6 @@ def resolve_dependencies(self, unit_repo_map):
         self._pool.createwhatprovides()
         flags = solv.Job.SOLVER_INSTALL | solv.Job.SOLVER_SOLVABLE
 
-        def run_solver_jobs(jobs):
-            """Execute the libsolv jobs, return results.
-
-            Take a list of jobs, get a solution, return the set of solvables that needed to
-            be installed.
-            """
-            solver = self._pool.Solver()
-            raw_problems = solver.solve(jobs)
-            # The solver is simply ignoring the problems encountered and proceeds associating
-            # any new solvables/units. This might be reported back to the user one day over
-            # the REST API. For now, log only "real" dependency issues (typically some variant
-            # of "can't find the package"
-            dependency_warnings = self._build_warnings(raw_problems)
-            if dependency_warnings:
-                logger.warning(
-                    "Encountered problems solving dependencies, "
-                    "copy may be incomplete: {}".format(", ".join(dependency_warnings))
-                )
-
-            transaction = solver.transaction()
-            return set(transaction.newsolvables())
-
         solvables_to_copy = set(solvables)
         result_solvables = set()
         install_jobs = []
@@ -830,12 +811,45 @@ def run_solver_jobs(jobs):
                 unit_install_job = self._pool.Job(flags, solvable.id)
                 install_jobs.append(unit_install_job)
 
-        # Depsolve using the list of unit install jobs, add them to the results
-        solvables_copied = run_solver_jobs(install_jobs)
-        result_solvables.update(solvables_copied)
+        # Take a list of jobs, get a solution, return the set of solvables that needed to
+        # be installed.
+        solver = self._pool.Solver()
+        solver.set_flag(solv.Solver.SOLVER_FLAG_FOCUS_INSTALLED, 1)
+
+        raw_problems = solver.solve(install_jobs)
+        # The solver is simply ignoring the problems encountered and proceeds associating
+        # any new solvables/units. This might be reported back to the user one day over
+        # the REST API. For now, log only "real" dependency issues (typically some variant
+        # of "can't find the package"
+        dependency_warnings = self._build_warnings(raw_problems)
+        if dependency_warnings:
+            logger.warning(
+                "Encountered problems solving dependencies, "
+                "copy may be incomplete: {}".format(", ".join(dependency_warnings))
+            )
+
+        transaction = solver.transaction()
+        if self.debug or settings.SOLVER_DEBUG_LOGS:
+            write_debug_data(solver)
+        result_solvables.update(set(transaction.newsolvables()))
 
         solved_units = self.mapping.get_units_from_solvables(result_solvables)
         for k in unit_repo_map.keys():
             solved_units[k] |= passthrough[k]
 
         return solved_units
+
+
+# Based on code from libdnf
+# https://github.com/rpm-software-management/libdnf/blob/8655c995582a8e6e2d6eae3453e6ff10e18384a0/libdnf/goal/Goal.cpp#L1137
+def write_debug_data(solver):
+    """Dump the state of the solver including actions decided upon and problems encountered."""
+    from pulpcore.plugin.models import Task
+    from pathlib import Path
+
+    debugdata_dir = (
+        settings.DEPLOY_ROOT / Path("rpm_solver_debug_logs") / str(Task.current().pulp_id)
+    )
+    debugdata_dir.mkdir(parents=True, exist_ok=True)
+    logger.info("Writing solver debug data to {}".format(debugdata_dir))
+    solver.write_testcase(str(debugdata_dir))

pulp_rpm/app/serializers/repository.py

@@ -372,6 +372,11 @@ class CopySerializer(serializers.Serializer):
         help_text=_("Also copy dependencies of the content being copied."), default=True
     )
 
+    debug = serializers.BooleanField(
+        help_text=_("For debugging purposes - dump dependency solving state to disk."),
+        default=False,
+    )
+
     def validate(self, data):
         """
         Validate that the Serializer contains valid data.

pulp_rpm/app/settings.py

@@ -10,3 +10,4 @@
 DEFAULT_ULN_SERVER_BASE_URL = "https://linux-update.oracle.com/"
 RPM_ITERATIVE_PARSING = True
 KEEP_CHANGELOG_LIMIT = 10
+SOLVER_DEBUG_LOGS = False

pulp_rpm/app/tasks/copy.py

@@ -109,11 +109,18 @@ def find_children_of_content(content, src_repo_version):
 
 
 @transaction.atomic
-def copy_content(config, dependency_solving):
+def copy_content(config, dependency_solving, debug=False):
     """
     Copy content from one repo to another.
 
     Args:
+        config: Details of how the copy should be performed.
+        dependency_solving: Use dependency solving to find additional content units to copy.
+
+    Kwargs:
+        debug (bool): Print log files to /var/lib/pulp/rpm_debug_logs/
+
+    Config format details:
         source_repo_version_pk: repository version primary key to copy units from
         dest_repo_pk: repository primary key to copy units into
         criteria: a dict that maps type to a list of criteria to filter content by. Note that this
@@ -172,7 +179,7 @@ def process_entry(entry):
         libsolv_repo_names = {}
         base_versions = {}
 
-        solver = Solver()
+        solver = Solver(debug=debug)
 
         for entry in config:
             (

pulp_rpm/app/viewsets.py

@@ -328,6 +328,7 @@ def create(self, request):
         serializer.is_valid(raise_exception=True)
 
         dependency_solving = serializer.validated_data["dependency_solving"]
+        debug = serializer.validated_data["debug"]
         config = serializer.validated_data["config"]
 
         config, shared_repos, exclusive_repos = self._process_config(config)
@@ -337,7 +338,7 @@ def create(self, request):
             shared_resources=shared_repos,
             exclusive_resources=exclusive_repos,
             args=[config, dependency_solving],
-            kwargs={},
+            kwargs={"debug": debug},
         )
         return OperationPostponedResponse(async_result, request)