Modify the PyROS Logging System

pyomo/contrib/pyros/master_problem_methods.py

@@ -296,7 +296,7 @@ def solve_master_feasibility_problem(master_data):
             f" Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)}s"
         )
     else:
-        config.progress_logger.warning(
+        config.progress_logger.debug(
             "Could not successfully solve master feasibility problem "
             f"of iteration {master_data.iteration} with primary subordinate "
             f"{'global' if config.solve_master_globally else 'local'} solver "
@@ -537,18 +537,12 @@ def minimize_dr_vars(master_data):
     # interested in the time and termination status for debugging
     # purposes
     config.progress_logger.debug(" Done solving DR polishing problem")
-    config.progress_logger.debug(
-        f"  Termination condition: {results.solver.termination_condition} "
-    )
-    config.progress_logger.debug(
-        f"  Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)} s"
-    )
 
     # === Process solution by termination condition
     acceptable = {tc.globallyOptimal, tc.optimal, tc.locallyOptimal}
     if results.solver.termination_condition not in acceptable:
         # continue with "unpolished" master model solution
-        config.progress_logger.warning(
+        config.progress_logger.debug(
             "Could not successfully solve DR polishing problem "
             f"of iteration {master_data.iteration} with primary subordinate "
             f"{'global' if config.solve_master_globally else 'local'} solver "
@@ -787,7 +781,7 @@ def solver_call_master(master_data):
 
     for idx, opt in enumerate(solvers):
         if idx > 0:
-            config.progress_logger.warning(
+            config.progress_logger.debug(
                 f"Invoking backup solver {opt!r} "
                 f"(solver {idx + 1} of {len(solvers)}) for "
                 f"master problem of iteration {master_data.iteration}."

pyomo/contrib/pyros/pyros.py

@@ -24,7 +24,8 @@
     load_final_solution,
     pyrosTerminationCondition,
     validate_pyros_inputs,
-    log_model_statistics,
+    log_preprocessed_model_statistics,
+    log_original_model_statistics,
     IterationLogRecord,
     setup_pyros_logger,
     time_code,
@@ -90,6 +91,14 @@ class PyROS:
 
     CONFIG = pyros_config()
     _LOG_LINE_LENGTH = 78
+    _DEFAULT_CONFIG_USER_OPTIONS = [
+        "first_stage_variables",
+        "second_stage_variables",
+        "uncertain_params",
+        "uncertainty_set",
+        "local_solver",
+        "global_solver",
+    ]
 
     def available(self, exception_flag=True):
         """Check if solver is available."""
@@ -199,7 +208,7 @@ def _log_disclaimer(self, logger, **log_kwargs):
         disclaimer_header = " DISCLAIMER ".center(self._LOG_LINE_LENGTH, "=")
 
         logger.log(msg=disclaimer_header, **log_kwargs)
-        logger.log(msg="PyROS is still under development. ", **log_kwargs)
+        logger.log(msg="PyROS is currently under active development. ", **log_kwargs)
         logger.log(
             msg=(
                 "Please provide feedback and/or report any issues by creating "
@@ -210,6 +219,43 @@ def _log_disclaimer(self, logger, **log_kwargs):
         logger.log(msg="https://github.com/Pyomo/pyomo/issues/new/choose", **log_kwargs)
         logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs)
 
+    def _log_config_user_values(
+        self, logger, config, exclude_options=None, **log_kwargs
+    ):
+        """
+        Log explicitly set PyROS solver options.
+
+        If there are no such options, or all such options
+        are to be excluded from consideration, then nothing is logged.
+
+        Parameters
+        ----------
+        logger : logging.Logger
+            Logger for the solver options.
+        config : ConfigDict
+            PyROS solver options.
+        exclude_options : None or iterable of str, optional
+            Options (keys of the ConfigDict) to exclude from
+            logging. If `None` passed, then the names of the
+            required arguments to ``self.solve()`` are skipped.
+        **log_kwargs : dict, optional
+            Keyword arguments to each statement of ``logger.log()``.
+        """
+        if exclude_options is None:
+            exclude_options = set(self._DEFAULT_CONFIG_USER_OPTIONS)
+        else:
+            exclude_options = set(exclude_options)
+
+        user_values = list(
+            filter(lambda val: val.name() not in exclude_options, config.user_values())
+        )
+        if user_values:
+            logger.log(msg="User-provided solver options:", **log_kwargs)
+            for val in user_values:
+                val_name, val_value = val.name(), val.value()
+                logger.log(msg=f" {val_name}={val_value!r}", **log_kwargs)
+            logger.log(msg="-" * self._LOG_LINE_LENGTH, **log_kwargs)
+
     def _log_config(self, logger, config, exclude_options=None, **log_kwargs):
         """
         Log PyROS solver options.
@@ -227,18 +273,12 @@ def _log_config(self, logger, config, exclude_options=None, **log_kwargs):
         **log_kwargs : dict, optional
             Keyword arguments to each statement of ``logger.log()``.
         """
-        # log solver options
         if exclude_options is None:
-            exclude_options = [
-                "first_stage_variables",
-                "second_stage_variables",
-                "uncertain_params",
-                "uncertainty_set",
-                "local_solver",
-                "global_solver",
-            ]
-
-        logger.log(msg="Solver options:", **log_kwargs)
+            exclude_options = set(self._DEFAULT_CONFIG_USER_OPTIONS)
+        else:
+            exclude_options = set(exclude_options)
+
+        logger.log(msg="Full solver options:", **log_kwargs)
         for key, val in config.items():
             if key not in exclude_options:
                 logger.log(msg=f" {key}={val!r}", **log_kwargs)
@@ -273,10 +313,10 @@ def _resolve_and_validate_pyros_args(self, model, **kwds):
            through direct argument 'options'.
         2. Inter-argument validation.
         """
-        config = self.CONFIG(kwds.pop("options", {}))
-        config = config(kwds)
+        # prioritize entries of kwds over entries of kwds['options']
+        kwargs = {**kwds.pop("options", {}), **kwds}
+        config = self.CONFIG(value=kwargs)
         user_var_partitioning = validate_pyros_inputs(model, config)
-
         return config, user_var_partitioning
 
     @document_kwargs_from_configdict(
@@ -331,6 +371,13 @@ def solve(
             Summary of PyROS termination outcome.
 
         """
+        # use this to determine whether user provided
+        # nominal uncertain parameter values
+        nominal_param_vals_in_kwds = (
+            "nominal_uncertain_param_vals" in kwds
+            or "nominal_uncertain_param_vals" in kwds.get("options", {})
+        )
+
         model_data = ModelData(original_model=model, timing=TimingData(), config=None)
         with time_code(
             timing_data_obj=model_data.timing,
@@ -367,14 +414,26 @@ def solve(
             config, user_var_partitioning = self._resolve_and_validate_pyros_args(
                 model, **kwds
             )
+            self._log_config_user_values(
+                logger=config.progress_logger,
+                config=config,
+                exclude_options=(
+                    self._DEFAULT_CONFIG_USER_OPTIONS
+                    + ["nominal_uncertain_param_vals"]
+                    * (not nominal_param_vals_in_kwds)
+                ),
+                level=logging.INFO,
+            )
             self._log_config(
                 logger=config.progress_logger,
                 config=config,
                 exclude_options=None,
-                level=logging.INFO,
+                level=logging.DEBUG,
             )
             model_data.config = config
 
+            log_original_model_statistics(model_data, user_var_partitioning)
+            IterationLogRecord.log_header_rule(config.progress_logger.info)
             config.progress_logger.info("Preprocessing...")
             model_data.timing.start_timer("main.preprocessing")
             robust_infeasible = model_data.preprocess(user_var_partitioning)
@@ -385,7 +444,8 @@ def solve(
                 f"{preprocessing_time:.3f}s."
             )
 
-            log_model_statistics(model_data)
+            IterationLogRecord.log_header_rule(config.progress_logger.debug)
+            log_preprocessed_model_statistics(model_data)
 
             # === Solve and load solution into model
             return_soln = ROSolveResults()
@@ -435,8 +495,8 @@ def solve(
         # log termination-related messages
         config.progress_logger.info(return_soln.pyros_termination_condition.message)
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
-        config.progress_logger.info(f"Timing breakdown:\n\n{model_data.timing}")
-        config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
+        config.progress_logger.debug(f"Timing breakdown:\n\n{model_data.timing}")
+        config.progress_logger.debug("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info(return_soln)
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info("All done. Exiting PyROS.")

pyomo/contrib/pyros/pyros_algorithm_methods.py

@@ -180,6 +180,10 @@ def ROSolver_iterative_solve(model_data):
                 all_sep_problems_solved=None,
                 global_separation=None,
                 elapsed_time=get_main_elapsed_time(model_data.timing),
+                master_backup_solver=master_soln.backup_solver_used,
+                master_feasibility_success=master_soln.feasibility_problem_success,
+                separation_backup_local_solver=None,
+                separation_backup_global_solver=None,
             )
             iter_log_record.log(config.progress_logger.info)
             return GRCSResults(
@@ -226,6 +230,10 @@ def ROSolver_iterative_solve(model_data):
                 all_sep_problems_solved=None,
                 global_separation=None,
                 elapsed_time=model_data.timing.get_main_elapsed_time(),
+                master_backup_solver=master_soln.backup_solver_used,
+                master_feasibility_success=master_soln.feasibility_problem_success,
+                separation_backup_local_solver=None,
+                separation_backup_global_solver=None,
             )
             iter_log_record.log(config.progress_logger.info)
             return GRCSResults(
@@ -269,6 +277,12 @@ def ROSolver_iterative_solve(model_data):
             all_sep_problems_solved=all_sep_problems_solved,
             global_separation=separation_results.solved_globally,
             elapsed_time=get_main_elapsed_time(model_data.timing),
+            master_backup_solver=master_soln.backup_solver_used,
+            master_feasibility_success=master_soln.feasibility_problem_success,
+            separation_backup_local_solver=separation_results.backup_local_solver_used,
+            separation_backup_global_solver=(
+                separation_results.backup_global_solver_used
+            ),
         )
 
         # terminate on time limit

pyomo/contrib/pyros/separation_problem_methods.py

@@ -15,6 +15,7 @@
 """
 
 from itertools import product
+import logging
 
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.common.dependencies import numpy as np
@@ -684,14 +685,27 @@ def perform_separation_loop(separation_data, master_data, solve_globally):
 
             priority_group_solve_call_results[ss_ineq_con] = solve_call_results
 
-            termination_not_ok = solve_call_results.time_out
-            if termination_not_ok:
+            if solve_call_results.time_out:
                 all_solve_call_results.update(priority_group_solve_call_results)
                 return SeparationLoopResults(
                     solver_call_results=all_solve_call_results,
                     solved_globally=solve_globally,
                     worst_case_ss_ineq_con=None,
                 )
+            elif not solve_call_results.subsolver_error:
+                config.progress_logger.debug("Separation successful. Results: ")
+                config.progress_logger.debug(
+                    " Scaled violation: "
+                    f"{solve_call_results.scaled_violations[ss_ineq_con]}"
+                )
+                config.progress_logger.debug(
+                    " Worst-case violating realization: "
+                    f"{solve_call_results.violating_param_realization}"
+                )
+                config.progress_logger.debug(
+                    f" Is constraint violated: {solve_call_results.found_violation} "
+                    f"(compared to tolerance {config.robust_feasibility_tolerance})"
+                )
 
             # provide message that PyROS will attempt to find a violation and move
             # to the next iteration even after subsolver error
@@ -703,6 +717,11 @@ def perform_separation_loop(separation_data, master_data, solve_globally):
 
         all_solve_call_results.update(priority_group_solve_call_results)
 
+        config.progress_logger.debug(
+            f"Done separating all constraints of priority {priority} "
+            f"(group {group_idx + 1} of {len(sorted_priority_groups)})"
+        )
+
         # there may be multiple separation problem solutions
         # found to have violated a second-stage inequality constraint.
         # we choose just one for master problem of next iteration
@@ -903,21 +922,22 @@ def eval_master_violation(scenario_idx):
     # confirm the initial point is feasible for cases where
     # we expect it to be (i.e. non-discrete uncertainty sets).
     # otherwise, log the violated constraints
-    tol = ABS_CON_CHECK_FEAS_TOL
-    ss_ineq_con_name_repr = get_con_name_repr(
-        separation_model=sep_model, con=ss_ineq_con_to_maximize, with_obj_name=True
-    )
-    uncertainty_set_is_discrete = (
-        config.uncertainty_set.geometry is Geometry.DISCRETE_SCENARIOS
-    )
-    for con in sep_model.component_data_objects(Constraint, active=True):
-        lslack, uslack = con.lslack(), con.uslack()
-        if (lslack < -tol or uslack < -tol) and not uncertainty_set_is_discrete:
-            config.progress_logger.debug(
-                f"Initial point for separation of second-stage ineq constraint "
-                f"{ss_ineq_con_name_repr} violates the model constraint "
-                f"{con.name!r} by more than {tol} ({lslack=}, {uslack=})"
-            )
+    if config.progress_logger.isEnabledFor(logging.DEBUG):
+        tol = ABS_CON_CHECK_FEAS_TOL
+        ss_ineq_con_name_repr = get_con_name_repr(
+            separation_model=sep_model, con=ss_ineq_con_to_maximize, with_obj_name=True
+        )
+        uncertainty_set_is_discrete = (
+            config.uncertainty_set.geometry is Geometry.DISCRETE_SCENARIOS
+        )
+        for con in sep_model.component_data_objects(Constraint, active=True):
+            lslack, uslack = con.lslack(), con.uslack()
+            if (lslack < -tol or uslack < -tol) and not uncertainty_set_is_discrete:
+                config.progress_logger.debug(
+                    f"Initial point for separation of second-stage ineq constraint "
+                    f"{ss_ineq_con_name_repr} violates the model constraint "
+                    f"{con.name!r} by more than {tol} ({lslack=}, {uslack=})"
+                )
 
     for con in sep_model.uncertainty.certain_param_var_cons:
         trivially_infeasible = (
@@ -1014,12 +1034,15 @@ def solver_call_separation(
     )
     for idx, opt in enumerate(solvers):
         if idx > 0:
-            config.progress_logger.warning(
+            config.progress_logger.debug(
                 f"Invoking backup solver {opt!r} "
                 f"(solver {idx + 1} of {len(solvers)}) for {solve_mode} "
                 f"separation of second-stage inequality constraint {con_name_repr} "
                 f"in iteration {separation_data.iteration}."
             )
+            # TODO: confirm this is sufficient for tracking
+            #       discrete separation backup solver usage
+            solve_call_results.backup_solver_used = True
         results = call_solver(
             model=separation_model,
             solver=opt,
@@ -1196,7 +1219,7 @@ def discrete_solve(
         # debug statement for solving square problem for each scenario
         config.progress_logger.debug(
             f"Attempting to solve square problem for discrete scenario {scenario}"
-            f", {idx + 1} of {len(scenario_idxs_to_separate)} total"
+            f" ({idx + 1} of {len(scenario_idxs_to_separate)} total)"
         )
 
         # obtain separation problem solution