From d9e3be53340cb339200ea4cb15b3a61add311a03 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 15:32:19 -0400
Subject: [PATCH 01/74] Make PyROS solver log more detailed

---
 pyomo/contrib/pyros/master_problem_methods.py |   7 +-
 pyomo/contrib/pyros/pyros.py                  | 237 ++++++++++++-
 .../contrib/pyros/pyros_algorithm_methods.py  | 334 ++++++++++++++++--
 pyomo/contrib/pyros/solve_data.py             |  16 +
 pyomo/contrib/pyros/util.py                   | 148 ++++++++
 5 files changed, 704 insertions(+), 38 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index a0e2245cab1..df9d4e1fbcb 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -298,6 +298,9 @@ def minimize_dr_vars(model_data, config):
     -------
     results : SolverResults
         Subordinate solver results for the polishing problem.
+    polishing_successful : bool
+        True if polishing model was solved to acceptable level,
+        False otherwise.
     """
     # config.progress_logger.info("Executing decision rule variable polishing solve.")
     model = model_data.master_model
@@ -493,7 +496,7 @@ def minimize_dr_vars(model_data, config):
     acceptable = {tc.globallyOptimal, tc.optimal, tc.locallyOptimal, tc.feasible}
     if results.solver.termination_condition not in acceptable:
         # continue with "unpolished" master model solution
-        return results
+        return results, False
 
     # update master model second-stage, state, and decision rule
     # variables to polishing model solution
@@ -520,7 +523,7 @@ def minimize_dr_vars(model_data, config):
             for mvar, pvar in zip(master_dr.values(), polish_dr.values()):
                 mvar.set_value(value(pvar), skip_validation=True)
 
-    return results
+    return results, True
 
 
 def add_p_robust_constraint(model_data, config):
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 34db54b64e6..b67cf5c3df6 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -37,17 +37,52 @@
     transform_to_standard_form,
     turn_bounds_to_constraints,
     replace_uncertain_bounds_with_constraints,
-    output_logger,
 )
 from pyomo.contrib.pyros.solve_data import ROSolveResults
 from pyomo.contrib.pyros.pyros_algorithm_methods import ROSolver_iterative_solve
 from pyomo.contrib.pyros.uncertainty_sets import uncertainty_sets
 from pyomo.core.base import Constraint
+from pyomo.common.timing import TicTocTimer
+from pyomo.contrib.pyros.util import IterationLogRecord
+
+from datetime import datetime
+import logging
 
 
 __version__ = "1.2.7"
 
 
+def _get_pyomo_git_info():
+    """
+    Get Pyomo git commit hash.
+    """
+    import os
+    import subprocess
+
+    pyros_dir = os.path.join(*os.path.split(__file__)[:-1])
+
+    git_info_dict = {}
+    commands_dict = {
+        "branch": [
+            "git", "-C", f"{pyros_dir}", "rev-parse", "--abbrev-ref", "HEAD"
+        ],
+        "commit hash": [
+            "git", "-C", f"{pyros_dir}", "rev-parse", "--short", "HEAD"
+        ],
+    }
+    for field, command in commands_dict.items():
+        try:
+            field_val = (
+                subprocess.check_output(command).decode("ascii").strip()
+            )
+        except subprocess.CalledProcessError:
+            field_val = "unknown"
+
+        git_info_dict[field] = field_val
+
+    return git_info_dict
+
+
 def NonNegIntOrMinusOne(obj):
     '''
     if obj is a non-negative int, return the non-negative int
@@ -642,6 +677,7 @@ class PyROS(object):
     '''
 
     CONFIG = pyros_config()
+    _LOG_LINE_LENGTH = 78
 
     def available(self, exception_flag=True):
         """Check if solver is available."""
@@ -663,6 +699,113 @@ def __enter__(self):
     def __exit__(self, et, ev, tb):
         pass
 
+    def _log_intro(self, logger, **log_kwargs):
+        """
+        Log PyROS solver introductory messages.
+
+        Parameters
+        ----------
+        logger : logging.Logger
+            Logger through which to emit messages.
+        **log_kwargs : dict, optional
+            Keyword arguments to ``logger.log()`` callable.
+            Should not include `msg`.
+        """
+        logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs)
+        logger.log(
+            msg="PyROS: The Pyomo Robust Optimization Solver.",
+            **log_kwargs,
+        )
+
+        git_info_str = ", ".join(
+            f"{field}: {val}" for field, val in _get_pyomo_git_info().items()
+        )
+        logger.log(
+            msg=(
+                f"{' ' * len('PyROS:')} Version {self.version()} | "
+                f"Git {git_info_str}"
+            ),
+            **log_kwargs,
+        )
+        logger.log(
+            msg=(
+                f"{' ' * len('PyROS:')} "
+                f"Invoked at UTC {datetime.utcnow().isoformat()}"
+            ),
+            **log_kwargs,
+        )
+        logger.log(msg="", **log_kwargs)
+        logger.log(
+            msg=("Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),"),
+            **log_kwargs,
+        )
+        logger.log(
+            msg=(
+                f"{' ' * len('Developed by:')} "
+                "John D. Siirola (2), Chrysanthos E. Gounaris (1)"
+            ),
+            **log_kwargs,
+        )
+        logger.log(
+            msg=(
+                "(1) Carnegie Mellon University, "
+                "Department of Chemical Engineering"
+            ),
+            **log_kwargs,
+        )
+        logger.log(
+            msg="(2) Sandia National Laboratories, Center for Computing Research",
+            **log_kwargs,
+        )
+        logger.log(msg="", **log_kwargs)
+        logger.log(
+            msg=(
+                "The developers gratefully acknowledge support "
+                "from the U.S. Department"
+            ),
+            **log_kwargs,
+        )
+        logger.log(
+            msg=(
+                "of Energy's "
+                "Institute for the Design of Advanced Energy Systems (IDAES)."
+            ),
+            **log_kwargs,
+        )
+        logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs)
+
+    def _log_disclaimer(self, logger, **log_kwargs):
+        """
+        Log PyROS solver disclaimer messages.
+
+        Parameters
+        ----------
+        logger : logging.Logger
+            Logger through which to emit messages.
+        **log_kwargs : dict, optional
+            Keyword arguments to ``logger.log()`` callable.
+            Should not include `msg`.
+        """
+        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=(
+                "Please provide feedback and/or report any issues by creating "
+                "a ticket at"
+            ),
+            **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 solve(
         self,
         model,
@@ -742,15 +885,42 @@ def solve(
         model_data = ROSolveResults()
         model_data.timing = Bunch()
 
-        # === Set up logger for logging results
-        with time_code(model_data.timing, 'total', is_main_timer=True):
-            config.progress_logger.setLevel(logging.INFO)
-
-            # === PREAMBLE
-            output_logger(config=config, preamble=True, version=str(self.version()))
+        # === Start timer, run the algorithm
+        model_data.timing = Bunch()
+        with time_code(
+                timing_data_obj=model_data.timing,
+                code_block_name='total',
+                is_main_timer=True,
+                ):
+            tt_timer = model_data.timing.tic_toc_timer
+            # output intro and disclaimer
+            self._log_intro(
+                config.progress_logger,
+                level=logging.INFO,
+            )
+            self._log_disclaimer(
+                config.progress_logger,
+                level=logging.INFO,
+            )
 
-            # === DISCLAIMER
-            output_logger(config=config, disclaimer=True)
+            # log solver options
+            excl_from_config_display = [
+                "first_stage_variables",
+                "second_stage_variables",
+                "uncertain_params",
+                "uncertainty_set",
+                "local_solver",
+                "global_solver",
+            ]
+            config.progress_logger.info("Solver options:")
+            for key, val in config.items():
+                if key not in excl_from_config_display:
+                    config.progress_logger.info(f" {key}={val!r}")
+            config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
+
+            # begin preprocessing
+            config.progress_logger.info("Preprocessing...")
+            tt_timer.toc(msg=None)
 
             # === A block to hold list-type data to make cloning easy
             util = Block(concrete=True)
@@ -831,10 +1001,16 @@ def solve(
                 if "bound_con" in c.name:
                     wm_util.ssv_bounds.append(c)
 
+            config.progress_logger.info(
+                f"Done preprocessing; required wall time of "
+                f"{tt_timer.toc(msg=None, delta=True):.2f}s."
+            )
+
             # === Solve and load solution into model
             pyros_soln, final_iter_separation_solns = ROSolver_iterative_solve(
                 model_data, config
             )
+            IterationLogRecord.log_header_rule(config.progress_logger.info)
 
             return_soln = ROSolveResults()
             if pyros_soln is not None and final_iter_separation_solns is not None:
@@ -884,6 +1060,49 @@ def solve(
                 return_soln.final_objective_value = None
                 return_soln.time = get_main_elapsed_time(model_data.timing)
                 return_soln.iterations = 0
+
+        termination_msg_dict = {
+            pyrosTerminationCondition.robust_optimal: (
+                "Robust optimal solution identified."
+            ),
+            pyrosTerminationCondition.robust_feasible: (
+                "Robust feasible solution identified."
+            ),
+            pyrosTerminationCondition.robust_infeasible: (
+                "Problem is robust infeasible."
+            ),
+            pyrosTerminationCondition.time_out: (
+                "Maximum allowable time exceeded."
+            ),
+            pyrosTerminationCondition.max_iter: (
+                "Maximum number of iterations reached."
+            ),
+            pyrosTerminationCondition.subsolver_error: (
+                "Subordinate optimizer(s) could not solve a subproblem "
+                "to an acceptable status."
+            ),
+        }
+        config.progress_logger.info(
+            termination_msg_dict[return_soln.pyros_termination_condition]
+        )
+        config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
+        config.progress_logger.info("Termination stats:")
+        config.progress_logger.info(
+            f" {'Iterations':<22s}: {return_soln.iterations}"
+        )
+        config.progress_logger.info(
+            f" {'Solve time (wall s)':<22s}: {return_soln.time:.4f}"
+        )
+        config.progress_logger.info(
+            f" {'Final objective value':<22s}: "
+            f"{return_soln.final_objective_value}"
+        )
+        config.progress_logger.info(
+            f" {'Termination condition':<22s}: "
+            f"{return_soln.pyros_termination_condition}"
+        )
+        config.progress_logger.info("=" * self._LOG_LINE_LENGTH)
+
         return return_soln
 
 
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 7a0c990d549..6787b49ca6f 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -11,14 +11,16 @@
     ObjectiveType,
     get_time_from_solver,
     pyrosTerminationCondition,
+    IterationLogRecord,
 )
 from pyomo.contrib.pyros.util import (
     get_main_elapsed_time,
-    output_logger,
     coefficient_matching,
 )
 from pyomo.core.base import value
-from pyomo.common.collections import ComponentSet
+from pyomo.common.collections import ComponentSet, ComponentMap
+from pyomo.core.base.var import _VarData as VarData
+from itertools import chain
 
 
 def update_grcs_solve_data(
@@ -47,6 +49,162 @@ def update_grcs_solve_data(
     return
 
 
+def get_dr_var_to_scaled_expr_map(
+        decision_rule_eqns,
+        second_stage_vars,
+        uncertain_params,
+        decision_rule_vars,
+        ):
+    """
+    Generate mapping from decision rule variables
+    to their terms in a model's DR expression.
+    """
+    var_to_scaled_expr_map = ComponentMap()
+    ssv_dr_eq_zip = zip(
+        second_stage_vars,
+        decision_rule_eqns,
+    )
+    for ssv_idx, (ssv, dr_eq) in enumerate(ssv_dr_eq_zip):
+        for term in dr_eq.body.args:
+            is_ssv_term = (
+                isinstance(term.args[0], int)
+                and term.args[0] == -1
+                and isinstance(term.args[1], VarData)
+            )
+            if not is_ssv_term:
+                dr_var = term.args[1]
+                var_to_scaled_expr_map[dr_var] = term
+
+    return var_to_scaled_expr_map
+
+
+def evaluate_and_log_component_stats(model_data, separation_model, config):
+    """
+    Evaluate and log model component statistics.
+    """
+    config.progress_logger.info(
+        "Model statistics:"
+    )
+    # print model statistics
+    dr_var_set = ComponentSet(chain(*tuple(
+        indexed_dr_var.values()
+        for indexed_dr_var in model_data.working_model.util.decision_rule_vars
+    )))
+    first_stage_vars = [
+        var for var in model_data.working_model.util.first_stage_variables
+        if var not in dr_var_set
+    ]
+
+    # account for epigraph constraint
+    sep_model_epigraph_con = getattr(separation_model, "epigraph_constr", None)
+    has_epigraph_con = sep_model_epigraph_con is not None
+
+    num_fsv = len(first_stage_vars)
+    num_ssv = len(model_data.working_model.util.second_stage_variables)
+    num_sv = len(model_data.working_model.util.state_vars)
+    num_dr_vars = len(dr_var_set)
+    num_vars = int(has_epigraph_con) + num_fsv + num_ssv + num_sv + num_dr_vars
+
+    eq_cons = [
+        con for con in
+        model_data.working_model.component_data_objects(
+            Constraint,
+            active=True,
+        )
+        if con.equality
+    ]
+    dr_eq_set = ComponentSet(chain(*tuple(
+        indexed_dr_eq.values()
+        for indexed_dr_eq in model_data.working_model.util.decision_rule_eqns
+    )))
+    num_eq_cons = len(eq_cons)
+    num_dr_cons = len(dr_eq_set)
+    num_coefficient_matching_cons = len(getattr(
+        model_data.working_model,
+        "coefficient_matching_constraints",
+        [],
+    ))
+    num_other_eq_cons = num_eq_cons - num_dr_cons - num_coefficient_matching_cons
+
+    # get performance constraints as referenced in the separation
+    # model object
+    new_sep_con_map = separation_model.util.map_new_constraint_list_to_original_con
+    perf_con_set = ComponentSet(
+        new_sep_con_map.get(con, con)
+        for con in separation_model.util.performance_constraints
+    )
+    is_epigraph_con_first_stage = (
+        has_epigraph_con
+        and sep_model_epigraph_con not in perf_con_set
+    )
+    working_model_perf_con_set = ComponentSet(
+        model_data.working_model.find_component(new_sep_con_map.get(con, con))
+        for con in separation_model.util.performance_constraints
+        if con is not None
+    )
+
+    num_perf_cons = len(separation_model.util.performance_constraints)
+    num_fsv_bounds = sum(
+        int(var.lower is not None) + int(var.upper is not None)
+        for var in first_stage_vars
+    )
+    ineq_con_set = [
+        con for con in
+        model_data.working_model.component_data_objects(
+            Constraint,
+            active=True,
+        )
+        if not con.equality
+    ]
+    num_fsv_ineqs = num_fsv_bounds + len(
+        [con for con in ineq_con_set if con not in working_model_perf_con_set]
+    ) + is_epigraph_con_first_stage
+    num_ineq_cons = (
+        len(ineq_con_set)
+        + has_epigraph_con
+        + num_fsv_bounds
+    )
+
+    config.progress_logger.info(
+        f"{'  Number of variables'} : {num_vars}"
+    )
+    config.progress_logger.info(
+        f"{'    Epigraph variable'} : {int(has_epigraph_con)}"
+    )
+    config.progress_logger.info(f"{'    First-stage variables'} : {num_fsv}")
+    config.progress_logger.info(f"{'    Second-stage variables'} : {num_ssv}")
+    config.progress_logger.info(f"{'    State variables'} : {num_sv}")
+    config.progress_logger.info(f"{'    Decision rule variables'} : {num_dr_vars}")
+    config.progress_logger.info(
+        f"{'  Number of constraints'} : "
+        f"{num_ineq_cons + num_eq_cons}"
+    )
+    config.progress_logger.info(
+        f"{'    Equality constraints'} : {num_eq_cons}"
+    )
+    config.progress_logger.info(
+        f"{'      Coefficient matching constraints'} : "
+        f"{num_coefficient_matching_cons}"
+    )
+    config.progress_logger.info(
+        f"{'      Decision rule equations'} : {num_dr_cons}"
+    )
+    config.progress_logger.info(
+        f"{'      All other equality constraints'} : "
+        f"{num_other_eq_cons}"
+    )
+    config.progress_logger.info(
+        f"{'    Inequality constraints'} : {num_ineq_cons}"
+    )
+    config.progress_logger.info(
+        f"{'      First-stage inequalities (incl. certain var bounds)'} : "
+        f"{num_fsv_ineqs}"
+    )
+    config.progress_logger.info(
+        f"{'      Performance constraints (incl. var bounds)'} : {num_perf_cons}"
+    )
+
+
 def ROSolver_iterative_solve(model_data, config):
     '''
     GRCS algorithm implementation
@@ -75,20 +233,23 @@ def ROSolver_iterative_solve(model_data, config):
             config=config,
         )
         if not coeff_matching_success and not robust_infeasible:
-            raise ValueError(
-                "Equality constraint \"%s\" cannot be guaranteed to be robustly feasible, "
-                "given the current partitioning between first-stage, second-stage and state variables. "
-                "You might consider editing this constraint to reference some second-stage "
-                "and/or state variable(s)." % c.name
+            config.progress_logger.error(
+                f"Equality constraint {c.name!r} cannot be guaranteed to "
+                "be robustly feasible, given the current partitioning "
+                "between first-stage, second-stage, and state variables. "
+                "Consider editing this constraint to reference some "
+                "second-stage and/or state variable(s)."
             )
+            raise ValueError("Coefficient matching unsuccessful. See the solver logs.")
         elif not coeff_matching_success and robust_infeasible:
             config.progress_logger.info(
                 "PyROS has determined that the model is robust infeasible. "
-                "One reason for this is that equality constraint \"%s\" cannot be satisfied "
-                "against all realizations of uncertainty, "
-                "given the current partitioning between first-stage, second-stage and state variables. "
-                "You might consider editing this constraint to reference some (additional) second-stage "
-                "and/or state variable(s)." % c.name
+                f"One reason for this is that the equality constraint {c.name} "
+                "cannot be satisfied against all realizations of uncertainty, "
+                "given the current partitioning between "
+                "first-stage, second-stage, and state variables. "
+                "Consider editing this constraint to reference some (additional) "
+                "second-stage and/or state variable(s)."
             )
             return None, None
         else:
@@ -156,6 +317,12 @@ def ROSolver_iterative_solve(model_data, config):
         model_data=master_data, config=config
     )
 
+    evaluate_and_log_component_stats(
+        model_data=model_data,
+        separation_model=separation_model,
+        config=config,
+    )
+
     # === Create separation problem data container object and add information to catalog during solve
     separation_data = SeparationProblemData()
     separation_data.separation_model = separation_model
@@ -204,6 +371,33 @@ def ROSolver_iterative_solve(model_data, config):
     dr_var_lists_original = []
     dr_var_lists_polished = []
 
+    # set up first-stage variable and DR variable sets
+    master_dr_var_set = ComponentSet(chain(*tuple(
+        indexed_var.values()
+        for indexed_var
+        in master_data.master_model.scenarios[0, 0].util.decision_rule_vars
+    )))
+    master_fsv_set = ComponentSet(
+        var for var in
+        master_data.master_model.scenarios[0, 0].util.first_stage_variables
+        if var not in master_dr_var_set
+    )
+    previous_master_fsv_vals = ComponentMap(
+        (var, None) for var in master_fsv_set
+    )
+    previous_master_dr_var_vals = ComponentMap(
+        (var, None) for var in master_dr_var_set
+    )
+
+    nom_master_util_blk = master_data.master_model.scenarios[0, 0].util
+    dr_var_scaled_expr_map = get_dr_var_to_scaled_expr_map(
+        decision_rule_vars=nom_master_util_blk.decision_rule_vars,
+        decision_rule_eqns=nom_master_util_blk.decision_rule_eqns,
+        second_stage_vars=nom_master_util_blk.second_stage_variables,
+        uncertain_params=nom_master_util_blk.uncertain_params,
+    )
+
+    IterationLogRecord.log_header(config.progress_logger.info)
     k = 0
     master_statuses = []
     while config.max_iter == -1 or k < config.max_iter:
@@ -216,7 +410,7 @@ def ROSolver_iterative_solve(model_data, config):
             )
 
         # === Solve Master Problem
-        config.progress_logger.info("PyROS working on iteration %s..." % k)
+        config.progress_logger.debug(f"PyROS working on iteration {k}...")
         master_soln = master_problem_methods.solve_master(
             model_data=master_data, config=config
         )
@@ -239,7 +433,6 @@ def ROSolver_iterative_solve(model_data, config):
             is pyrosTerminationCondition.robust_infeasible
         ):
             term_cond = pyrosTerminationCondition.robust_infeasible
-            output_logger(config=config, robust_infeasible=True)
         elif (
             master_soln.pyros_termination_condition
             is pyrosTerminationCondition.subsolver_error
@@ -257,6 +450,18 @@ def ROSolver_iterative_solve(model_data, config):
             pyrosTerminationCondition.time_out,
             pyrosTerminationCondition.robust_infeasible,
         }:
+            log_record = IterationLogRecord(
+                iteration=k,
+                objective=None,
+                first_stage_var_shift=None,
+                dr_var_shift=None,
+                num_violated_cons=None,
+                max_violation=None,
+                dr_polishing_failed=None,
+                all_sep_problems_solved=None,
+                elapsed_time=get_main_elapsed_time(model_data.timing),
+            )
+            log_record.log(config.progress_logger.info)
             update_grcs_solve_data(
                 pyros_soln=model_data,
                 k=k,
@@ -280,6 +485,7 @@ def ROSolver_iterative_solve(model_data, config):
             nominal_data.nom_second_stage_cost = master_soln.second_stage_objective
             nominal_data.nom_obj = value(master_data.master_model.obj)
 
+        polishing_successful = True
         if (
             config.decision_rule_order != 0
             and len(config.second_stage_variables) > 0
@@ -294,8 +500,11 @@ def ROSolver_iterative_solve(model_data, config):
                     vals.append(dvar.value)
                 dr_var_lists_original.append(vals)
 
-            polishing_results = master_problem_methods.minimize_dr_vars(
-                model_data=master_data, config=config
+            polishing_results, polishing_successful = (
+                master_problem_methods.minimize_dr_vars(
+                    model_data=master_data,
+                    config=config,
+                )
             )
             timing_data.total_dr_polish_time += get_time_from_solver(polishing_results)
 
@@ -308,11 +517,45 @@ def ROSolver_iterative_solve(model_data, config):
                     vals.append(dvar.value)
                 dr_var_lists_polished.append(vals)
 
-        # === Check if time limit reached
-        elapsed = get_main_elapsed_time(model_data.timing)
+        # get current first-stage and DR variable values
+        # and compare with previous first-stage and DR variable
+        # values
+        current_master_fsv_vals = ComponentMap(
+            (var, value(var))
+            for var in master_fsv_set
+        )
+        current_master_dr_var_vals = ComponentMap(
+            (var, value(var))
+            for var, expr in dr_var_scaled_expr_map.items()
+        )
+        if k > 0:
+            first_stage_var_shift = max(
+                abs(current_master_fsv_vals[var] - previous_master_fsv_vals[var])
+                for var in previous_master_fsv_vals
+            ) if current_master_fsv_vals else None
+            dr_var_shift = max(
+                abs(current_master_dr_var_vals[var] - previous_master_dr_var_vals[var])
+                for var in previous_master_dr_var_vals
+            ) if current_master_dr_var_vals else None
+        else:
+            first_stage_var_shift = None
+            dr_var_shift = None
+
+        # === Check if time limit reached after polishing
         if config.time_limit:
+            elapsed = get_main_elapsed_time(model_data.timing)
             if elapsed >= config.time_limit:
-                output_logger(config=config, time_out=True, elapsed=elapsed)
+                iter_log_record = IterationLogRecord(
+                    iteration=k,
+                    objective=value(master_data.master_model.obj),
+                    first_stage_var_shift=first_stage_var_shift,
+                    dr_var_shift=dr_var_shift,
+                    num_violated_cons=None,
+                    max_violation=None,
+                    dr_polishing_failed=not polishing_successful,
+                    all_sep_problems_solved=None,
+                    elapsed_time=elapsed,
+                )
                 update_grcs_solve_data(
                     pyros_soln=model_data,
                     k=k,
@@ -322,6 +565,7 @@ def ROSolver_iterative_solve(model_data, config):
                     separation_data=separation_data,
                     master_soln=master_soln,
                 )
+                iter_log_record.log(config.progress_logger.info)
                 return model_data, []
 
         # === Set up for the separation problem
@@ -376,10 +620,39 @@ def ROSolver_iterative_solve(model_data, config):
             separation_results.violating_param_realization
         )
 
+        scaled_violations = [
+            solve_call_res.scaled_violations[con]
+            for con, solve_call_res
+            in separation_results.main_loop_results.solver_call_results.items()
+            if solve_call_res.scaled_violations is not None
+        ]
+        if scaled_violations:
+            max_sep_con_violation = max(scaled_violations)
+        else:
+            max_sep_con_violation = None
+        num_violated_cons = len(
+            separation_results.violated_performance_constraints
+        )
+        all_sep_problems_solved = (
+            len(scaled_violations)
+            == len(separation_model.util.performance_constraints)
+        )
+
+        iter_log_record = IterationLogRecord(
+            iteration=k,
+            objective=value(master_data.master_model.obj),
+            first_stage_var_shift=first_stage_var_shift,
+            dr_var_shift=dr_var_shift,
+            num_violated_cons=num_violated_cons,
+            max_violation=max_sep_con_violation,
+            dr_polishing_failed=not polishing_successful,
+            all_sep_problems_solved=all_sep_problems_solved,
+            elapsed_time=get_main_elapsed_time(model_data.timing),
+        )
+
         # terminate on time limit
         elapsed = get_main_elapsed_time(model_data.timing)
         if separation_results.time_out:
-            output_logger(config=config, time_out=True, elapsed=elapsed)
             termination_condition = pyrosTerminationCondition.time_out
             update_grcs_solve_data(
                 pyros_soln=model_data,
@@ -390,6 +663,7 @@ def ROSolver_iterative_solve(model_data, config):
                 separation_data=separation_data,
                 master_soln=master_soln,
             )
+            iter_log_record.log(config.progress_logger.info)
             return model_data, separation_results
 
         # terminate on separation subsolver error
@@ -404,24 +678,26 @@ def ROSolver_iterative_solve(model_data, config):
                 separation_data=separation_data,
                 master_soln=master_soln,
             )
+            iter_log_record.log(config.progress_logger.info)
             return model_data, separation_results
 
         # === Check if we terminate due to robust optimality or feasibility,
         #     or in the event of bypassing global separation, no violations
         robustness_certified = separation_results.robustness_certified
         if robustness_certified:
-            output_logger(
-                config=config, bypass_global_separation=config.bypass_global_separation
-            )
+            if config.bypass_global_separation:
+                config.progress_logger.info(
+                    "NOTE: Option to bypass global separation was chosen. "
+                    "Robust feasibility and optimality of the reported "
+                    "solution are not guaranteed."
+                )
             robust_optimal = (
                 config.solve_master_globally
                 and config.objective_focus is ObjectiveType.worst_case
             )
             if robust_optimal:
-                output_logger(config=config, robust_optimal=True)
                 termination_condition = pyrosTerminationCondition.robust_optimal
             else:
-                output_logger(config=config, robust_feasible=True)
                 termination_condition = pyrosTerminationCondition.robust_feasible
             update_grcs_solve_data(
                 pyros_soln=model_data,
@@ -432,6 +708,7 @@ def ROSolver_iterative_solve(model_data, config):
                 separation_data=separation_data,
                 master_soln=master_soln,
             )
+            iter_log_record.log(config.progress_logger.info)
             return model_data, separation_results
 
         # === Add block to master at violation
@@ -445,11 +722,14 @@ def ROSolver_iterative_solve(model_data, config):
 
         k += 1
 
+        iter_log_record.log(config.progress_logger.info)
+        previous_master_fsv_vals = current_master_fsv_vals
+        previous_master_dr_var_vals = current_master_dr_var_vals
+
     # Iteration limit reached
-    output_logger(config=config, max_iter=True)
     update_grcs_solve_data(
         pyros_soln=model_data,
-        k=k,
+        k=k - 1,  # remove last increment to fix iteration count
         term_cond=pyrosTerminationCondition.max_iter,
         nominal_data=nominal_data,
         timing_data=timing_data,
diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 63e7fdd7ebd..511c042e48e 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -541,6 +541,22 @@ def get_violating_attr(self, attr_name):
 
         return attr_val
 
+    @property
+    def worst_case_perf_con(self):
+        """
+        ...
+        """
+        return self.get_violating_attr("worst_case_perf_con")
+
+    @property
+    def main_loop_results(self):
+        """
+        Get main separation loop results.
+        """
+        if self.global_separation_loop_results is not None:
+            return self.global_separation_loop_results
+        return self.local_separation_loop_results
+
     @property
     def found_violation(self):
         """
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 2c1a309ced3..485744d2ec9 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -41,6 +41,7 @@
 import logging
 from pprint import pprint
 import math
+from pyomo.common.timing import TicTocTimer
 
 
 # Tolerances used in the code
@@ -63,6 +64,10 @@ def time_code(timing_data_obj, code_block_name, is_main_timer=False):
     allowing calculation of total elapsed time 'on the fly' (e.g. to enforce
     a time limit) using `get_main_elapsed_time(timing_data_obj)`.
     """
+    # initialize tic toc timer
+    timing_data_obj.tic_toc_timer = TicTocTimer()
+    timing_data_obj.tic_toc_timer.tic(msg=None)
+
     start_time = timeit.default_timer()
     if is_main_timer:
         timing_data_obj.main_timer_start_time = start_time
@@ -1383,6 +1388,149 @@ def process_termination_condition_master_problem(config, results):
             )
 
 
+class IterationLogRecord:
+    """
+    PyROS solver iteration log record.
+
+    Attributes
+    ----------
+    iteration : int or None
+        Iteration number.
+    objective : int or None
+        Master problem objective value.
+        Note: if the sense of the original model is maximization,
+        then this is the negative of the objective value.
+    first_stage_var_shift : float or None
+        Infinity norm of the difference between first-stage
+        variable vectors for the current and previous iterations.
+    dr_var_shift : float or None
+        Infinity norm of the difference between decision rule
+        variable vectors for the current and previous iterations.
+    num_violated_cons : int or None
+        Number of performance constraints found to be violated
+        during separation step.
+    max_violation : int or None
+        Maximum scaled violation of any performance constraint
+        found during separation step.
+    """
+
+    _LINE_LENGTH = 78
+    _ATTR_FORMAT_LENGTHS = {
+        "iteration": 5,
+        "objective": 13,
+        "first_stage_var_shift": 13,
+        "dr_var_shift": 13,
+        "num_violated_cons": 8,
+        "max_violation": 12,
+        "elapsed_time": 14,
+    }
+    _ATTR_HEADER_NAMES = {
+        "iteration": "Itn",
+        "objective": "Objective",
+        "first_stage_var_shift": "1-Stg Shift",
+        "dr_var_shift": "DR Shift",
+        "num_violated_cons": "#CViol",
+        "max_violation": "Max Viol",
+        "elapsed_time": "Wall Time (s)",
+    }
+
+    def __init__(
+            self,
+            iteration,
+            objective,
+            first_stage_var_shift,
+            dr_var_shift,
+            dr_polishing_failed,
+            num_violated_cons,
+            all_sep_problems_solved,
+            max_violation,
+            elapsed_time,
+            ):
+        """Initialize self (see class docstring)."""
+        self.iteration = iteration
+        self.objective = objective
+        self.first_stage_var_shift = first_stage_var_shift
+        self.dr_var_shift = dr_var_shift
+        self.dr_polishing_failed = dr_polishing_failed
+        self.num_violated_cons = num_violated_cons
+        self.all_sep_problems_solved = all_sep_problems_solved
+        self.max_violation = max_violation
+        self.elapsed_time = elapsed_time
+
+    def get_log_str(self):
+        """Get iteration log string."""
+        attrs = [
+            "iteration",
+            "objective",
+            "first_stage_var_shift",
+            "dr_var_shift",
+            "num_violated_cons",
+            "max_violation",
+            "elapsed_time",
+        ]
+        return "".join(self._format_record_attr(attr) for attr in attrs)
+
+    def _format_record_attr(self, attr_name):
+        """Format attribute record for logging."""
+        attr_val = getattr(self, attr_name)
+        if attr_val is None:
+            fmt_str = f"<{self._ATTR_FORMAT_LENGTHS[attr_name]}s"
+            return f"{'-':{fmt_str}}"
+        else:
+            attr_val_fstrs = {
+                "iteration": "f'{attr_val:d}'",
+                "objective": "f'{attr_val: .4e}'",
+                "first_stage_var_shift": "f'{attr_val:.4e}'",
+                "dr_var_shift": "f'{attr_val:.4e}'",
+                "num_violated_cons": "f'{attr_val:d}'",
+                "max_violation": "f'{attr_val:.4e}'",
+                "elapsed_time": "f'{attr_val:.2f}'",
+            }
+
+            # qualifier for DR polishing and separation columns
+            if attr_name == "dr_var_shift":
+                qual = "*" if self.dr_polishing_failed else ""
+            elif attr_name == "num_violated_cons":
+                qual = "+" if not self.all_sep_problems_solved else ""
+            else:
+                qual = ""
+
+            attr_val_str = f"{eval(attr_val_fstrs[attr_name])}{qual}"
+
+            return (
+                f"{attr_val_str:{f'<{self._ATTR_FORMAT_LENGTHS[attr_name]}'}}"
+            )
+
+    def log(self, log_func, **log_func_kwargs):
+        """Log self."""
+        log_str = self.get_log_str()
+        log_func(log_str, **log_func_kwargs)
+
+    @staticmethod
+    def get_log_header_str():
+        """Get string for iteration log header."""
+        fmt_lengths_dict = IterationLogRecord._ATTR_FORMAT_LENGTHS
+        header_names_dict = IterationLogRecord._ATTR_HEADER_NAMES
+        return "".join(
+            f"{header_names_dict[attr]:<{fmt_lengths_dict[attr]}s}"
+            for attr in fmt_lengths_dict
+        )
+
+    @staticmethod
+    def log_header(log_func, with_rules=True, **log_func_kwargs):
+        """Log header."""
+        if with_rules:
+            IterationLogRecord.log_header_rule(log_func, **log_func_kwargs)
+        log_func(IterationLogRecord.get_log_header_str(), **log_func_kwargs)
+        if with_rules:
+            IterationLogRecord.log_header_rule(log_func, **log_func_kwargs)
+
+    @staticmethod
+    def log_header_rule(log_func, fillchar="-", **log_func_kwargs):
+        """Log header rule."""
+        log_func(fillchar * IterationLogRecord._LINE_LENGTH, **log_func_kwargs)
+
+
 def output_logger(config, **kwargs):
     '''
     All user returned messages (termination conditions, runtime errors) are here

From 8dca4071b619d167c301697a1a9da7faf5beb9e8 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 15:50:08 -0400
Subject: [PATCH 02/74] Reconfigure default PyROS progress logger

---
 pyomo/contrib/pyros/pyros.py |  7 +++----
 pyomo/contrib/pyros/util.py  | 36 ++++++++++++++++++++++++++++++++++--
 2 files changed, 37 insertions(+), 6 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index b67cf5c3df6..c5efbb8dadb 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -37,16 +37,15 @@
     transform_to_standard_form,
     turn_bounds_to_constraints,
     replace_uncertain_bounds_with_constraints,
+    IterationLogRecord,
+    DEFAULT_LOGGER_NAME,
 )
 from pyomo.contrib.pyros.solve_data import ROSolveResults
 from pyomo.contrib.pyros.pyros_algorithm_methods import ROSolver_iterative_solve
 from pyomo.contrib.pyros.uncertainty_sets import uncertainty_sets
 from pyomo.core.base import Constraint
-from pyomo.common.timing import TicTocTimer
-from pyomo.contrib.pyros.util import IterationLogRecord
 
 from datetime import datetime
-import logging
 
 
 __version__ = "1.2.7"
@@ -520,7 +519,7 @@ def pyros_config():
     CONFIG.declare(
         "progress_logger",
         PyROSConfigValue(
-            default="pyomo.contrib.pyros",
+            default=DEFAULT_LOGGER_NAME,
             domain=a_logger,
             doc=(
                 """
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 485744d2ec9..9a7eb4e2f76 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -51,6 +51,7 @@
 COEFF_MATCH_ABS_TOL = 0
 ABS_CON_CHECK_FEAS_TOL = 1e-5
 TIC_TOC_SOLVE_TIME_ATTR = "pyros_tic_toc_time"
+DEFAULT_LOGGER_NAME = "pyomo.contrib.pyros"
 
 
 '''Code borrowed from gdpopt: time_code, get_main_elapsed_time, a_logger.'''
@@ -229,11 +230,42 @@ def revert_solver_max_time_adjustment(
 
 
 def a_logger(str_or_logger):
-    """Returns a logger when passed either a logger name or logger object."""
+    """
+    Standardize a string or logger object to a logger object.
+
+    Parameters
+    ----------
+    str_or_logger : str or logging.Logger
+        String or logger object to normalize.
+
+    Returns
+    -------
+    logging.Logger
+        If `str_or_logger` is of type `logging.Logger`,then
+        `str_or_logger` is returned.
+        Otherwise, a logger with name `str_or_logger`, INFO level,
+        ``propagate=False``, and handlers reduced to just a single
+        stream handler, is returned.
+    """
     if isinstance(str_or_logger, logging.Logger):
         return str_or_logger
     else:
-        return logging.getLogger(str_or_logger)
+        logger = logging.getLogger(str_or_logger)
+
+        if str_or_logger == DEFAULT_LOGGER_NAME:
+            # turn off propagate to remove possible influence
+            # of overarching Pyomo logger settings
+            logger.propagate = False
+
+        # clear handlers, want just a single stream handler
+        logger.handlers.clear()
+        ch = logging.StreamHandler()
+        logger.addHandler(ch)
+
+        # info level logger
+        logger.setLevel(logging.INFO)
+
+        return logger
 
 
 def ValidEnum(enum_class):

From 4b6cd10137975c320b621399bf1372aef75f5607 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 16:17:47 -0400
Subject: [PATCH 03/74] Add detailed subsolver failure warning messages

---
 pyomo/contrib/pyros/master_problem_methods.py | 42 ++++++++++++++----
 .../pyros/separation_problem_methods.py       | 44 +++++++++++++++----
 2 files changed, 68 insertions(+), 18 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index df9d4e1fbcb..bfc8bafa8fb 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -657,7 +657,7 @@ def solver_call_master(model_data, config, solver, solve_data):
             # errors, etc.)
             config.progress_logger.error(
                 f"Solver {repr(opt)} encountered exception attempting to "
-                f"optimize master problem in iteration {model_data.iteration}"
+                f"optimize master problem in iteration {model_data.iteration}."
             )
             raise
         else:
@@ -718,6 +718,20 @@ def solver_call_master(model_data, config, solver, solve_data):
                 nlp_model.scenarios[0, 0].first_stage_objective
             )
 
+            # debugging: log breakdown of master objective
+            config.progress_logger.debug("Master objective")
+            config.progress_logger.debug(
+                f" First-stage objective {master_soln.first_stage_objective}"
+            )
+            config.progress_logger.debug(
+                f" Second-stage objective {master_soln.second_stage_objective}"
+            )
+            master_obj = (
+                master_soln.first_stage_objective
+                + master_soln.second_stage_objective
+            )
+            config.progress_logger.debug(f" Objective {master_obj}")
+
             master_soln.nominal_block = nlp_model.scenarios[0, 0]
             master_soln.results = results
             master_soln.master_model = nlp_model
@@ -745,8 +759,9 @@ def solver_call_master(model_data, config, solver, solve_data):
     # NOTE: subproblem is written with variables set to their
     #       initial values (not the final subsolver iterate)
     save_dir = config.subproblem_file_directory
+    serialization_msg = ""
     if save_dir and config.keepfiles:
-        name = os.path.join(
+        output_problem_path = os.path.join(
             save_dir,
             (
                 config.uncertainty_set.type
@@ -757,15 +772,24 @@ def solver_call_master(model_data, config, solver, solve_data):
                 + ".bar"
             ),
         )
-        nlp_model.write(name, io_options={'symbolic_solver_labels': True})
-        output_logger(
-            config=config,
-            master_error=True,
-            status_dict=solver_term_cond_dict,
-            filename=name,
-            iteration=model_data.iteration,
+        nlp_model.write(
+            output_problem_path,
+            io_options={'symbolic_solver_labels': True},
         )
+        serialization_msg = (
+            f" Problem has been serialized to path {output_problem_path!r}."
+        )
+
     master_soln.pyros_termination_condition = pyrosTerminationCondition.subsolver_error
+    solve_mode = "global" if config.solve_master_globally else "local"
+    config.progress_logger.warning(
+        f"Could not successfully solve master problem of iteration "
+        f"{model_data.iteration} with any of the "
+        f"provided subordinate {solve_mode} optimizers. "
+        f"(Termination statuses: "
+        f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.)"
+        f"{ serialization_msg}"
+    )
     return master_soln
 
 
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 2c41c869474..872c2f0edb5 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -929,6 +929,26 @@ def solver_call_separation(
     solver_status_dict = {}
     nlp_model = model_data.separation_model
 
+    # get name of constraint for loggers
+    orig_con = (
+        nlp_model.util.map_new_constraint_list_to_original_con.get(
+            perf_con_to_maximize,
+            perf_con_to_maximize,
+        )
+    )
+    if orig_con is perf_con_to_maximize:
+        con_name_repr = (
+            f"{perf_con_to_maximize.name!r} "
+            f"(mapped to objective {separation_obj.name!r})"
+        )
+    else:
+        con_name_repr = (
+            f"{perf_con_to_maximize.name!r} "
+            f"(originally named {orig_con.name!r}, "
+            f"mapped to objective {separation_obj.name!r})"
+        )
+    solve_mode = "global" if solve_globally else "local"
+
     # === Initialize separation problem; fix first-stage variables
     initialize_separation(model_data, config)
 
@@ -1020,9 +1040,10 @@ def solver_call_separation(
     # error. At this point, export model if desired
     solve_call_results.subsolver_error = True
     save_dir = config.subproblem_file_directory
+    serialization_msg = ""
     if save_dir and config.keepfiles:
         objective = separation_obj.name
-        name = os.path.join(
+        output_problem_path = os.path.join(
             save_dir,
             (
                 config.uncertainty_set.type
@@ -1035,15 +1056,20 @@ def solver_call_separation(
                 + ".bar"
             ),
         )
-        nlp_model.write(name, io_options={'symbolic_solver_labels': True})
-        output_logger(
-            config=config,
-            separation_error=True,
-            filename=name,
-            iteration=model_data.iteration,
-            objective=objective,
-            status_dict=solver_status_dict,
+        nlp_model.write(output_problem_path, io_options={'symbolic_solver_labels': True})
+        serialization_msg = (
+            f"Problem has been serialized to path {output_problem_path!r}."
         )
+    solve_call_results.message = (
+        "Could not successfully solve separation problem of iteration "
+        f"{model_data.iteration} "
+        f"for performance constraint {con_name_repr} with any of the "
+        f"provided subordinate {solve_mode} optimizers. "
+        f"(Termination statuses: "
+        f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.)"
+        f"{ serialization_msg}"
+    )
+    config.progress_logger.warning(solve_call_results.message)
 
     separation_obj.deactivate()
 

From 46dfa5d3f8a6267f9da1488fc65733bf83823625 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 16:29:42 -0400
Subject: [PATCH 04/74] Standardize subsolver exception log messages

---
 pyomo/contrib/pyros/master_problem_methods.py     | 8 ++++----
 pyomo/contrib/pyros/separation_problem_methods.py | 7 ++++---
 2 files changed, 8 insertions(+), 7 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index bfc8bafa8fb..81ae38dc955 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -253,8 +253,8 @@ def solve_master_feasibility_problem(model_data, config):
         # (such as segmentation faults, function evaluation
         # errors, etc.)
         config.progress_logger.error(
-            f"Solver {repr(solver)} encountered exception attempting to "
-            "optimize master feasibility problem in iteration "
+            f"Optimizer {repr(solver)} encountered exception "
+            "attempting to solve master feasibility problem in iteration "
             f"{model_data.iteration}"
         )
         raise
@@ -656,8 +656,8 @@ def solver_call_master(model_data, config, solver, solve_data):
             # (such as segmentation faults, function evaluation
             # errors, etc.)
             config.progress_logger.error(
-                f"Solver {repr(opt)} encountered exception attempting to "
-                f"optimize master problem in iteration {model_data.iteration}."
+                f"Optimizer {repr(opt)} encountered exception attempting to "
+                f"solve master problem in iteration {model_data.iteration}."
             )
             raise
         else:
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 872c2f0edb5..f4a3d6df7af 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -978,10 +978,11 @@ def solver_call_separation(
             # account for possible external subsolver errors
             # (such as segmentation faults, function evaluation
             # errors, etc.)
+            adverb = "globally" if solve_globally else "locally"
             config.progress_logger.error(
-                f"Solver {repr(opt)} encountered exception attempting to "
-                "optimize separation problem in iteration "
-                f"{model_data.iteration}"
+                f"Optimizer {repr(opt)} encountered exception attempting "
+                f"to {adverb} solve separation problem for constraint "
+                f"{con_name_repr} in iteration {model_data.iteration}."
             )
             raise
         else:

From 7bcdb98b43afd7cc6b9cbe95c4b84cdf985bb67b Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 17:26:09 -0400
Subject: [PATCH 05/74] Add backup solver warning level messages

---
 pyomo/contrib/pyros/master_problem_methods.py     | 13 +++++++++----
 pyomo/contrib/pyros/separation_problem_methods.py |  9 ++++++++-
 2 files changed, 17 insertions(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 81ae38dc955..c50fba746d7 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -631,15 +631,20 @@ def solver_call_master(model_data, config, solver, solve_data):
     solver_term_cond_dict = {}
 
     if config.solve_master_globally:
-        backup_solvers = deepcopy(config.backup_global_solvers)
+        solvers = [solver] + config.backup_global_solvers
     else:
-        backup_solvers = deepcopy(config.backup_local_solvers)
-    backup_solvers.insert(0, solver)
+        solvers = [solver] + config.backup_local_solvers
 
     higher_order_decision_rule_efficiency(config, model_data)
 
     timer = TicTocTimer()
-    for opt in backup_solvers:
+    for idx, opt in enumerate(solvers):
+        if idx > 0:
+            config.progress_logger.warning(
+                f"Invoking backup solver {opt!r} "
+                f"(solver {idx + 1} of {len(solvers)}) for "
+                f"master problem of iteration {model_data.iteration}."
+            )
         orig_setting, custom_setting_present = adjust_solver_time_settings(
             model_data.timing, opt, config
         )
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index f4a3d6df7af..3536001baf4 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -962,7 +962,14 @@ def solver_call_separation(
         subsolver_error=False,
     )
     timer = TicTocTimer()
-    for opt in solvers:
+    for idx, opt in enumerate(solvers):
+        if idx > 0:
+            config.progress_logger.warning(
+                f"Invoking backup solver {opt!r} "
+                f"(solver {idx + 1} of {len(solvers)}) for {solve_mode} "
+                f"separation of performance constraint {con_name_repr} "
+                f"in iteration {model_data.iteration}."
+            )
         orig_setting, custom_setting_present = adjust_solver_time_settings(
             model_data.timing, opt, config
         )

From 2119c21090f2be280467286ee3fdee58ec386849 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 17:34:22 -0400
Subject: [PATCH 06/74] Tweak subsolver exception log messages

---
 pyomo/contrib/pyros/master_problem_methods.py     | 3 ++-
 pyomo/contrib/pyros/separation_problem_methods.py | 3 ++-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index c50fba746d7..1e3a95835e1 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -661,7 +661,8 @@ def solver_call_master(model_data, config, solver, solve_data):
             # (such as segmentation faults, function evaluation
             # errors, etc.)
             config.progress_logger.error(
-                f"Optimizer {repr(opt)} encountered exception attempting to "
+                f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) "
+                "encountered exception attempting to "
                 f"solve master problem in iteration {model_data.iteration}."
             )
             raise
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 3536001baf4..b58871e2b10 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -987,7 +987,8 @@ def solver_call_separation(
             # errors, etc.)
             adverb = "globally" if solve_globally else "locally"
             config.progress_logger.error(
-                f"Optimizer {repr(opt)} encountered exception attempting "
+                f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) "
+                f"encountered exception attempting "
                 f"to {adverb} solve separation problem for constraint "
                 f"{con_name_repr} in iteration {model_data.iteration}."
             )

From 7fff720eb10490d7f218d3bb80464530304fdedb Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 18:33:47 -0400
Subject: [PATCH 07/74] Add more debug level log messages

---
 pyomo/contrib/pyros/master_problem_methods.py |  52 +++++++
 .../contrib/pyros/pyros_algorithm_methods.py  |   6 +
 .../pyros/separation_problem_methods.py       | 127 ++++++++++++++----
 3 files changed, 157 insertions(+), 28 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 1e3a95835e1..f925313806e 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -470,6 +470,15 @@ def minimize_dr_vars(model_data, config):
     else:
         solver = config.local_solver
 
+    config.progress_logger.debug("Solving DR polishing problem")
+
+    # NOTE: this objective evalaution may not be accurate, due
+    #       to the current initialization scheme for the auxiliary
+    #       variables. new initialization will be implemented in the
+    #       near future.
+    polishing_obj = polishing_model.scenarios[0, 0].polishing_obj
+    config.progress_logger.debug(f" Initial DR norm: {value(polishing_obj)}")
+
     # === Solve the polishing model
     timer = TicTocTimer()
     orig_setting, custom_setting_present = adjust_solver_time_settings(
@@ -492,6 +501,16 @@ def minimize_dr_vars(model_data, config):
             solver, orig_setting, custom_setting_present, config
         )
 
+    # interested in the time and termination status for debugging
+    # purposes
+    config.progress_logger.debug(" Done solving DR polishing problem")
+    config.progress_logger.debug(
+        f"  Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)} s"
+    )
+    config.progress_logger.debug(
+        f"  Termination status: {results.solver.termination_condition} "
+    )
+
     # === Process solution by termination condition
     acceptable = {tc.globallyOptimal, tc.optimal, tc.locallyOptimal, tc.feasible}
     if results.solver.termination_condition not in acceptable:
@@ -523,6 +542,37 @@ def minimize_dr_vars(model_data, config):
             for mvar, pvar in zip(master_dr.values(), polish_dr.values()):
                 mvar.set_value(value(pvar), skip_validation=True)
 
+    config.progress_logger.debug(f" Optimized DDR norm: {value(polishing_obj)}")
+    config.progress_logger.debug("Polished Master objective:")
+
+    # print master solution
+    if config.objective_focus == ObjectiveType.worst_case:
+        worst_blk_idx = max(
+            model_data.master_model.scenarios.keys(),
+            key=lambda idx: value(
+                model_data.master_model.scenarios[idx]
+                .second_stage_objective
+            )
+        )
+    else:
+        worst_blk_idx = (0, 0)
+
+    # debugging: summarize objective breakdown
+    worst_master_blk = model_data.master_model.scenarios[worst_blk_idx]
+    config.progress_logger.debug(
+        " First-stage objective "
+        f"{value(worst_master_blk.first_stage_objective)}"
+    )
+    config.progress_logger.debug(
+        " Second-stage objective "
+        f"{value(worst_master_blk.second_stage_objective)}"
+    )
+    polished_master_obj = value(
+        worst_master_blk.first_stage_objective
+        + worst_master_blk.second_stage_objective
+    )
+    config.progress_logger.debug(f" Objective {polished_master_obj}")
+
     return results, True
 
 
@@ -637,6 +687,8 @@ def solver_call_master(model_data, config, solver, solve_data):
 
     higher_order_decision_rule_efficiency(config, model_data)
 
+    config.progress_logger.debug("Solving master problem")
+
     timer = TicTocTimer()
     for idx, opt in enumerate(solvers):
         if idx > 0:
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 6787b49ca6f..d9a05425135 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -21,6 +21,7 @@
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.core.base.var import _VarData as VarData
 from itertools import chain
+import numpy as np
 
 
 def update_grcs_solve_data(
@@ -720,6 +721,11 @@ def ROSolver_iterative_solve(model_data, config):
             separation_results.violating_param_realization
         )
 
+        config.progress_logger.debug("Points added to master:")
+        config.progress_logger.debug(
+            np.array([pt for pt in separation_data.points_added_to_master]),
+        )
+
         k += 1
 
         iter_log_record.log(config.progress_logger.info)
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index b58871e2b10..61bc514f933 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -536,6 +536,61 @@ def get_worst_discrete_separation_solution(
     )
 
 
+def get_con_name_repr(
+        separation_model,
+        perf_con,
+        with_orig_name=True,
+        with_obj_name=True,
+        ):
+    """
+    Get string representation of performance constraint
+    and any other modeling components to which it has
+    been mapped.
+
+    Parameters
+    ----------
+    separation_model : ConcreteModel
+        Separation model.
+    perf_con : ScalarConstraint or ConstraintData
+        Performance constraint for which to get the
+        representation
+    with_orig_name : bool, optional
+        If constraint was added during construction of the
+        separation problem (i.e. if the constraint is a member of
+        in `separation_model.util.new_constraints`),
+        include the name of the original constraint from which
+        `perf_con` was created.
+    with_obj_name : bool, optional
+        Include name of separation model objective to which
+        performance constraint is mapped.
+
+    Returns
+    -------
+    str
+        Constraint name representation.
+    """
+
+    qual_strs = []
+    if with_orig_name:
+        # check performance constraint was not added
+        # at construction of separation problem
+        orig_con = (
+            separation_model
+            .util
+            .map_new_constraint_list_to_original_con.get(perf_con, perf_con)
+        )
+        if orig_con is not perf_con:
+            qual_strs.append(f"originally {orig_con.name!r}")
+    if with_obj_name:
+        objectives_map = separation_model.util.map_obj_to_constr
+        separation_obj = objectives_map[perf_con]
+        qual_strs.append(f"mapped to objective {separation_obj.name!r}")
+
+    final_qual_str = f"({', '.join(qual_strs)})" if qual_strs else ""
+
+    return f"{perf_con.name!r} {final_qual_str}"
+
+
 def perform_separation_loop(model_data, config, solve_globally):
     """
     Loop through, and solve, PyROS separation problems to
@@ -635,7 +690,15 @@ def perform_separation_loop(model_data, config, solve_globally):
     all_solve_call_results = ComponentMap()
     for priority, perf_constraints in sorted_priority_groups.items():
         priority_group_solve_call_results = ComponentMap()
-        for perf_con in perf_constraints:
+        for idx, perf_con in enumerate(perf_constraints):
+            solve_adverb = "Globally" if solve_globally else "Locally"
+            config.progress_logger.debug(
+                f"{solve_adverb} separating constraint "
+                f"{get_con_name_repr(model_data.separation_model, perf_con)} "
+                f"(group priority {priority}, "
+                f"constraint {idx + 1} of {len(perf_constraints)})"
+            )
+
             # config.progress_logger.info(
             #     f"Separating constraint {perf_con.name}"
             # )
@@ -689,17 +752,27 @@ def perform_separation_loop(model_data, config, solve_globally):
                 )
 
             # # auxiliary log messages
-            # objectives_map = (
-            #     model_data.separation_model.util.map_obj_to_constr
-            # )
-            # violated_con_name = list(objectives_map.keys())[
-            #     worst_case_perf_con
-            # ]
-            # config.progress_logger.info(
-            #     f"Violation found for constraint {violated_con_name} "
-            #     "under realization "
-            #     f"{worst_case_res.violating_param_realization}"
-            # )
+            violated_con_names = "\n ".join(
+                get_con_name_repr(model_data.separation_model, con)
+                for con, res in all_solve_call_results.items()
+                if res.found_violation
+            )
+            config.progress_logger.debug(
+                f"Violated constraints:\n {violated_con_names} "
+            )
+            config.progress_logger.debug(
+                "Worst-case constraint: "
+                f"{get_con_name_repr(model_data.separation_model, worst_case_perf_con)} "
+                "under realization "
+                f"{worst_case_res.violating_param_realization}."
+            )
+            config.progress_logger.debug(
+                f"Maximal scaled violation "
+                f"{worst_case_res.scaled_violations[worst_case_perf_con]} "
+                "from this constraint "
+                "exceeds the robust feasibility tolerance "
+                f"{config.robust_feasibility_tolerance}"
+            )
 
             # violating separation problem solution now chosen.
             # exit loop
@@ -930,23 +1003,12 @@ def solver_call_separation(
     nlp_model = model_data.separation_model
 
     # get name of constraint for loggers
-    orig_con = (
-        nlp_model.util.map_new_constraint_list_to_original_con.get(
-            perf_con_to_maximize,
-            perf_con_to_maximize,
-        )
+    con_name_repr = get_con_name_repr(
+        separation_model=nlp_model,
+        perf_con=perf_con_to_maximize,
+        with_orig_name=True,
+        with_obj_name=True,
     )
-    if orig_con is perf_con_to_maximize:
-        con_name_repr = (
-            f"{perf_con_to_maximize.name!r} "
-            f"(mapped to objective {separation_obj.name!r})"
-        )
-    else:
-        con_name_repr = (
-            f"{perf_con_to_maximize.name!r} "
-            f"(originally named {orig_con.name!r}, "
-            f"mapped to objective {separation_obj.name!r})"
-        )
     solve_mode = "global" if solve_globally else "local"
 
     # === Initialize separation problem; fix first-stage variables
@@ -1043,6 +1105,15 @@ def solver_call_separation(
             separation_obj.deactivate()
 
             return solve_call_results
+        else:
+            config.progress_logger.debug(
+                f"Solver {opt} ({idx + 1} of {len(solvers)}) "
+                f"failed for {solve_mode} separation of performance "
+                f"constraint {con_name_repr} in iteration "
+                f"{model_data.iteration}. Termination condition: "
+                f"{results.solver.termination_condition!r}."
+            )
+            config.progress_logger.debug(f"Results:\n{results.solver}")
 
     # All subordinate solvers failed to optimize model to appropriate
     # termination condition. PyROS will terminate with subsolver

From 696a3b78a1787e1930e1c013238641c7a555394e Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 18:47:39 -0400
Subject: [PATCH 08/74] Fix all testing issues

---
 pyomo/contrib/pyros/tests/test_grcs.py | 14 ++++++++++----
 1 file changed, 10 insertions(+), 4 deletions(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 0d24b799b99..0c9351835ec 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -59,6 +59,7 @@
     sqrt,
     value,
 )
+import logging
 
 
 if not (numpy_available and scipy_available):
@@ -3589,6 +3590,7 @@ def test_solve_master(self):
         )
         config.declare("subproblem_file_directory", ConfigValue(default=None))
         config.declare("time_limit", ConfigValue(default=None))
+        config.declare("progress_logger", ConfigValue(default=logging.getLogger(__name__)))
 
         with time_code(master_data.timing, "total", is_main_timer=True):
             master_soln = solve_master(master_data, config)
@@ -3866,7 +3868,7 @@ def test_minimize_dr_norm(self):
         m.working_model.util.state_vars = []
 
         m.working_model.util.first_stage_variables = []
-        config = Block()
+        config = Bunch()
         config.decision_rule_order = 1
         config.objective_focus = ObjectiveType.nominal
         config.global_solver = SolverFactory('baron')
@@ -3874,6 +3876,7 @@ def test_minimize_dr_norm(self):
         config.tee = False
         config.solve_master_globally = True
         config.time_limit = None
+        config.progress_logger = logging.getLogger(__name__)
 
         add_decision_rule_variables(model_data=m, config=config)
         add_decision_rule_constraints(model_data=m, config=config)
@@ -3895,12 +3898,16 @@ def test_minimize_dr_norm(self):
 
         master_data.timing = Bunch()
         with time_code(master_data.timing, "total", is_main_timer=True):
-            results = minimize_dr_vars(model_data=master_data, config=config)
+            results, success = minimize_dr_vars(model_data=master_data, config=config)
             self.assertEqual(
                 results.solver.termination_condition,
                 TerminationCondition.optimal,
                 msg="Minimize dr norm did not solve to optimality.",
             )
+            self.assertTrue(
+                success,
+                msg=f"DR polishing {success=}, expected True."
+            )
 
     @unittest.skipUnless(
         baron_license_is_valid, "Global NLP solver is not available and licensed."
@@ -4867,8 +4874,7 @@ def test_coefficient_matching_raises_error_4_3(self):
             with self.assertRaisesRegex(
                 ValueError,
                 expected_regex=(
-                    "Equality constraint.*cannot be guaranteed to be robustly "
-                    "feasible.*"
+                    "Coefficient matching unsuccessful. See the solver logs."
                 ),
             ):
                 res = pyros_solver.solve(

From 673b5498112d5e86dd6d8919072b93d5ca6187b0 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 19:14:27 -0400
Subject: [PATCH 09/74] Add spacing for serialization messages

---
 pyomo/contrib/pyros/master_problem_methods.py     | 4 ++--
 pyomo/contrib/pyros/separation_problem_methods.py | 4 ++--
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index f925313806e..1fc65a552a8 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -845,8 +845,8 @@ def solver_call_master(model_data, config, solver, solve_data):
         f"{model_data.iteration} with any of the "
         f"provided subordinate {solve_mode} optimizers. "
         f"(Termination statuses: "
-        f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.)"
-        f"{ serialization_msg}"
+        f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.) "
+        f"{serialization_msg}"
     )
     return master_soln
 
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 61bc514f933..6efa0f66071 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -1146,8 +1146,8 @@ def solver_call_separation(
         f"for performance constraint {con_name_repr} with any of the "
         f"provided subordinate {solve_mode} optimizers. "
         f"(Termination statuses: "
-        f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.)"
-        f"{ serialization_msg}"
+        f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.) "
+        f"{serialization_msg}"
     )
     config.progress_logger.warning(solve_call_results.message)
 

From 46f31dd2df15e73041bffb0a152a5fc17f793202 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 19:39:05 -0400
Subject: [PATCH 10/74] Apply black formatting

---
 pyomo/contrib/pyros/master_problem_methods.py |  20 +-
 pyomo/contrib/pyros/pyros.py                  |  59 ++----
 .../contrib/pyros/pyros_algorithm_methods.py  | 199 ++++++++----------
 .../pyros/separation_problem_methods.py       |  17 +-
 pyomo/contrib/pyros/util.py                   |  26 ++-
 5 files changed, 133 insertions(+), 188 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 1fc65a552a8..b71bbb9285a 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -550,9 +550,8 @@ def minimize_dr_vars(model_data, config):
         worst_blk_idx = max(
             model_data.master_model.scenarios.keys(),
             key=lambda idx: value(
-                model_data.master_model.scenarios[idx]
-                .second_stage_objective
-            )
+                model_data.master_model.scenarios[idx].second_stage_objective
+            ),
         )
     else:
         worst_blk_idx = (0, 0)
@@ -560,16 +559,13 @@ def minimize_dr_vars(model_data, config):
     # debugging: summarize objective breakdown
     worst_master_blk = model_data.master_model.scenarios[worst_blk_idx]
     config.progress_logger.debug(
-        " First-stage objective "
-        f"{value(worst_master_blk.first_stage_objective)}"
+        " First-stage objective " f"{value(worst_master_blk.first_stage_objective)}"
     )
     config.progress_logger.debug(
-        " Second-stage objective "
-        f"{value(worst_master_blk.second_stage_objective)}"
+        " Second-stage objective " f"{value(worst_master_blk.second_stage_objective)}"
     )
     polished_master_obj = value(
-        worst_master_blk.first_stage_objective
-        + worst_master_blk.second_stage_objective
+        worst_master_blk.first_stage_objective + worst_master_blk.second_stage_objective
     )
     config.progress_logger.debug(f" Objective {polished_master_obj}")
 
@@ -785,8 +781,7 @@ def solver_call_master(model_data, config, solver, solve_data):
                 f" Second-stage objective {master_soln.second_stage_objective}"
             )
             master_obj = (
-                master_soln.first_stage_objective
-                + master_soln.second_stage_objective
+                master_soln.first_stage_objective + master_soln.second_stage_objective
             )
             config.progress_logger.debug(f" Objective {master_obj}")
 
@@ -831,8 +826,7 @@ def solver_call_master(model_data, config, solver, solve_data):
             ),
         )
         nlp_model.write(
-            output_problem_path,
-            io_options={'symbolic_solver_labels': True},
+            output_problem_path, io_options={'symbolic_solver_labels': True}
         )
         serialization_msg = (
             f" Problem has been serialized to path {output_problem_path!r}."
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index c5efbb8dadb..89f0c7a39d6 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -62,18 +62,12 @@ def _get_pyomo_git_info():
 
     git_info_dict = {}
     commands_dict = {
-        "branch": [
-            "git", "-C", f"{pyros_dir}", "rev-parse", "--abbrev-ref", "HEAD"
-        ],
-        "commit hash": [
-            "git", "-C", f"{pyros_dir}", "rev-parse", "--short", "HEAD"
-        ],
+        "branch": ["git", "-C", f"{pyros_dir}", "rev-parse", "--abbrev-ref", "HEAD"],
+        "commit hash": ["git", "-C", f"{pyros_dir}", "rev-parse", "--short", "HEAD"],
     }
     for field, command in commands_dict.items():
         try:
-            field_val = (
-                subprocess.check_output(command).decode("ascii").strip()
-            )
+            field_val = subprocess.check_output(command).decode("ascii").strip()
         except subprocess.CalledProcessError:
             field_val = "unknown"
 
@@ -711,10 +705,7 @@ def _log_intro(self, logger, **log_kwargs):
             Should not include `msg`.
         """
         logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs)
-        logger.log(
-            msg="PyROS: The Pyomo Robust Optimization Solver.",
-            **log_kwargs,
-        )
+        logger.log(msg="PyROS: The Pyomo Robust Optimization Solver.", **log_kwargs)
 
         git_info_str = ", ".join(
             f"{field}: {val}" for field, val in _get_pyomo_git_info().items()
@@ -747,8 +738,7 @@ def _log_intro(self, logger, **log_kwargs):
         )
         logger.log(
             msg=(
-                "(1) Carnegie Mellon University, "
-                "Department of Chemical Engineering"
+                "(1) Carnegie Mellon University, " "Department of Chemical Engineering"
             ),
             **log_kwargs,
         )
@@ -788,10 +778,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 still under development. ", **log_kwargs)
         logger.log(
             msg=(
                 "Please provide feedback and/or report any issues by creating "
@@ -799,10 +786,7 @@ def _log_disclaimer(self, logger, **log_kwargs):
             ),
             **log_kwargs,
         )
-        logger.log(
-            msg="https://github.com/Pyomo/pyomo/issues/new/choose",
-            **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 solve(
@@ -887,20 +871,14 @@ def solve(
         # === Start timer, run the algorithm
         model_data.timing = Bunch()
         with time_code(
-                timing_data_obj=model_data.timing,
-                code_block_name='total',
-                is_main_timer=True,
-                ):
+            timing_data_obj=model_data.timing,
+            code_block_name='total',
+            is_main_timer=True,
+        ):
             tt_timer = model_data.timing.tic_toc_timer
             # output intro and disclaimer
-            self._log_intro(
-                config.progress_logger,
-                level=logging.INFO,
-            )
-            self._log_disclaimer(
-                config.progress_logger,
-                level=logging.INFO,
-            )
+            self._log_intro(config.progress_logger, level=logging.INFO)
+            self._log_disclaimer(config.progress_logger, level=logging.INFO)
 
             # log solver options
             excl_from_config_display = [
@@ -1070,9 +1048,7 @@ def solve(
             pyrosTerminationCondition.robust_infeasible: (
                 "Problem is robust infeasible."
             ),
-            pyrosTerminationCondition.time_out: (
-                "Maximum allowable time exceeded."
-            ),
+            pyrosTerminationCondition.time_out: ("Maximum allowable time exceeded."),
             pyrosTerminationCondition.max_iter: (
                 "Maximum number of iterations reached."
             ),
@@ -1086,15 +1062,12 @@ def solve(
         )
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info("Termination stats:")
-        config.progress_logger.info(
-            f" {'Iterations':<22s}: {return_soln.iterations}"
-        )
+        config.progress_logger.info(f" {'Iterations':<22s}: {return_soln.iterations}")
         config.progress_logger.info(
             f" {'Solve time (wall s)':<22s}: {return_soln.time:.4f}"
         )
         config.progress_logger.info(
-            f" {'Final objective value':<22s}: "
-            f"{return_soln.final_objective_value}"
+            f" {'Final objective value':<22s}: " f"{return_soln.final_objective_value}"
         )
         config.progress_logger.info(
             f" {'Termination condition':<22s}: "
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index d9a05425135..bba81222aa4 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -13,10 +13,7 @@
     pyrosTerminationCondition,
     IterationLogRecord,
 )
-from pyomo.contrib.pyros.util import (
-    get_main_elapsed_time,
-    coefficient_matching,
-)
+from pyomo.contrib.pyros.util import get_main_elapsed_time, coefficient_matching
 from pyomo.core.base import value
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.core.base.var import _VarData as VarData
@@ -51,20 +48,14 @@ def update_grcs_solve_data(
 
 
 def get_dr_var_to_scaled_expr_map(
-        decision_rule_eqns,
-        second_stage_vars,
-        uncertain_params,
-        decision_rule_vars,
-        ):
+    decision_rule_eqns, second_stage_vars, uncertain_params, decision_rule_vars
+):
     """
     Generate mapping from decision rule variables
     to their terms in a model's DR expression.
     """
     var_to_scaled_expr_map = ComponentMap()
-    ssv_dr_eq_zip = zip(
-        second_stage_vars,
-        decision_rule_eqns,
-    )
+    ssv_dr_eq_zip = zip(second_stage_vars, decision_rule_eqns)
     for ssv_idx, (ssv, dr_eq) in enumerate(ssv_dr_eq_zip):
         for term in dr_eq.body.args:
             is_ssv_term = (
@@ -83,16 +74,19 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
     """
     Evaluate and log model component statistics.
     """
-    config.progress_logger.info(
-        "Model statistics:"
-    )
+    config.progress_logger.info("Model statistics:")
     # print model statistics
-    dr_var_set = ComponentSet(chain(*tuple(
-        indexed_dr_var.values()
-        for indexed_dr_var in model_data.working_model.util.decision_rule_vars
-    )))
+    dr_var_set = ComponentSet(
+        chain(
+            *tuple(
+                indexed_dr_var.values()
+                for indexed_dr_var in model_data.working_model.util.decision_rule_vars
+            )
+        )
+    )
     first_stage_vars = [
-        var for var in model_data.working_model.util.first_stage_variables
+        var
+        for var in model_data.working_model.util.first_stage_variables
         if var not in dr_var_set
     ]
 
@@ -107,24 +101,25 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
     num_vars = int(has_epigraph_con) + num_fsv + num_ssv + num_sv + num_dr_vars
 
     eq_cons = [
-        con for con in
-        model_data.working_model.component_data_objects(
-            Constraint,
-            active=True,
+        con
+        for con in model_data.working_model.component_data_objects(
+            Constraint, active=True
         )
         if con.equality
     ]
-    dr_eq_set = ComponentSet(chain(*tuple(
-        indexed_dr_eq.values()
-        for indexed_dr_eq in model_data.working_model.util.decision_rule_eqns
-    )))
+    dr_eq_set = ComponentSet(
+        chain(
+            *tuple(
+                indexed_dr_eq.values()
+                for indexed_dr_eq in model_data.working_model.util.decision_rule_eqns
+            )
+        )
+    )
     num_eq_cons = len(eq_cons)
     num_dr_cons = len(dr_eq_set)
-    num_coefficient_matching_cons = len(getattr(
-        model_data.working_model,
-        "coefficient_matching_constraints",
-        [],
-    ))
+    num_coefficient_matching_cons = len(
+        getattr(model_data.working_model, "coefficient_matching_constraints", [])
+    )
     num_other_eq_cons = num_eq_cons - num_dr_cons - num_coefficient_matching_cons
 
     # get performance constraints as referenced in the separation
@@ -135,8 +130,7 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
         for con in separation_model.util.performance_constraints
     )
     is_epigraph_con_first_stage = (
-        has_epigraph_con
-        and sep_model_epigraph_con not in perf_con_set
+        has_epigraph_con and sep_model_epigraph_con not in perf_con_set
     )
     working_model_perf_con_set = ComponentSet(
         model_data.working_model.find_component(new_sep_con_map.get(con, con))
@@ -150,53 +144,38 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
         for var in first_stage_vars
     )
     ineq_con_set = [
-        con for con in
-        model_data.working_model.component_data_objects(
-            Constraint,
-            active=True,
+        con
+        for con in model_data.working_model.component_data_objects(
+            Constraint, active=True
         )
         if not con.equality
     ]
-    num_fsv_ineqs = num_fsv_bounds + len(
-        [con for con in ineq_con_set if con not in working_model_perf_con_set]
-    ) + is_epigraph_con_first_stage
-    num_ineq_cons = (
-        len(ineq_con_set)
-        + has_epigraph_con
-        + num_fsv_bounds
+    num_fsv_ineqs = (
+        num_fsv_bounds
+        + len([con for con in ineq_con_set if con not in working_model_perf_con_set])
+        + is_epigraph_con_first_stage
     )
+    num_ineq_cons = len(ineq_con_set) + has_epigraph_con + num_fsv_bounds
 
-    config.progress_logger.info(
-        f"{'  Number of variables'} : {num_vars}"
-    )
-    config.progress_logger.info(
-        f"{'    Epigraph variable'} : {int(has_epigraph_con)}"
-    )
+    config.progress_logger.info(f"{'  Number of variables'} : {num_vars}")
+    config.progress_logger.info(f"{'    Epigraph variable'} : {int(has_epigraph_con)}")
     config.progress_logger.info(f"{'    First-stage variables'} : {num_fsv}")
     config.progress_logger.info(f"{'    Second-stage variables'} : {num_ssv}")
     config.progress_logger.info(f"{'    State variables'} : {num_sv}")
     config.progress_logger.info(f"{'    Decision rule variables'} : {num_dr_vars}")
     config.progress_logger.info(
-        f"{'  Number of constraints'} : "
-        f"{num_ineq_cons + num_eq_cons}"
-    )
-    config.progress_logger.info(
-        f"{'    Equality constraints'} : {num_eq_cons}"
+        f"{'  Number of constraints'} : " f"{num_ineq_cons + num_eq_cons}"
     )
+    config.progress_logger.info(f"{'    Equality constraints'} : {num_eq_cons}")
     config.progress_logger.info(
         f"{'      Coefficient matching constraints'} : "
         f"{num_coefficient_matching_cons}"
     )
+    config.progress_logger.info(f"{'      Decision rule equations'} : {num_dr_cons}")
     config.progress_logger.info(
-        f"{'      Decision rule equations'} : {num_dr_cons}"
-    )
-    config.progress_logger.info(
-        f"{'      All other equality constraints'} : "
-        f"{num_other_eq_cons}"
-    )
-    config.progress_logger.info(
-        f"{'    Inequality constraints'} : {num_ineq_cons}"
+        f"{'      All other equality constraints'} : " f"{num_other_eq_cons}"
     )
+    config.progress_logger.info(f"{'    Inequality constraints'} : {num_ineq_cons}")
     config.progress_logger.info(
         f"{'      First-stage inequalities (incl. certain var bounds)'} : "
         f"{num_fsv_ineqs}"
@@ -319,9 +298,7 @@ def ROSolver_iterative_solve(model_data, config):
     )
 
     evaluate_and_log_component_stats(
-        model_data=model_data,
-        separation_model=separation_model,
-        config=config,
+        model_data=model_data, separation_model=separation_model, config=config
     )
 
     # === Create separation problem data container object and add information to catalog during solve
@@ -373,22 +350,23 @@ def ROSolver_iterative_solve(model_data, config):
     dr_var_lists_polished = []
 
     # set up first-stage variable and DR variable sets
-    master_dr_var_set = ComponentSet(chain(*tuple(
-        indexed_var.values()
-        for indexed_var
-        in master_data.master_model.scenarios[0, 0].util.decision_rule_vars
-    )))
+    master_dr_var_set = ComponentSet(
+        chain(
+            *tuple(
+                indexed_var.values()
+                for indexed_var in master_data.master_model.scenarios[
+                    0, 0
+                ].util.decision_rule_vars
+            )
+        )
+    )
     master_fsv_set = ComponentSet(
-        var for var in
-        master_data.master_model.scenarios[0, 0].util.first_stage_variables
+        var
+        for var in master_data.master_model.scenarios[0, 0].util.first_stage_variables
         if var not in master_dr_var_set
     )
-    previous_master_fsv_vals = ComponentMap(
-        (var, None) for var in master_fsv_set
-    )
-    previous_master_dr_var_vals = ComponentMap(
-        (var, None) for var in master_dr_var_set
-    )
+    previous_master_fsv_vals = ComponentMap((var, None) for var in master_fsv_set)
+    previous_master_dr_var_vals = ComponentMap((var, None) for var in master_dr_var_set)
 
     nom_master_util_blk = master_data.master_model.scenarios[0, 0].util
     dr_var_scaled_expr_map = get_dr_var_to_scaled_expr_map(
@@ -501,11 +479,11 @@ def ROSolver_iterative_solve(model_data, config):
                     vals.append(dvar.value)
                 dr_var_lists_original.append(vals)
 
-            polishing_results, polishing_successful = (
-                master_problem_methods.minimize_dr_vars(
-                    model_data=master_data,
-                    config=config,
-                )
+            (
+                polishing_results,
+                polishing_successful,
+            ) = master_problem_methods.minimize_dr_vars(
+                model_data=master_data, config=config
             )
             timing_data.total_dr_polish_time += get_time_from_solver(polishing_results)
 
@@ -522,22 +500,31 @@ def ROSolver_iterative_solve(model_data, config):
         # and compare with previous first-stage and DR variable
         # values
         current_master_fsv_vals = ComponentMap(
-            (var, value(var))
-            for var in master_fsv_set
+            (var, value(var)) for var in master_fsv_set
         )
         current_master_dr_var_vals = ComponentMap(
-            (var, value(var))
-            for var, expr in dr_var_scaled_expr_map.items()
+            (var, value(var)) for var, expr in dr_var_scaled_expr_map.items()
         )
         if k > 0:
-            first_stage_var_shift = max(
-                abs(current_master_fsv_vals[var] - previous_master_fsv_vals[var])
-                for var in previous_master_fsv_vals
-            ) if current_master_fsv_vals else None
-            dr_var_shift = max(
-                abs(current_master_dr_var_vals[var] - previous_master_dr_var_vals[var])
-                for var in previous_master_dr_var_vals
-            ) if current_master_dr_var_vals else None
+            first_stage_var_shift = (
+                max(
+                    abs(current_master_fsv_vals[var] - previous_master_fsv_vals[var])
+                    for var in previous_master_fsv_vals
+                )
+                if current_master_fsv_vals
+                else None
+            )
+            dr_var_shift = (
+                max(
+                    abs(
+                        current_master_dr_var_vals[var]
+                        - previous_master_dr_var_vals[var]
+                    )
+                    for var in previous_master_dr_var_vals
+                )
+                if current_master_dr_var_vals
+                else None
+            )
         else:
             first_stage_var_shift = None
             dr_var_shift = None
@@ -623,20 +610,16 @@ def ROSolver_iterative_solve(model_data, config):
 
         scaled_violations = [
             solve_call_res.scaled_violations[con]
-            for con, solve_call_res
-            in separation_results.main_loop_results.solver_call_results.items()
+            for con, solve_call_res in separation_results.main_loop_results.solver_call_results.items()
             if solve_call_res.scaled_violations is not None
         ]
         if scaled_violations:
             max_sep_con_violation = max(scaled_violations)
         else:
             max_sep_con_violation = None
-        num_violated_cons = len(
-            separation_results.violated_performance_constraints
-        )
-        all_sep_problems_solved = (
-            len(scaled_violations)
-            == len(separation_model.util.performance_constraints)
+        num_violated_cons = len(separation_results.violated_performance_constraints)
+        all_sep_problems_solved = len(scaled_violations) == len(
+            separation_model.util.performance_constraints
         )
 
         iter_log_record = IterationLogRecord(
@@ -723,7 +706,7 @@ def ROSolver_iterative_solve(model_data, config):
 
         config.progress_logger.debug("Points added to master:")
         config.progress_logger.debug(
-            np.array([pt for pt in separation_data.points_added_to_master]),
+            np.array([pt for pt in separation_data.points_added_to_master])
         )
 
         k += 1
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 6efa0f66071..7d8669286f5 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -537,11 +537,8 @@ def get_worst_discrete_separation_solution(
 
 
 def get_con_name_repr(
-        separation_model,
-        perf_con,
-        with_orig_name=True,
-        with_obj_name=True,
-        ):
+    separation_model, perf_con, with_orig_name=True, with_obj_name=True
+):
     """
     Get string representation of performance constraint
     and any other modeling components to which it has
@@ -574,10 +571,8 @@ def get_con_name_repr(
     if with_orig_name:
         # check performance constraint was not added
         # at construction of separation problem
-        orig_con = (
-            separation_model
-            .util
-            .map_new_constraint_list_to_original_con.get(perf_con, perf_con)
+        orig_con = separation_model.util.map_new_constraint_list_to_original_con.get(
+            perf_con, perf_con
         )
         if orig_con is not perf_con:
             qual_strs.append(f"originally {orig_con.name!r}")
@@ -1136,7 +1131,9 @@ def solver_call_separation(
                 + ".bar"
             ),
         )
-        nlp_model.write(output_problem_path, io_options={'symbolic_solver_labels': True})
+        nlp_model.write(
+            output_problem_path, io_options={'symbolic_solver_labels': True}
+        )
         serialization_msg = (
             f"Problem has been serialized to path {output_problem_path!r}."
         )
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 9a7eb4e2f76..690595dd88b 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -1467,17 +1467,17 @@ class IterationLogRecord:
     }
 
     def __init__(
-            self,
-            iteration,
-            objective,
-            first_stage_var_shift,
-            dr_var_shift,
-            dr_polishing_failed,
-            num_violated_cons,
-            all_sep_problems_solved,
-            max_violation,
-            elapsed_time,
-            ):
+        self,
+        iteration,
+        objective,
+        first_stage_var_shift,
+        dr_var_shift,
+        dr_polishing_failed,
+        num_violated_cons,
+        all_sep_problems_solved,
+        max_violation,
+        elapsed_time,
+    ):
         """Initialize self (see class docstring)."""
         self.iteration = iteration
         self.objective = objective
@@ -1529,9 +1529,7 @@ def _format_record_attr(self, attr_name):
 
             attr_val_str = f"{eval(attr_val_fstrs[attr_name])}{qual}"
 
-            return (
-                f"{attr_val_str:{f'<{self._ATTR_FORMAT_LENGTHS[attr_name]}'}}"
-            )
+            return f"{attr_val_str:{f'<{self._ATTR_FORMAT_LENGTHS[attr_name]}'}}"
 
     def log(self, log_func, **log_func_kwargs):
         """Log self."""

From 01b93b185c6b1d9baf6726f5bbf9bff0bb652972 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 19:40:20 -0400
Subject: [PATCH 11/74] Apply black formatting to tests

---
 pyomo/contrib/pyros/tests/test_grcs.py | 9 ++++-----
 1 file changed, 4 insertions(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 0c9351835ec..3526b70b846 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -3590,7 +3590,9 @@ def test_solve_master(self):
         )
         config.declare("subproblem_file_directory", ConfigValue(default=None))
         config.declare("time_limit", ConfigValue(default=None))
-        config.declare("progress_logger", ConfigValue(default=logging.getLogger(__name__)))
+        config.declare(
+            "progress_logger", ConfigValue(default=logging.getLogger(__name__))
+        )
 
         with time_code(master_data.timing, "total", is_main_timer=True):
             master_soln = solve_master(master_data, config)
@@ -3904,10 +3906,7 @@ def test_minimize_dr_norm(self):
                 TerminationCondition.optimal,
                 msg="Minimize dr norm did not solve to optimality.",
             )
-            self.assertTrue(
-                success,
-                msg=f"DR polishing {success=}, expected True."
-            )
+            self.assertTrue(success, msg=f"DR polishing {success=}, expected True.")
 
     @unittest.skipUnless(
         baron_license_is_valid, "Global NLP solver is not available and licensed."

From 2ca6ea1314263714dab642464904df593664af02 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 7 Sep 2023 20:38:38 -0400
Subject: [PATCH 12/74] Refactor termination condition messages

---
 pyomo/contrib/pyros/pyros.py | 23 +----------------------
 pyomo/contrib/pyros/util.py  | 19 +++++++++++++++++++
 2 files changed, 20 insertions(+), 22 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 89f0c7a39d6..7b0b78f6729 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1038,28 +1038,7 @@ def solve(
                 return_soln.time = get_main_elapsed_time(model_data.timing)
                 return_soln.iterations = 0
 
-        termination_msg_dict = {
-            pyrosTerminationCondition.robust_optimal: (
-                "Robust optimal solution identified."
-            ),
-            pyrosTerminationCondition.robust_feasible: (
-                "Robust feasible solution identified."
-            ),
-            pyrosTerminationCondition.robust_infeasible: (
-                "Problem is robust infeasible."
-            ),
-            pyrosTerminationCondition.time_out: ("Maximum allowable time exceeded."),
-            pyrosTerminationCondition.max_iter: (
-                "Maximum number of iterations reached."
-            ),
-            pyrosTerminationCondition.subsolver_error: (
-                "Subordinate optimizer(s) could not solve a subproblem "
-                "to an acceptable status."
-            ),
-        }
-        config.progress_logger.info(
-            termination_msg_dict[return_soln.pyros_termination_condition]
-        )
+        config.progress_logger.info(return_soln.pyros_termination_condition.message)
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info("Termination stats:")
         config.progress_logger.info(f" {'Iterations':<22s}: {return_soln.iterations}")
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 690595dd88b..d40670580f3 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -308,6 +308,25 @@ class pyrosTerminationCondition(Enum):
     time_out = 5
     """Maximum allowable time exceeded."""
 
+    @property
+    def message(self):
+        """
+        str : Message associated with a given PyROS
+        termination condition.
+        """
+        message_dict = {
+            self.robust_optimal: "Robust optimal solution identified.",
+            self.robust_feasible: "Robust feasible solution identified.",
+            self.robust_infeasible: "Problem is robust infeasible.",
+            self.time_out: "Maximum allowable time exceeded.",
+            self.max_iter: "Maximum number of iterations reached.",
+            self.subsolver_error: (
+                "Subordinate optimizer(s) could not solve a subproblem "
+                "to an acceptable status."
+            ),
+        }
+        return message_dict[self]
+
 
 class SeparationStrategy(Enum):
     all_violations = auto()

From e58669149fccfac3ff3c53d3bf0e1c4b0910a840 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 21:26:45 -0400
Subject: [PATCH 13/74] Use `HierarchicalTimer` for detailed PyROS timing

---
 pyomo/contrib/pyros/master_problem_methods.py |   6 +
 pyomo/contrib/pyros/pyros.py                  |  20 ++-
 .../contrib/pyros/pyros_algorithm_methods.py  |   1 +
 .../pyros/separation_problem_methods.py       |   2 +
 pyomo/contrib/pyros/tests/test_grcs.py        |   9 +-
 pyomo/contrib/pyros/util.py                   | 133 ++++++++++++++++--
 6 files changed, 147 insertions(+), 24 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index b71bbb9285a..3a85c7f70a2 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -245,6 +245,7 @@ def solve_master_feasibility_problem(model_data, config):
     orig_setting, custom_setting_present = adjust_solver_time_settings(
         model_data.timing, solver, config
     )
+    model_data.timing.start_timer("main.master_feasibility")
     timer.tic(msg=None)
     try:
         results = solver.solve(model, tee=config.tee, load_solutions=False)
@@ -260,6 +261,7 @@ def solve_master_feasibility_problem(model_data, config):
         raise
     else:
         setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
+        model_data.timing.stop_timer("main.master_feasibility")
     finally:
         revert_solver_max_time_adjustment(
             solver, orig_setting, custom_setting_present, config
@@ -484,6 +486,7 @@ def minimize_dr_vars(model_data, config):
     orig_setting, custom_setting_present = adjust_solver_time_settings(
         model_data.timing, solver, config
     )
+    model_data.timing.start_timer("main.dr_polishing")
     timer.tic(msg=None)
     try:
         results = solver.solve(polishing_model, tee=config.tee, load_solutions=False)
@@ -496,6 +499,7 @@ def minimize_dr_vars(model_data, config):
         raise
     else:
         setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
+        model_data.timing.stop_timer("main.dr_polishing")
     finally:
         revert_solver_max_time_adjustment(
             solver, orig_setting, custom_setting_present, config
@@ -696,6 +700,7 @@ def solver_call_master(model_data, config, solver, solve_data):
         orig_setting, custom_setting_present = adjust_solver_time_settings(
             model_data.timing, opt, config
         )
+        model_data.timing.start_timer("main.master")
         timer.tic(msg=None)
         try:
             results = opt.solve(
@@ -716,6 +721,7 @@ def solver_call_master(model_data, config, solver, solve_data):
             raise
         else:
             setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
+            model_data.timing.stop_timer("main.master")
         finally:
             revert_solver_max_time_adjustment(
                 solver, orig_setting, custom_setting_present, config
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 7b0b78f6729..0e9dd6fa051 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -39,6 +39,7 @@
     replace_uncertain_bounds_with_constraints,
     IterationLogRecord,
     DEFAULT_LOGGER_NAME,
+    TimingData,
 )
 from pyomo.contrib.pyros.solve_data import ROSolveResults
 from pyomo.contrib.pyros.pyros_algorithm_methods import ROSolver_iterative_solve
@@ -869,13 +870,12 @@ def solve(
         model_data.timing = Bunch()
 
         # === Start timer, run the algorithm
-        model_data.timing = Bunch()
+        model_data.timing = TimingData()
         with time_code(
             timing_data_obj=model_data.timing,
-            code_block_name='total',
+            code_block_name="main",
             is_main_timer=True,
         ):
-            tt_timer = model_data.timing.tic_toc_timer
             # output intro and disclaimer
             self._log_intro(config.progress_logger, level=logging.INFO)
             self._log_disclaimer(config.progress_logger, level=logging.INFO)
@@ -897,7 +897,7 @@ def solve(
 
             # begin preprocessing
             config.progress_logger.info("Preprocessing...")
-            tt_timer.toc(msg=None)
+            model_data.timing.start_timer("main.preprocessing")
 
             # === A block to hold list-type data to make cloning easy
             util = Block(concrete=True)
@@ -978,9 +978,13 @@ def solve(
                 if "bound_con" in c.name:
                     wm_util.ssv_bounds.append(c)
 
+            model_data.timing.stop_timer("main.preprocessing")
+            preprocessing_time = model_data.timing.get_total_time(
+                "main.preprocessing",
+            )
             config.progress_logger.info(
                 f"Done preprocessing; required wall time of "
-                f"{tt_timer.toc(msg=None, delta=True):.2f}s."
+                f"{preprocessing_time:.2f}s."
             )
 
             # === Solve and load solution into model
@@ -1052,6 +1056,12 @@ def solve(
             f" {'Termination condition':<22s}: "
             f"{return_soln.pyros_termination_condition}"
         )
+        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.info("All done. Exiting PyROS.")
         config.progress_logger.info("=" * self._LOG_LINE_LENGTH)
 
         return return_soln
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index bba81222aa4..456089c2882 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -74,6 +74,7 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
     """
     Evaluate and log model component statistics.
     """
+    IterationLogRecord.log_header_rule(config.progress_logger.info)
     config.progress_logger.info("Model statistics:")
     # print model statistics
     dr_var_set = ComponentSet(
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 7d8669286f5..5a3bf5469e5 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -1030,6 +1030,7 @@ def solver_call_separation(
         orig_setting, custom_setting_present = adjust_solver_time_settings(
             model_data.timing, opt, config
         )
+        model_data.timing.start_timer(f"main.{solve_mode}_separation")
         timer.tic(msg=None)
         try:
             results = opt.solve(
@@ -1052,6 +1053,7 @@ def solver_call_separation(
             raise
         else:
             setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
+            model_data.timing.stop_timer(f"main.{solve_mode}_separation")
         finally:
             revert_solver_max_time_adjustment(
                 opt, orig_setting, custom_setting_present, config
diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 3526b70b846..50be1e218dd 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -19,6 +19,7 @@
     ObjectiveType,
     pyrosTerminationCondition,
     coefficient_matching,
+    TimingData,
 )
 from pyomo.contrib.pyros.util import replace_uncertain_bounds_with_constraints
 from pyomo.contrib.pyros.util import get_vars_from_component
@@ -3568,7 +3569,7 @@ def test_solve_master(self):
             expr=master_data.master_model.scenarios[0, 0].x
         )
         master_data.iteration = 0
-        master_data.timing = Bunch()
+        master_data.timing = TimingData()
 
         box_set = BoxSet(bounds=[(0, 2)])
         solver = SolverFactory(global_solver)
@@ -3594,7 +3595,7 @@ def test_solve_master(self):
             "progress_logger", ConfigValue(default=logging.getLogger(__name__))
         )
 
-        with time_code(master_data.timing, "total", is_main_timer=True):
+        with time_code(master_data.timing, "main", is_main_timer=True):
             master_soln = solve_master(master_data, config)
             self.assertEqual(
                 master_soln.termination_condition,
@@ -3898,8 +3899,8 @@ def test_minimize_dr_norm(self):
         master_data.master_model.const_efficiency_applied = False
         master_data.master_model.linear_efficiency_applied = False
 
-        master_data.timing = Bunch()
-        with time_code(master_data.timing, "total", is_main_timer=True):
+        master_data.timing = TimingData()
+        with time_code(master_data.timing, "main", is_main_timer=True):
             results, success = minimize_dr_vars(model_data=master_data, config=config)
             self.assertEqual(
                 results.solver.termination_condition,
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index d40670580f3..6c46ffaf1bb 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -41,7 +41,7 @@
 import logging
 from pprint import pprint
 import math
-from pyomo.common.timing import TicTocTimer
+from pyomo.common.timing import HierarchicalTimer
 
 
 # Tolerances used in the code
@@ -54,40 +54,143 @@
 DEFAULT_LOGGER_NAME = "pyomo.contrib.pyros"
 
 
+class TimingData:
+    """
+    PyROS solver timing data object.
+
+    A wrapper around `common.timing.HierarchicalTimer`,
+    with added functionality for enforcing a standardized
+    hierarchy of identifiers.
+
+    Attributes
+    ----------
+    hierarchical_timer_full_ids : set of str
+        (Class attribute.) Valid identifiers for use with
+        the encapsulated hierarchical timer.
+    """
+
+    hierarchical_timer_full_ids = {
+        "main",
+        "main.preprocessing",
+        "main.master_feasibility",
+        "main.master",
+        "main.dr_polishing",
+        "main.local_separation",
+        "main.global_separation",
+    }
+
+    def __init__(self):
+        """Initialize self (see class docstring).
+
+        """
+        self._hierarchical_timer = HierarchicalTimer()
+
+    def __str__(self):
+        """
+        String representation of `self`. Currently
+        returns the string representation of `self.hierarchical_timer`.
+
+        Returns
+        -------
+        str
+            String representation.
+        """
+        return self._hierarchical_timer.__str__()
+
+    def _validate_full_identifier(self, full_identifier):
+        """
+        Validate identifier for hierarchical timer.
+
+        Raises
+        ------
+        ValueError
+            If identifier not in `self.hierarchical_timer_full_ids`.
+        """
+        if full_identifier not in self.hierarchical_timer_full_ids:
+            raise ValueError(
+                "PyROS timing data object does not support timing ID: "
+                f"{full_identifier}."
+            )
+
+    def start_timer(self, full_identifier):
+        """Start timer for `self.hierarchical_timer`.
+
+        """
+        self._validate_full_identifier(full_identifier)
+        identifier = full_identifier.split(".")[-1]
+        return self._hierarchical_timer.start(identifier=identifier)
+
+    def stop_timer(self, full_identifier):
+        """Stop timer for `self.hierarchical_timer`.
+
+        """
+        self._validate_full_identifier(full_identifier)
+        identifier = full_identifier.split(".")[-1]
+        return self._hierarchical_timer.stop(identifier=identifier)
+
+    def get_total_time(self, full_identifier):
+        """
+        Get total time spent with identifier active.
+        """
+        self._validate_full_identifier(full_identifier)
+        return self._hierarchical_timer.get_total_time(
+            identifier=full_identifier,
+        )
+
+    def get_main_elapsed_time(self):
+        """
+        Get total time elapsed for main timer of
+        the HierarchicalTimer contained in self.
+
+        Returns
+        -------
+        float
+            Total elapsed time.
+
+        Note
+        ----
+        This method is meant for use while the main timer is active.
+        Otherwise, use ``self.get_total_time("main")``.
+        """
+        # clean?
+        return self._hierarchical_timer.timers["main"].tic_toc.toc(
+            msg=None,
+            delta=False,
+        )
+
+
 '''Code borrowed from gdpopt: time_code, get_main_elapsed_time, a_logger.'''
 
 
 @contextmanager
 def time_code(timing_data_obj, code_block_name, is_main_timer=False):
-    """Starts timer at entry, stores elapsed time at exit
+    """
+    Starts timer at entry, stores elapsed time at exit.
+
+    Parameters
+    ----------
+    timing_data_obj : TimingData
+        Timing data object.
+    code_block_name : str
+        Name of code block being timed.
 
     If `is_main_timer=True`, the start time is stored in the timing_data_obj,
     allowing calculation of total elapsed time 'on the fly' (e.g. to enforce
     a time limit) using `get_main_elapsed_time(timing_data_obj)`.
     """
     # initialize tic toc timer
-    timing_data_obj.tic_toc_timer = TicTocTimer()
-    timing_data_obj.tic_toc_timer.tic(msg=None)
+    timing_data_obj.start_timer(code_block_name)
 
     start_time = timeit.default_timer()
     if is_main_timer:
         timing_data_obj.main_timer_start_time = start_time
     yield
-    elapsed_time = timeit.default_timer() - start_time
-    prev_time = timing_data_obj.get(code_block_name, 0)
-    timing_data_obj[code_block_name] = prev_time + elapsed_time
+    timing_data_obj.stop_timer(code_block_name)
 
 
 def get_main_elapsed_time(timing_data_obj):
     """Returns the time since entering the main `time_code` context"""
-    current_time = timeit.default_timer()
-    try:
-        return current_time - timing_data_obj.main_timer_start_time
-    except AttributeError as e:
-        if 'main_timer_start_time' in str(e):
-            raise AttributeError(
-                "You need to be in a 'time_code' context to use `get_main_elapsed_time()`."
-            )
+    return timing_data_obj.get_main_elapsed_time()
 
 
 def adjust_solver_time_settings(timing_data_obj, solver, config):

From 89ede577c86624bc452a6438762ebff98f181b0f Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 21:29:03 -0400
Subject: [PATCH 14/74] Fix debug statement typo

---
 pyomo/contrib/pyros/master_problem_methods.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 3a85c7f70a2..2f7076ff336 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -546,7 +546,7 @@ def minimize_dr_vars(model_data, config):
             for mvar, pvar in zip(master_dr.values(), polish_dr.values()):
                 mvar.set_value(value(pvar), skip_validation=True)
 
-    config.progress_logger.debug(f" Optimized DDR norm: {value(polishing_obj)}")
+    config.progress_logger.debug(f" Optimized DR norm: {value(polishing_obj)}")
     config.progress_logger.debug("Polished Master objective:")
 
     # print master solution

From 3895c35bac9e4445327ed67dcc03442bdd30f2a7 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 21:39:21 -0400
Subject: [PATCH 15/74] Delete `pyros.util.output_logger`

---
 pyomo/contrib/pyros/master_problem_methods.py |   6 -
 .../pyros/separation_problem_methods.py       |   2 +-
 pyomo/contrib/pyros/util.py                   | 110 ------------------
 3 files changed, 1 insertion(+), 117 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 2f7076ff336..1707bba288e 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -22,7 +22,6 @@
     adjust_solver_time_settings,
     revert_solver_max_time_adjustment,
     get_main_elapsed_time,
-    output_logger,
 )
 from pyomo.contrib.pyros.solve_data import MasterProblemData, MasterResult
 from pyomo.opt.results import check_optimal_termination
@@ -807,7 +806,6 @@ def solver_call_master(model_data, config, solver, solve_data):
                 master_soln.pyros_termination_condition = (
                     pyrosTerminationCondition.time_out
                 )
-                output_logger(config=config, time_out=True, elapsed=elapsed)
 
         if not try_backup:
             return master_soln
@@ -883,10 +881,6 @@ def solve_master(model_data, config):
                     None,
                     pyrosTerminationCondition.time_out,
                 )
-
-                # log time out message
-                output_logger(config=config, time_out=True, elapsed=elapsed)
-
                 return master_soln
 
     solver = (
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 5a3bf5469e5..43d8108924a 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -6,7 +6,7 @@
 from pyomo.core.base import Var, Param
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.common.dependencies import numpy as np
-from pyomo.contrib.pyros.util import ObjectiveType, get_time_from_solver, output_logger
+from pyomo.contrib.pyros.util import ObjectiveType, get_time_from_solver
 from pyomo.contrib.pyros.solve_data import (
     DiscreteSeparationSolveCallResults,
     SeparationSolveCallResults,
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 6c46ffaf1bb..7ab49a818a8 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -1681,113 +1681,3 @@ def log_header(log_func, with_rules=True, **log_func_kwargs):
     def log_header_rule(log_func, fillchar="-", **log_func_kwargs):
         """Log header rule."""
         log_func(fillchar * IterationLogRecord._LINE_LENGTH, **log_func_kwargs)
-
-
-def output_logger(config, **kwargs):
-    '''
-    All user returned messages (termination conditions, runtime errors) are here
-    Includes when
-    "sub-solver %s returned status infeasible..."
-    :return:
-    '''
-
-    # === PREAMBLE + LICENSING
-    # Version printing
-    if "preamble" in kwargs:
-        if kwargs["preamble"]:
-            version = str(kwargs["version"])
-            preamble = (
-                "===========================================================================================\n"
-                "PyROS: Pyomo Robust Optimization Solver v.%s \n"
-                "Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1), \n"
-                "              John D. Siirola (2), Chrysanthos E. Gounaris (1) \n"
-                "(1) Carnegie Mellon University, Department of Chemical Engineering \n"
-                "(2) Sandia National Laboratories, Center for Computing Research\n\n"
-                "The developers gratefully acknowledge support from the U.S. Department of Energy's \n"
-                "Institute for the Design of Advanced Energy Systems (IDAES) \n"
-                "==========================================================================================="
-                % version
-            )
-            print(preamble)
-    # === DISCLAIMER
-    if "disclaimer" in kwargs:
-        if kwargs["disclaimer"]:
-            print(
-                "======================================== DISCLAIMER =======================================\n"
-                "PyROS is still under development. \n"
-                "Please provide feedback and/or report any issues by opening a Pyomo ticket.\n"
-                "===========================================================================================\n"
-            )
-    # === ALL LOGGER RETURN MESSAGES
-    if "bypass_global_separation" in kwargs:
-        if kwargs["bypass_global_separation"]:
-            config.progress_logger.info(
-                "NOTE: Option to bypass global separation was chosen. "
-                "Robust feasibility and optimality of the reported "
-                "solution are not guaranteed."
-            )
-    if "robust_optimal" in kwargs:
-        if kwargs["robust_optimal"]:
-            config.progress_logger.info(
-                'Robust optimal solution identified. Exiting PyROS.'
-            )
-
-    if "robust_feasible" in kwargs:
-        if kwargs["robust_feasible"]:
-            config.progress_logger.info(
-                'Robust feasible solution identified. Exiting PyROS.'
-            )
-
-    if "robust_infeasible" in kwargs:
-        if kwargs["robust_infeasible"]:
-            config.progress_logger.info('Robust infeasible problem. Exiting PyROS.')
-
-    if "time_out" in kwargs:
-        if kwargs["time_out"]:
-            config.progress_logger.info(
-                'PyROS was unable to identify robust solution '
-                'before exceeding time limit of %s seconds. '
-                'Consider increasing the time limit via option time_limit.'
-                % config.time_limit
-            )
-
-    if "max_iter" in kwargs:
-        if kwargs["max_iter"]:
-            config.progress_logger.info(
-                'PyROS was unable to identify robust solution '
-                'within %s iterations of the GRCS algorithm. '
-                'Consider increasing the iteration limit via option max_iter.'
-                % config.max_iter
-            )
-
-    if "master_error" in kwargs:
-        if kwargs["master_error"]:
-            status_dict = kwargs["status_dict"]
-            filename = kwargs["filename"]  # solver name to solver termination condition
-            if kwargs["iteration"] == 0:
-                raise AttributeError(
-                    "User-supplied solver(s) could not solve the deterministic model. "
-                    "Returned termination conditions were: %s"
-                    "Please ensure deterministic model is solvable by at least one of the supplied solvers. "
-                    "Exiting PyROS." % pprint(status_dict, width=1)
-                )
-            config.progress_logger.info(
-                "User-supplied solver(s) could not solve the master model at iteration %s.\n"
-                "Returned termination conditions were: %s\n"
-                "For debugging, this problem has been written to a GAMS file titled %s. Exiting PyROS."
-                % (kwargs["iteration"], pprint(status_dict), filename)
-            )
-    if "separation_error" in kwargs:
-        if kwargs["separation_error"]:
-            status_dict = kwargs["status_dict"]
-            filename = kwargs["filename"]
-            iteration = kwargs["iteration"]
-            obj = kwargs["objective"]
-            config.progress_logger.info(
-                "User-supplied solver(s) could not solve the separation problem at iteration %s under separation objective %s.\n"
-                "Returned termination conditions were: %s\n"
-                "For debugging, this problem has been written to a GAMS file titled %s. Exiting PyROS."
-                % (iteration, obj, pprint(status_dict, width=1), filename)
-            )
-
-    return

From f0e26ba8d6749716a0fce4f0cf001bc69a586b99 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 21:55:21 -0400
Subject: [PATCH 16/74] Add more detail to master failure message

---
 pyomo/contrib/pyros/master_problem_methods.py | 19 +++++++++++++++----
 1 file changed, 15 insertions(+), 4 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 1707bba288e..b18201888ad 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -686,6 +686,7 @@ def solver_call_master(model_data, config, solver, solve_data):
 
     higher_order_decision_rule_efficiency(config, model_data)
 
+    solve_mode = "global" if config.solve_master_globally else "local"
     config.progress_logger.debug("Solving master problem")
 
     timer = TicTocTimer()
@@ -715,7 +716,7 @@ def solver_call_master(model_data, config, solver, solve_data):
             config.progress_logger.error(
                 f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) "
                 "encountered exception attempting to "
-                f"solve master problem in iteration {model_data.iteration}."
+                f"solve master problem in iteration {model_data.iteration}"
             )
             raise
         else:
@@ -836,16 +837,26 @@ def solver_call_master(model_data, config, solver, solve_data):
             f" Problem has been serialized to path {output_problem_path!r}."
         )
 
+    deterministic_model_qual = (
+        " (i.e., the deterministic model)"
+        if model_data.iteration == 0 else ""
+    )
+    deterministic_msg = (
+        " Please ensure your deterministic model "
+        f"is solvable by at least one of the subordinate {solve_mode} "
+        "optimizers provided."
+    ) if model_data.iteration == 0 else ""
     master_soln.pyros_termination_condition = pyrosTerminationCondition.subsolver_error
-    solve_mode = "global" if config.solve_master_globally else "local"
     config.progress_logger.warning(
         f"Could not successfully solve master problem of iteration "
-        f"{model_data.iteration} with any of the "
+        f"{model_data.iteration}{deterministic_model_qual} with any of the "
         f"provided subordinate {solve_mode} optimizers. "
         f"(Termination statuses: "
-        f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.) "
+        f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.)"
+        f"{deterministic_msg}"
         f"{serialization_msg}"
     )
+
     return master_soln
 
 

From 27cac3da25dd553afc5bfbfb55099696565b675a Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 22:00:15 -0400
Subject: [PATCH 17/74] Tweak master and separation serialization msgs

---
 pyomo/contrib/pyros/master_problem_methods.py     | 3 ++-
 pyomo/contrib/pyros/separation_problem_methods.py | 5 +++--
 2 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index b18201888ad..28f7945205e 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -834,7 +834,8 @@ def solver_call_master(model_data, config, solver, solve_data):
             output_problem_path, io_options={'symbolic_solver_labels': True}
         )
         serialization_msg = (
-            f" Problem has been serialized to path {output_problem_path!r}."
+            " For debugging, problem has been serialized to the file "
+            f"{output_problem_path!r}."
         )
 
     deterministic_model_qual = (
diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 43d8108924a..9e3e0b72f07 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -1137,7 +1137,8 @@ def solver_call_separation(
             output_problem_path, io_options={'symbolic_solver_labels': True}
         )
         serialization_msg = (
-            f"Problem has been serialized to path {output_problem_path!r}."
+            " For debugging, problem has been serialized to the file "
+            f"{output_problem_path!r}."
         )
     solve_call_results.message = (
         "Could not successfully solve separation problem of iteration "
@@ -1145,7 +1146,7 @@ def solver_call_separation(
         f"for performance constraint {con_name_repr} with any of the "
         f"provided subordinate {solve_mode} optimizers. "
         f"(Termination statuses: "
-        f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.) "
+        f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.)"
         f"{serialization_msg}"
     )
     config.progress_logger.warning(solve_call_results.message)

From b56c0343c3243da34d22bc08f8030abc531d12cd Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 23:15:43 -0400
Subject: [PATCH 18/74] Tweak format of wall time and final objective

---
 pyomo/contrib/pyros/pyros.py | 4 ++--
 pyomo/contrib/pyros/util.py  | 2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 0e9dd6fa051..34850e33872 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1047,10 +1047,10 @@ def solve(
         config.progress_logger.info("Termination stats:")
         config.progress_logger.info(f" {'Iterations':<22s}: {return_soln.iterations}")
         config.progress_logger.info(
-            f" {'Solve time (wall s)':<22s}: {return_soln.time:.4f}"
+            f" {'Solve time (wall s)':<22s}: {return_soln.time:.3f}"
         )
         config.progress_logger.info(
-            f" {'Final objective value':<22s}: " f"{return_soln.final_objective_value}"
+            f" {'Final objective value':<22s}: " f"{return_soln.final_objective_value:.4e}"
         )
         config.progress_logger.info(
             f" {'Termination condition':<22s}: "
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 7ab49a818a8..578f1d59e20 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -1638,7 +1638,7 @@ def _format_record_attr(self, attr_name):
                 "dr_var_shift": "f'{attr_val:.4e}'",
                 "num_violated_cons": "f'{attr_val:d}'",
                 "max_violation": "f'{attr_val:.4e}'",
-                "elapsed_time": "f'{attr_val:.2f}'",
+                "elapsed_time": "f'{attr_val:.3f}'",
             }
 
             # qualifier for DR polishing and separation columns

From 91ed9eb112166fa6bb893c9d763b59a1dc8662f3 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 23:42:57 -0400
Subject: [PATCH 19/74] Make `ROSolveResults` more structured

---
 pyomo/contrib/pyros/pyros.py      | 16 ++-----
 pyomo/contrib/pyros/solve_data.py | 72 +++++++++++++++++++++++++++----
 2 files changed, 68 insertions(+), 20 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 34850e33872..5c76736ff37 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1042,21 +1042,13 @@ def solve(
                 return_soln.time = get_main_elapsed_time(model_data.timing)
                 return_soln.iterations = 0
 
-        config.progress_logger.info(return_soln.pyros_termination_condition.message)
-        config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
-        config.progress_logger.info("Termination stats:")
-        config.progress_logger.info(f" {'Iterations':<22s}: {return_soln.iterations}")
-        config.progress_logger.info(
-            f" {'Solve time (wall s)':<22s}: {return_soln.time:.3f}"
-        )
+        # log termination-related messages
         config.progress_logger.info(
-            f" {'Final objective value':<22s}: " f"{return_soln.final_objective_value:.4e}"
-        )
-        config.progress_logger.info(
-            f" {'Termination condition':<22s}: "
-            f"{return_soln.pyros_termination_condition}"
+            return_soln.pyros_termination_condition.message
         )
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
+        config.progress_logger.info(return_soln)
+        config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info(
             f"Timing breakdown:\n\n{model_data.timing}",
         )
diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 511c042e48e..232a761ffc6 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -5,17 +5,73 @@
 
 class ROSolveResults(object):
     """
-    Container for solve-instance data returned to the user after solving with PyROS.
+    PyROS solver results object.
 
-    Attributes:
-        :pyros_termination_condition: termination condition of the PyROS algorithm
-        :config: the config block for this solve instance
-        :time: Total solver CPU time
-        :iterations: total iterations done by PyROS solver
-        :final_objective_value: objective function value at termination
+    Parameters
+    ----------
+    config : ConfigDict, optional
+        User-specified solver settings.
+    iterations : int, optional
+        Number of iterations required.
+    time : float, optional
+        Total elapsed time (or wall time), in seconds.
+    final_objective_value : float, optional
+        Final objective function value to report.
+    pyros_termination_condition : pyrosTerminationCondition, optional
+        PyROS-specific termination condition.
+
+    Attributes
+    ----------
+    config : ConfigDict, optional
+        User-specified solver settings.
+    iterations : int, optional
+        Number of iterations required by PyROS.
+    time : float, optional
+        Total elapsed time (or wall time), in seconds.
+    final_objective_value : float, optional
+        Final objective function value to report.
+    pyros_termination_condition : pyros.util.pyrosTerminationStatus
+        Indicator of the manner of termination.
     """
 
-    pass
+    def __init__(
+            self,
+            config=None,
+            iterations=None,
+            time=None,
+            final_objective_value=None,
+            pyros_termination_condition=None,
+            ):
+        """Initialize self (see class docstring).
+
+        """
+        self.config = config
+        self.iterations = iterations
+        self.time = time
+        self.final_objective_value = final_objective_value
+        self.pyros_termination_condition = pyros_termination_condition
+
+    def __str__(self):
+        """
+        Generate string representation of self.
+        Does not include any information about `self.config`.
+        """
+        lines = ["Termination_stats:"]
+        attr_name_format_dict = {
+            "iterations": ("Iterations", "f'{val}'"),
+            "time": ("Solve time (wall s)", "f'{val:.3f}'"),
+            "final_objective_value": ("Final objective value", "f'{val:.4e}'"),
+            "pyros_termination_condition": ("Termination condition", "f'{val}'"),
+        }
+        attr_desc_pad_length = 1 + max(
+            len(desc) for desc, _ in attr_name_format_dict.values()
+        )
+        for attr_name, (attr_desc, fmt_str) in attr_name_format_dict.items():
+            val = getattr(self, attr_name)
+            val_str = eval(fmt_str)
+            lines.append(f" {attr_desc:<{attr_desc_pad_length}s} : {val_str}")
+
+        return "\n".join(lines)
 
 
 class MasterProblemData(object):

From a36865266c0d92ad3312d53ea0121cd40c52c6d1 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 23:52:47 -0400
Subject: [PATCH 20/74] Log timing breakdown before results object

---
 pyomo/contrib/pyros/pyros.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 5c76736ff37..ba9cc677802 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1047,12 +1047,12 @@ def solve(
             return_soln.pyros_termination_condition.message
         )
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
-        config.progress_logger.info(return_soln)
-        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.info(return_soln)
+        config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info("All done. Exiting PyROS.")
         config.progress_logger.info("=" * self._LOG_LINE_LENGTH)
 

From f456e294877cea15953edf45979016e5579ad09b Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 8 Sep 2023 23:54:15 -0400
Subject: [PATCH 21/74] Tweak solve results string rep

---
 pyomo/contrib/pyros/solve_data.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 232a761ffc6..41ff15f7939 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -56,7 +56,7 @@ def __str__(self):
         Generate string representation of self.
         Does not include any information about `self.config`.
         """
-        lines = ["Termination_stats:"]
+        lines = ["Termination stats:"]
         attr_name_format_dict = {
             "iterations": ("Iterations", "f'{val}'"),
             "time": ("Solve time (wall s)", "f'{val:.3f}'"),

From 020e2aaf3f2e7ddb7e51fe82810bb44a24d1fdbd Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 16:21:32 -0400
Subject: [PATCH 22/74] Make bypass global sep message warning level

---
 pyomo/contrib/pyros/pyros_algorithm_methods.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 456089c2882..aa8cbbd0718 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -671,8 +671,8 @@ def ROSolver_iterative_solve(model_data, config):
         robustness_certified = separation_results.robustness_certified
         if robustness_certified:
             if config.bypass_global_separation:
-                config.progress_logger.info(
-                    "NOTE: Option to bypass global separation was chosen. "
+                config.progress_logger.warning(
+                    "Option to bypass global separation was chosen. "
                     "Robust feasibility and optimality of the reported "
                     "solution are not guaranteed."
                 )

From d88df0666cc7bfdcee24339adc3b65feffa32411 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 16:29:53 -0400
Subject: [PATCH 23/74] Add documentation of PyROS solver logs

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 279 +++++++++++++++++-
 1 file changed, 276 insertions(+), 3 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 4ef57fbf26c..f7b88020a82 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -604,6 +604,8 @@ optional keyword argument ``decision_rule_order`` to the PyROS
 In this example, we select affine decision rules by setting
 ``decision_rule_order=1``:
 
+.. _example-two-stg:
+
 .. doctest::
   :skipif: not (baron.available() and baron.license_is_valid())
 
@@ -733,7 +735,278 @@ set size on the robust optimal objective function value
 and demonstrates the ease of implementing a price of robustness study
 for a given optimization problem under uncertainty.
 
-.. note::
+PyROS Solver Log Output
+-------------------------------
+
+The PyROS solver log output is controlled through the optional
+``progress_logger`` argument, itself cast to
+a standard Python logger (:py:class:`logging.Logger`) object
+at the outset of a :meth:`~pyomo.contrib.pyros.PyROS.solve` call.
+The level of detail of the solver log output
+can be adjusted by adjusting the level of the
+logger object; see :ref:`the following table <table-logging-levels>`.
+Note that by default, ``progress_logger`` is cast to a logger of level
+:py:obj:`logging.INFO`.
+
+We refer the reader to the
+:doc:`official Python logging library documentation <python:library/logging>`
+for customization of Python logger objects;
+for a basic tutorial, see the :doc:`logging HOWTO <python:howto/logging>`.
+
+.. _table-logging-levels:
+
+.. list-table:: PyROS solver log output at the various standard Python :py:mod:`logging` levels.
+   :widths: 10 50
+   :header-rows: 1
+
+   * - Logging Level
+     - Output Messages
+   * - :py:obj:`logging.ERROR`
+     - * Information on the subproblem for which an exception was raised
+         by a subordinate solver
+       * Details about failure of the PyROS coefficient matching routine
+   * - :py:obj:`logging.WARNING`
+     - * Information about a subproblem not solved to an acceptable status
+         by the user-provided subordinate optimizers
+       * Invocation of a backup solver for a particular subproblem
+       * Caution about solution robustness guarantees in event that
+         user passes ``bypass_global_separation=True``
+   * - :py:obj:`logging.INFO`
+     - * PyROS version, author, and disclaimer information
+       * Summary of user options
+       * Breakdown of model component statistics
+       * Iteration log table
+       * Termination details: message, timing breakdown, summary of statistics
+   * - :py:obj:`logging.DEBUG`
+     - * Termination outcomes (and/or summary of statistics)
+         for every subproblem
+       * Summary of separation loop outcomes: performance constraints
+         violated, uncertain parameter value added to master
+
+An example of an output log produced through the default PyROS
+progress logger is shown in
+:ref:`the snippet that follows <solver-log-snippet>`.
+Observe that the log contains the following information:
+
+
+* **Introductory information** (lines 1--18).
+  Includes the version number, author
+  information, (UTC) time at which the solver was invoked,
+  and, if available, information on the local Git branch and
+  commit hash.
+* **Summary of solver options** (lines 19--38).
+* **Preprocessing information** (lines 39--41).
+  Wall time required for preprocessing
+  the deterministic model and associated components,
+  i.e. standardizing model components and adding the decision rule
+  variables and equations.
+* **Model component statistics** (lines 42--57).
+  Breakdown of model component statistics.
+  Includes components added by PyROS, such as the decision rule variables
+  and equations.
+* **Iteration log table** (lines 58--68).
+  Summary information on the problem iterates and subproblem outcomes.
+  The constituent columns are defined in detail in
+  :ref:`the table following the snippet <table-iteration-log-columns>`.
+* **Termination message** (lines 69--70). Very brief summary of the termination outcome.
+* **Timing statistics** (lines 71--87).
+  Tabulated breakdown of the solver timing statistics, based on a
+  :class:`pyomo.common.timing.HierarchicalTimer` printout.
+  The identifiers are as follows:
+
+  * ``main``: Total time elapsed by the solver.
+  * ``main.dr_polishing``: Total time elapsed by the subordinate solvers
+    on polishing of the decision rules.
+  * ``main.global_separation``: Total time elapsed by the subordinate solvers
+    on global separation subproblems.
+  * ``main.local_separation``: Total time elapsed by the subordinate solvers
+    on local separation subproblems.
+  * ``main.master``: Total time elapsed by the subordinate solvers on
+    the master problems.
+  * ``main.master_feasibility``: Total time elapsed by the subordinate solvers
+    on the master feasibility problems.
+  * ``main.preprocessing``: Total preprocessing time.
+  * ``main.other``: Total overhead time.
+
+* **Termination statistics** (lines 88--93). Summary of statistics related to the
+  iterate at which PyROS terminates.
+* **Exit message** (lines 94--95).
+
+.. _solver-log-snippet:
+
+.. code-block:: text
+   :caption: PyROS solver output log for the :ref:`two-stage problem example <example-two-stg>`.
+   :linenos:
+
+   ==============================================================================
+   PyROS: The Pyomo Robust Optimization Solver.
+          Version 1.2.7 | Git branch: unknown, commit hash: unknown
+          Invoked at UTC 2023-09-09T18:13:21.893626
+
+   Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),
+                 John D. Siirola (2), Chrysanthos E. Gounaris (1)
+   (1) Carnegie Mellon University, Department of Chemical Engineering
+   (2) Sandia National Laboratories, Center for Computing Research
+
+   The developers gratefully acknowledge support from the U.S. Department
+   of Energy's Institute for the Design of Advanced Energy Systems (IDAES).
+   ==============================================================================
+   ================================= DISCLAIMER =================================
+   PyROS is still under development. 
+   Please provide feedback and/or report any issues by creating a ticket at
+   https://github.com/Pyomo/pyomo/issues/new/choose
+   ==============================================================================
+   Solver options:
+    time_limit=None
+    keepfiles=False
+    tee=False
+    load_solution=True
+    objective_focus=<ObjectiveType.worst_case: 1>
+    nominal_uncertain_param_vals=[0.13248000000000001, 4.97, 4.97, 1800]
+    decision_rule_order=1
+    solve_master_globally=True
+    max_iter=-1
+    robust_feasibility_tolerance=0.0001
+    separation_priority_order={}
+    progress_logger=<Logger pyomo.contrib.pyros (INFO)>
+    backup_local_solvers=[]
+    backup_global_solvers=[]
+    subproblem_file_directory=None
+    bypass_local_separation=False
+    bypass_global_separation=False
+    p_robustness={}
+   ------------------------------------------------------------------------------
+   Preprocessing...
+   Done preprocessing; required wall time of 0.23s.
+   ------------------------------------------------------------------------------
+   Model statistics:
+     Number of variables : 62
+       Epigraph variable : 1
+       First-stage variables : 7
+       Second-stage variables : 6
+       State variables : 18
+       Decision rule variables : 30
+     Number of constraints : 81
+       Equality constraints : 24
+         Coefficient matching constraints : 0
+         Decision rule equations : 6
+         All other equality constraints : 18
+       Inequality constraints : 57
+         First-stage inequalities (incl. certain var bounds) : 10
+         Performance constraints (incl. var bounds) : 47
+   ------------------------------------------------------------------------------
+   Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol    Wall Time (s) 
+   ------------------------------------------------------------------------------
+   0     3.5838e+07  -            -            5       1.8832e+04  1.212         
+   1     3.5838e+07  7.4506e-09   1.6105e+03   7       3.7766e+04  2.712         
+   2     3.6116e+07  2.7803e+05   1.2918e+03   8       1.3466e+06  4.548         
+   3     3.6285e+07  1.6957e+05   5.8386e+03   6       4.8734e+03  6.542         
+   4     3.6285e+07  1.4901e-08   3.3097e+03   1       3.5036e+01  8.916         
+   5     3.6285e+07  2.9786e-10   3.3597e+03   6       2.9103e+00  11.204        
+   6     3.6285e+07  7.4506e-07   8.7228e+02   5       4.1726e-01  13.546        
+   7     3.6285e+07  7.4506e-07   8.1995e+02   0       9.3279e-10  20.666        
+   ------------------------------------------------------------------------------
+   Robust optimal solution identified.
+   ------------------------------------------------------------------------------
+   Timing breakdown:
+
+   Identifier                ncalls   cumtime   percall      %
+   -----------------------------------------------------------
+   main                           1    20.668    20.668  100.0
+        ------------------------------------------------------
+        dr_polishing              7     1.459     0.208    7.1
+        global_separation        47     1.281     0.027    6.2
+        local_separation        376     9.105     0.024   44.1
+        master                    8     5.356     0.669   25.9
+        master_feasibility        7     0.456     0.065    2.2
+        preprocessing             1     0.232     0.232    1.1
+        other                   n/a     2.779       n/a   13.4
+        ======================================================
+   ===========================================================
+
+   ------------------------------------------------------------------------------
+   Termination stats:
+    Iterations             : 8
+    Solve time (wall s)    : 20.668
+    Final objective value  : 3.6285e+07
+    Termination condition  : pyrosTerminationCondition.robust_optimal
+   ------------------------------------------------------------------------------
+   All done. Exiting PyROS.
+   ==============================================================================
+
+
+The iteration log table is designed to provide, in a concise manner,
+important information about the progress of the iterative algorithm for
+the problem of interest.
+The constituent columns are defined in the
+:ref:`table that follows <table-iteration-log-columns>`.
+
+.. _table-iteration-log-columns:
+
+.. list-table:: PyROS iteration log table columns.
+   :widths: 10 50
+   :header-rows: 1
 
-    Please provide feedback and/or report any problems by opening an issue on
-    the `Pyomo GitHub page <https://github.com/Pyomo/pyomo/issues/new/choose>`_.
+   * - Column Name
+     - Definition
+   * - Itn
+     - Iteration number.
+   * - Objective
+     - Master solution objective function value.
+       If the objective of the deterministic model provided
+       has a maximization sense,
+       then the negative of the objective function value is displayed.
+       Expect this value to trend upward as the iteration number
+       increases.
+       If the master problems are solved globally
+       (by passing ``solve_master_globally=True``),
+       then this value should be monotonically nondecreasing
+       as the iteration number is increased.
+   * - 1-Stg Shift
+     - Infinity norm of the difference between the first-stage
+       variable vectors of the master solutions of the current
+       and previous iterations. Expect this value to trend
+       downward as the iteration number increases.
+       A dash ("-") is produced in lieu of a value in the first iteration,
+       if there are no first-stage variables, or if the master problem
+       of the current iteration is not solved successfully.
+   * - DR Shift
+     - Infinity norm of the difference between the decision rule
+       variable vectors of the master solutions of the current
+       and previous iterations.
+       Expect this value to trend downward as the iteration number increases.
+       An asterisk ("*") is appended to this value if the decision rules are
+       not successfully polished.
+       A dash ("-") is produced in lieu of a value in the first iteration,
+       if there are no decision rule variables, or if the master problem
+       of the current iteration is not solved successfully.
+   * - #CViol
+     - Number of performance constraints found to be violated during
+       the separation step of the current iteration.
+       Unless a custom prioritization of the model's performance constraints
+       is specified (through the ``separation_priority_order`` argument),
+       expect this number to trend downward as the iteration number increases.
+       A "+" is appended if not all of the separation problems
+       were solved, either due to custom prioritization, a time out, or
+       an issue encountered by the subordinate optimizers.
+       A dash ("-") is produced in lieu of a value if the separation
+       routine is not invoked during the current iteration.
+   * - Max Viol
+     - Maximum scaled performance constraint violation.
+       Expect this value to trend downward as the iteration number increases.
+       If this value is smaller than the robust feasibility tolerance,
+       then the master solution of the current iteration is certified to be
+       robust feasible or robust optimal (up to the robust feasibility tolerance),
+       and PyROS should terminate at the end of the iteration.
+       A dash ("-") is produced in lieu of a value if the separation
+       routine is not invoked during the current iteration, or if there are
+       no performance constraints.
+   * - Wall time (s)
+     - Total time elapsed by the solver, in seconds, up to the end of the
+       current iteration.
+
+
+Feedback and Reporting Issues
+-------------------------------
+Please provide feedback and/or report any problems by opening an issue on
+the `Pyomo GitHub page <https://github.com/Pyomo/pyomo/issues/new/choose>`_.

From 7e2b6d98840941e1cfd6139b4cc1b70dd029ea33 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 16:40:40 -0400
Subject: [PATCH 24/74] Update `progress_logger` argument documentation

---
 pyomo/contrib/pyros/pyros.py | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index ba9cc677802..a7ac59118cc 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -519,8 +519,13 @@ def pyros_config():
             doc=(
                 """
                 Logger (or name thereof) used for reporting PyROS solver
-                progress. If a `str` is specified, then
-                ``logging.getLogger(progress_logger)`` is used.
+                progress. If a `str` is specified, then the string
+                is cast to a ``logging.Logger`` object
+                with ``name=progress_logger`` and ``level=logging.INFO``.
+                All handlers are cleared,
+                and a single ``StreamHandler`` (with default settings)
+                is added.
+                In the default case, we also set ``propagate=False``.
                 """
             ),
             is_optional=True,

From 5fa861da9e59bd0ea283c1df5a5828c1464a4601 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 17:12:51 -0400
Subject: [PATCH 25/74] Add global sep indicator to solver logs

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 25 +++++++++----------
 .../contrib/pyros/pyros_algorithm_methods.py  |  3 +++
 pyomo/contrib/pyros/util.py                   |  8 ++++--
 3 files changed, 21 insertions(+), 15 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index f7b88020a82..73dbc29eaac 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -832,6 +832,7 @@ Observe that the log contains the following information:
   iterate at which PyROS terminates.
 * **Exit message** (lines 94--95).
 
+
 .. _solver-log-snippet:
 
 .. code-block:: text
@@ -895,16 +896,16 @@ Observe that the log contains the following information:
          First-stage inequalities (incl. certain var bounds) : 10
          Performance constraints (incl. var bounds) : 47
    ------------------------------------------------------------------------------
-   Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol    Wall Time (s) 
+   Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol     Wall Time (s) 
    ------------------------------------------------------------------------------
-   0     3.5838e+07  -            -            5       1.8832e+04  1.212         
-   1     3.5838e+07  7.4506e-09   1.6105e+03   7       3.7766e+04  2.712         
-   2     3.6116e+07  2.7803e+05   1.2918e+03   8       1.3466e+06  4.548         
-   3     3.6285e+07  1.6957e+05   5.8386e+03   6       4.8734e+03  6.542         
-   4     3.6285e+07  1.4901e-08   3.3097e+03   1       3.5036e+01  8.916         
-   5     3.6285e+07  2.9786e-10   3.3597e+03   6       2.9103e+00  11.204        
-   6     3.6285e+07  7.4506e-07   8.7228e+02   5       4.1726e-01  13.546        
-   7     3.6285e+07  7.4506e-07   8.1995e+02   0       9.3279e-10  20.666        
+   0     3.5838e+07  -            -            5       1.8832e+04   1.212         
+   1     3.5838e+07  7.4506e-09   1.6105e+03   7       3.7766e+04   2.712         
+   2     3.6116e+07  2.7803e+05   1.2918e+03   8       1.3466e+06   4.548         
+   3     3.6285e+07  1.6957e+05   5.8386e+03   6       4.8734e+03   6.542         
+   4     3.6285e+07  1.4901e-08   3.3097e+03   1       3.5036e+01   8.916         
+   5     3.6285e+07  2.9786e-10   3.3597e+03   6       2.9103e+00   11.204        
+   6     3.6285e+07  7.4506e-07   8.7228e+02   5       4.1726e-01   13.546        
+   7     3.6285e+07  7.4506e-07   8.1995e+02   0       9.3279e-10g  20.666        
    ------------------------------------------------------------------------------
    Robust optimal solution identified.
    ------------------------------------------------------------------------------
@@ -994,10 +995,8 @@ The constituent columns are defined in the
    * - Max Viol
      - Maximum scaled performance constraint violation.
        Expect this value to trend downward as the iteration number increases.
-       If this value is smaller than the robust feasibility tolerance,
-       then the master solution of the current iteration is certified to be
-       robust feasible or robust optimal (up to the robust feasibility tolerance),
-       and PyROS should terminate at the end of the iteration.
+       A 'g' is appended to the value if the separation problems were solved
+       globally during the current iteration.
        A dash ("-") is produced in lieu of a value if the separation
        routine is not invoked during the current iteration, or if there are
        no performance constraints.
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index aa8cbbd0718..00e6af29053 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -439,6 +439,7 @@ def ROSolver_iterative_solve(model_data, config):
                 max_violation=None,
                 dr_polishing_failed=None,
                 all_sep_problems_solved=None,
+                global_separation=None,
                 elapsed_time=get_main_elapsed_time(model_data.timing),
             )
             log_record.log(config.progress_logger.info)
@@ -543,6 +544,7 @@ def ROSolver_iterative_solve(model_data, config):
                     max_violation=None,
                     dr_polishing_failed=not polishing_successful,
                     all_sep_problems_solved=None,
+                    global_separation=None,
                     elapsed_time=elapsed,
                 )
                 update_grcs_solve_data(
@@ -632,6 +634,7 @@ def ROSolver_iterative_solve(model_data, config):
             max_violation=max_sep_con_violation,
             dr_polishing_failed=not polishing_successful,
             all_sep_problems_solved=all_sep_problems_solved,
+            global_separation=separation_results.solved_globally,
             elapsed_time=get_main_elapsed_time(model_data.timing),
         )
 
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 578f1d59e20..ff0ba89c264 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -1575,8 +1575,8 @@ class IterationLogRecord:
         "first_stage_var_shift": 13,
         "dr_var_shift": 13,
         "num_violated_cons": 8,
-        "max_violation": 12,
-        "elapsed_time": 14,
+        "max_violation": 13,
+        "elapsed_time": 13,
     }
     _ATTR_HEADER_NAMES = {
         "iteration": "Itn",
@@ -1597,6 +1597,7 @@ def __init__(
         dr_polishing_failed,
         num_violated_cons,
         all_sep_problems_solved,
+        global_separation,
         max_violation,
         elapsed_time,
     ):
@@ -1608,6 +1609,7 @@ def __init__(
         self.dr_polishing_failed = dr_polishing_failed
         self.num_violated_cons = num_violated_cons
         self.all_sep_problems_solved = all_sep_problems_solved
+        self.global_separation = global_separation
         self.max_violation = max_violation
         self.elapsed_time = elapsed_time
 
@@ -1646,6 +1648,8 @@ def _format_record_attr(self, attr_name):
                 qual = "*" if self.dr_polishing_failed else ""
             elif attr_name == "num_violated_cons":
                 qual = "+" if not self.all_sep_problems_solved else ""
+            elif attr_name == "max_violation":
+                qual = "g" if self.global_separation else ""
             else:
                 qual = ""
 

From 17a50fffc3ec697965f250ba1ff2fa036ebd682f Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 18:00:27 -0400
Subject: [PATCH 26/74] Apply black

---
 pyomo/contrib/pyros/master_problem_methods.py | 15 +++++++++------
 pyomo/contrib/pyros/pyros.py                  | 12 +++---------
 pyomo/contrib/pyros/solve_data.py             | 18 ++++++++----------
 pyomo/contrib/pyros/util.py                   | 19 +++++--------------
 4 files changed, 25 insertions(+), 39 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 28f7945205e..2db9410ca95 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -839,14 +839,17 @@ def solver_call_master(model_data, config, solver, solve_data):
         )
 
     deterministic_model_qual = (
-        " (i.e., the deterministic model)"
-        if model_data.iteration == 0 else ""
+        " (i.e., the deterministic model)" if model_data.iteration == 0 else ""
     )
     deterministic_msg = (
-        " Please ensure your deterministic model "
-        f"is solvable by at least one of the subordinate {solve_mode} "
-        "optimizers provided."
-    ) if model_data.iteration == 0 else ""
+        (
+            " Please ensure your deterministic model "
+            f"is solvable by at least one of the subordinate {solve_mode} "
+            "optimizers provided."
+        )
+        if model_data.iteration == 0
+        else ""
+    )
     master_soln.pyros_termination_condition = pyrosTerminationCondition.subsolver_error
     config.progress_logger.warning(
         f"Could not successfully solve master problem of iteration "
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index a7ac59118cc..d3bd37406ff 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -984,9 +984,7 @@ def solve(
                     wm_util.ssv_bounds.append(c)
 
             model_data.timing.stop_timer("main.preprocessing")
-            preprocessing_time = model_data.timing.get_total_time(
-                "main.preprocessing",
-            )
+            preprocessing_time = model_data.timing.get_total_time("main.preprocessing")
             config.progress_logger.info(
                 f"Done preprocessing; required wall time of "
                 f"{preprocessing_time:.2f}s."
@@ -1048,13 +1046,9 @@ def solve(
                 return_soln.iterations = 0
 
         # log termination-related messages
-        config.progress_logger.info(
-            return_soln.pyros_termination_condition.message
-        )
+        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(f"Timing breakdown:\n\n{model_data.timing}")
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
         config.progress_logger.info(return_soln)
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 41ff15f7939..c19b8000dca 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -35,16 +35,14 @@ class ROSolveResults(object):
     """
 
     def __init__(
-            self,
-            config=None,
-            iterations=None,
-            time=None,
-            final_objective_value=None,
-            pyros_termination_condition=None,
-            ):
-        """Initialize self (see class docstring).
-
-        """
+        self,
+        config=None,
+        iterations=None,
+        time=None,
+        final_objective_value=None,
+        pyros_termination_condition=None,
+    ):
+        """Initialize self (see class docstring)."""
         self.config = config
         self.iterations = iterations
         self.time = time
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index ff0ba89c264..e20e198f833 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -80,9 +80,7 @@ class TimingData:
     }
 
     def __init__(self):
-        """Initialize self (see class docstring).
-
-        """
+        """Initialize self (see class docstring)."""
         self._hierarchical_timer = HierarchicalTimer()
 
     def __str__(self):
@@ -113,17 +111,13 @@ def _validate_full_identifier(self, full_identifier):
             )
 
     def start_timer(self, full_identifier):
-        """Start timer for `self.hierarchical_timer`.
-
-        """
+        """Start timer for `self.hierarchical_timer`."""
         self._validate_full_identifier(full_identifier)
         identifier = full_identifier.split(".")[-1]
         return self._hierarchical_timer.start(identifier=identifier)
 
     def stop_timer(self, full_identifier):
-        """Stop timer for `self.hierarchical_timer`.
-
-        """
+        """Stop timer for `self.hierarchical_timer`."""
         self._validate_full_identifier(full_identifier)
         identifier = full_identifier.split(".")[-1]
         return self._hierarchical_timer.stop(identifier=identifier)
@@ -133,9 +127,7 @@ def get_total_time(self, full_identifier):
         Get total time spent with identifier active.
         """
         self._validate_full_identifier(full_identifier)
-        return self._hierarchical_timer.get_total_time(
-            identifier=full_identifier,
-        )
+        return self._hierarchical_timer.get_total_time(identifier=full_identifier)
 
     def get_main_elapsed_time(self):
         """
@@ -154,8 +146,7 @@ def get_main_elapsed_time(self):
         """
         # clean?
         return self._hierarchical_timer.timers["main"].tic_toc.toc(
-            msg=None,
-            delta=False,
+            msg=None, delta=False
         )
 
 

From bcf99ef2b9006a5c91aaf7c2208ff326c179265e Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 18:14:03 -0400
Subject: [PATCH 27/74] Fix 3.7 test syntax error

---
 pyomo/contrib/pyros/tests/test_grcs.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 50be1e218dd..997ca24920f 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -3907,7 +3907,7 @@ def test_minimize_dr_norm(self):
                 TerminationCondition.optimal,
                 msg="Minimize dr norm did not solve to optimality.",
             )
-            self.assertTrue(success, msg=f"DR polishing {success=}, expected True.")
+            self.assertTrue(success, msg=f"DR polishing success {success}, expected True.")
 
     @unittest.skipUnless(
         baron_license_is_valid, "Global NLP solver is not available and licensed."

From a6e1b7b000b569bc9a30ff05c02af7c643e97a34 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 18:23:02 -0400
Subject: [PATCH 28/74] Apply black to test module

---
 pyomo/contrib/pyros/tests/test_grcs.py | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 997ca24920f..0b67251e7bd 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -3907,7 +3907,9 @@ def test_minimize_dr_norm(self):
                 TerminationCondition.optimal,
                 msg="Minimize dr norm did not solve to optimality.",
             )
-            self.assertTrue(success, msg=f"DR polishing success {success}, expected True.")
+            self.assertTrue(
+                success, msg=f"DR polishing success {success}, expected True."
+            )
 
     @unittest.skipUnless(
         baron_license_is_valid, "Global NLP solver is not available and licensed."

From 69c04e3f6bd9a2547d7751bafbdcddcd040bb2e4 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 18:30:49 -0400
Subject: [PATCH 29/74] Modify casting of `progress_logger` argument

---
 pyomo/contrib/pyros/pyros.py | 15 ++++++------
 pyomo/contrib/pyros/util.py  | 47 +++++++++++++++++++++++++-----------
 2 files changed, 41 insertions(+), 21 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index d3bd37406ff..6343780f86f 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -519,13 +519,14 @@ def pyros_config():
             doc=(
                 """
                 Logger (or name thereof) used for reporting PyROS solver
-                progress. If a `str` is specified, then the string
-                is cast to a ``logging.Logger`` object
-                with ``name=progress_logger`` and ``level=logging.INFO``.
-                All handlers are cleared,
-                and a single ``StreamHandler`` (with default settings)
-                is added.
-                In the default case, we also set ``propagate=False``.
+                progress. If a `str` is specified, then ``progress_logger``
+                is cast to ``logging.getLogger(progress_logger)``.
+                In the default case, we also configure the logger
+                as follows:
+                set ``propagate=False``,
+                set ``level=logging.INFO``,
+                clear all handlers,
+                and add a single ``StreamHandler`` with default options.
                 """
             ),
             is_optional=True,
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index e20e198f833..d5c8891159e 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -323,6 +323,36 @@ def revert_solver_max_time_adjustment(
                     del solver.options[options_key]
 
 
+def setup_default_pyros_logger():
+    """
+    Setup default PyROS logger.
+
+    Returns
+    -------
+    logging.Logger
+        Default PyROS logger. Settings:
+
+        - ``name=DEFAULT_LOGGER_NAME``
+        - ``propagate=False``
+        - All handlers cleared, and a single ``StreamHandler``
+          (with default settings) added.
+    """
+    logger = logging.getLogger(DEFAULT_LOGGER_NAME)
+
+    # avoid possible influence of Pyomo logger customizations
+    logger.propagate = False
+
+    # clear handlers, want just a single stream handler
+    logger.handlers.clear()
+    ch = logging.StreamHandler()
+    logger.addHandler(ch)
+
+    # info level logger
+    logger.setLevel(logging.INFO)
+
+    return logger
+
+
 def a_logger(str_or_logger):
     """
     Standardize a string or logger object to a logger object.
@@ -344,21 +374,10 @@ def a_logger(str_or_logger):
     if isinstance(str_or_logger, logging.Logger):
         return str_or_logger
     else:
-        logger = logging.getLogger(str_or_logger)
-
         if str_or_logger == DEFAULT_LOGGER_NAME:
-            # turn off propagate to remove possible influence
-            # of overarching Pyomo logger settings
-            logger.propagate = False
-
-        # clear handlers, want just a single stream handler
-        logger.handlers.clear()
-        ch = logging.StreamHandler()
-        logger.addHandler(ch)
-
-        # info level logger
-        logger.setLevel(logging.INFO)
-
+            logger = setup_default_pyros_logger()
+        else:
+            logger = logging.getLogger(str_or_logger)
         return logger
 
 

From 41ac3721180c8e229d160cdc4aa0304cc0da7b98 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 22:55:12 -0400
Subject: [PATCH 30/74] Tweak preprocessing time format

---
 pyomo/contrib/pyros/pyros.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 6343780f86f..e8decbea451 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -988,7 +988,7 @@ def solve(
             preprocessing_time = model_data.timing.get_total_time("main.preprocessing")
             config.progress_logger.info(
                 f"Done preprocessing; required wall time of "
-                f"{preprocessing_time:.2f}s."
+                f"{preprocessing_time:.3f}s."
             )
 
             # === Solve and load solution into model

From 83c9e4cb7c19900ccb3fc07a0e421f12c63bf41d Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 9 Sep 2023 23:10:48 -0400
Subject: [PATCH 31/74] Update logging doc time format

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 73dbc29eaac..400e5ecbea0 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -878,7 +878,7 @@ Observe that the log contains the following information:
     p_robustness={}
    ------------------------------------------------------------------------------
    Preprocessing...
-   Done preprocessing; required wall time of 0.23s.
+   Done preprocessing; required wall time of 0.232s.
    ------------------------------------------------------------------------------
    Model statistics:
      Number of variables : 62

From 9c1e99fd25e87b718de96fb1a43ca4d020cbc1ef Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 17:57:27 -0400
Subject: [PATCH 32/74] Log number of uncertain parameters

---
 doc/OnlineDocs/contributed_packages/pyros.rst  | 13 +++++++------
 pyomo/contrib/pyros/pyros_algorithm_methods.py |  5 +++++
 2 files changed, 12 insertions(+), 6 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 400e5ecbea0..e4128c77b94 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -800,16 +800,16 @@ Observe that the log contains the following information:
   the deterministic model and associated components,
   i.e. standardizing model components and adding the decision rule
   variables and equations.
-* **Model component statistics** (lines 42--57).
+* **Model component statistics** (lines 42--58).
   Breakdown of model component statistics.
   Includes components added by PyROS, such as the decision rule variables
   and equations.
-* **Iteration log table** (lines 58--68).
+* **Iteration log table** (lines 59--69).
   Summary information on the problem iterates and subproblem outcomes.
   The constituent columns are defined in detail in
   :ref:`the table following the snippet <table-iteration-log-columns>`.
-* **Termination message** (lines 69--70). Very brief summary of the termination outcome.
-* **Timing statistics** (lines 71--87).
+* **Termination message** (lines 70--71). Very brief summary of the termination outcome.
+* **Timing statistics** (lines 72--88).
   Tabulated breakdown of the solver timing statistics, based on a
   :class:`pyomo.common.timing.HierarchicalTimer` printout.
   The identifiers are as follows:
@@ -828,9 +828,9 @@ Observe that the log contains the following information:
   * ``main.preprocessing``: Total preprocessing time.
   * ``main.other``: Total overhead time.
 
-* **Termination statistics** (lines 88--93). Summary of statistics related to the
+* **Termination statistics** (lines 89--94). Summary of statistics related to the
   iterate at which PyROS terminates.
-* **Exit message** (lines 94--95).
+* **Exit message** (lines 95--96).
 
 
 .. _solver-log-snippet:
@@ -887,6 +887,7 @@ Observe that the log contains the following information:
        Second-stage variables : 6
        State variables : 18
        Decision rule variables : 30
+     Number of uncertain parameters : 4
      Number of constraints : 81
        Equality constraints : 24
          Coefficient matching constraints : 0
diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 00e6af29053..3458f2caa3d 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -101,6 +101,8 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
     num_dr_vars = len(dr_var_set)
     num_vars = int(has_epigraph_con) + num_fsv + num_ssv + num_sv + num_dr_vars
 
+    num_uncertain_params = len(model_data.working_model.util.uncertain_params)
+
     eq_cons = [
         con
         for con in model_data.working_model.component_data_objects(
@@ -164,6 +166,9 @@ def evaluate_and_log_component_stats(model_data, separation_model, config):
     config.progress_logger.info(f"{'    Second-stage variables'} : {num_ssv}")
     config.progress_logger.info(f"{'    State variables'} : {num_sv}")
     config.progress_logger.info(f"{'    Decision rule variables'} : {num_dr_vars}")
+    config.progress_logger.info(
+        f"{'  Number of uncertain parameters'} : {num_uncertain_params}"
+    )
     config.progress_logger.info(
         f"{'  Number of constraints'} : " f"{num_ineq_cons + num_eq_cons}"
     )

From df8931e6546158de13cf1708a8aafad6b5801dd7 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 19:28:30 -0400
Subject: [PATCH 33/74] Tweak iteration log column definitions

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 23 +++++++++++--------
 1 file changed, 14 insertions(+), 9 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index e4128c77b94..c00ce27f38b 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -962,16 +962,20 @@ The constituent columns are defined in the
        increases.
        If the master problems are solved globally
        (by passing ``solve_master_globally=True``),
-       then this value should be monotonically nondecreasing
+       then after the iteration number exceeds the number of uncertain parameters,
+       this value should be monotonically nondecreasing
        as the iteration number is increased.
+       A dash ("-") is produced in lieu of a value if the master
+       problem of the current iteration is not solved successfully.
    * - 1-Stg Shift
      - Infinity norm of the difference between the first-stage
        variable vectors of the master solutions of the current
        and previous iterations. Expect this value to trend
        downward as the iteration number increases.
-       A dash ("-") is produced in lieu of a value in the first iteration,
-       if there are no first-stage variables, or if the master problem
-       of the current iteration is not solved successfully.
+       A dash ("-") is produced in lieu of a value
+       if the current iteration number is 0,
+       there are no first-stage variables,
+       or the master problem of the current iteration is not solved successfully.
    * - DR Shift
      - Infinity norm of the difference between the decision rule
        variable vectors of the master solutions of the current
@@ -979,9 +983,10 @@ The constituent columns are defined in the
        Expect this value to trend downward as the iteration number increases.
        An asterisk ("*") is appended to this value if the decision rules are
        not successfully polished.
-       A dash ("-") is produced in lieu of a value in the first iteration,
-       if there are no decision rule variables, or if the master problem
-       of the current iteration is not solved successfully.
+       A dash ("-") is produced in lieu of a value
+       if the current iteration number is 0,
+       there are no decision rule variables,
+       or the master problem of the current iteration is not solved successfully.
    * - #CViol
      - Number of performance constraints found to be violated during
        the separation step of the current iteration.
@@ -989,8 +994,8 @@ The constituent columns are defined in the
        is specified (through the ``separation_priority_order`` argument),
        expect this number to trend downward as the iteration number increases.
        A "+" is appended if not all of the separation problems
-       were solved, either due to custom prioritization, a time out, or
-       an issue encountered by the subordinate optimizers.
+       were solved successfully, either due to custom prioritization, a time out,
+       or an issue encountered by the subordinate optimizers.
        A dash ("-") is produced in lieu of a value if the separation
        routine is not invoked during the current iteration.
    * - Max Viol

From b380486fec1143437880819409608ad684744f6b Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 19:47:52 -0400
Subject: [PATCH 34/74] Update `IterationLogRecord` docs and attributes

---
 .../contrib/pyros/pyros_algorithm_methods.py  | 15 +++--
 pyomo/contrib/pyros/util.py                   | 55 +++++++++++++++++--
 2 files changed, 61 insertions(+), 9 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 3458f2caa3d..a5747017016 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -442,7 +442,7 @@ def ROSolver_iterative_solve(model_data, config):
                 dr_var_shift=None,
                 num_violated_cons=None,
                 max_violation=None,
-                dr_polishing_failed=None,
+                dr_polishing_success=None,
                 all_sep_problems_solved=None,
                 global_separation=None,
                 elapsed_time=get_main_elapsed_time(model_data.timing),
@@ -547,7 +547,7 @@ def ROSolver_iterative_solve(model_data, config):
                     dr_var_shift=dr_var_shift,
                     num_violated_cons=None,
                     max_violation=None,
-                    dr_polishing_failed=not polishing_successful,
+                    dr_polishing_success=polishing_successful,
                     all_sep_problems_solved=None,
                     global_separation=None,
                     elapsed_time=elapsed,
@@ -626,8 +626,13 @@ def ROSolver_iterative_solve(model_data, config):
         else:
             max_sep_con_violation = None
         num_violated_cons = len(separation_results.violated_performance_constraints)
-        all_sep_problems_solved = len(scaled_violations) == len(
-            separation_model.util.performance_constraints
+
+        all_sep_problems_solved = (
+            len(scaled_violations) == len(
+                separation_model.util.performance_constraints
+            )
+            and not separation_results.subsolver_error
+            and not separation_results.time_out
         )
 
         iter_log_record = IterationLogRecord(
@@ -637,7 +642,7 @@ def ROSolver_iterative_solve(model_data, config):
             dr_var_shift=dr_var_shift,
             num_violated_cons=num_violated_cons,
             max_violation=max_sep_con_violation,
-            dr_polishing_failed=not polishing_successful,
+            dr_polishing_success=polishing_successful,
             all_sep_problems_solved=all_sep_problems_solved,
             global_separation=separation_results.solved_globally,
             elapsed_time=get_main_elapsed_time(model_data.timing),
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index d5c8891159e..fd50df6a92d 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -1556,6 +1556,40 @@ class IterationLogRecord:
     """
     PyROS solver iteration log record.
 
+    Parameters
+    ----------
+    iteration : int or None, optional
+        Iteration number.
+    objective : int or None, optional
+        Master problem objective value.
+        Note: if the sense of the original model is maximization,
+        then this is the negative of the objective value
+        of the original model.
+    first_stage_var_shift : float or None, optional
+        Infinity norm of the difference between first-stage
+        variable vectors for the current and previous iterations.
+    dr_var_shift : float or None, optional
+        Infinity norm of the difference between decision rule
+        variable vectors for the current and previous iterations.
+    dr_polishing_success : bool or None, optional
+        True if DR polishing solved successfully, False otherwise.
+    num_violated_cons : int or None, optional
+        Number of performance constraints found to be violated
+        during separation step.
+    all_sep_problems_solved : int or None, optional
+        True if all separation problems were solved successfully,
+        False otherwise (such as if there was a time out, subsolver
+        error, or only a subset of the problems were solved due to
+        custom constraint prioritization).
+    global_separation : bool, optional
+        True if separation problems were solved with the subordinate
+        global optimizer(s), False otherwise.
+    max_violation : int or None
+        Maximum scaled violation of any performance constraint
+        found during separation step.
+    elapsed_time : float, optional
+        Total time elapsed up to the current iteration, in seconds.
+
     Attributes
     ----------
     iteration : int or None
@@ -1563,19 +1597,32 @@ class IterationLogRecord:
     objective : int or None
         Master problem objective value.
         Note: if the sense of the original model is maximization,
-        then this is the negative of the objective value.
+        then this is the negative of the objective value
+        of the original model.
     first_stage_var_shift : float or None
         Infinity norm of the difference between first-stage
         variable vectors for the current and previous iterations.
     dr_var_shift : float or None
         Infinity norm of the difference between decision rule
         variable vectors for the current and previous iterations.
+    dr_polishing_success : bool or None
+        True if DR polishing solved successfully, False otherwise.
     num_violated_cons : int or None
         Number of performance constraints found to be violated
         during separation step.
+    all_sep_problems_solved : int or None
+        True if all separation problems were solved successfully,
+        False otherwise (such as if there was a time out, subsolver
+        error, or only a subset of the problems were solved due to
+        custom constraint prioritization).
+    global_separation : bool
+        True if separation problems were solved with the subordinate
+        global optimizer(s), False otherwise.
     max_violation : int or None
         Maximum scaled violation of any performance constraint
         found during separation step.
+    elapsed_time : float
+        Total time elapsed up to the current iteration, in seconds.
     """
 
     _LINE_LENGTH = 78
@@ -1604,7 +1651,7 @@ def __init__(
         objective,
         first_stage_var_shift,
         dr_var_shift,
-        dr_polishing_failed,
+        dr_polishing_success,
         num_violated_cons,
         all_sep_problems_solved,
         global_separation,
@@ -1616,7 +1663,7 @@ def __init__(
         self.objective = objective
         self.first_stage_var_shift = first_stage_var_shift
         self.dr_var_shift = dr_var_shift
-        self.dr_polishing_failed = dr_polishing_failed
+        self.dr_polishing_success = dr_polishing_success
         self.num_violated_cons = num_violated_cons
         self.all_sep_problems_solved = all_sep_problems_solved
         self.global_separation = global_separation
@@ -1655,7 +1702,7 @@ def _format_record_attr(self, attr_name):
 
             # qualifier for DR polishing and separation columns
             if attr_name == "dr_var_shift":
-                qual = "*" if self.dr_polishing_failed else ""
+                qual = "*" if not self.dr_polishing_success else ""
             elif attr_name == "num_violated_cons":
                 qual = "+" if not self.all_sep_problems_solved else ""
             elif attr_name == "max_violation":

From ef3334ffb101dd1681435995ec2eeb9d7c465c35 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 20:40:42 -0400
Subject: [PATCH 35/74] Fix `SeparationLoopResults` attribute retrieval logic

---
 pyomo/contrib/pyros/solve_data.py | 16 ++++++----------
 1 file changed, 6 insertions(+), 10 deletions(-)

diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index c19b8000dca..10ca1bc6db8 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -580,16 +580,11 @@ def get_violating_attr(self, attr_name):
         object
             Attribute value.
         """
-        if self.solved_locally:
-            local_loop_val = getattr(self.local_separation_loop_results, attr_name)
-        else:
-            local_loop_val = None
-
-        if local_loop_val is not None:
-            attr_val = local_loop_val
+        if self.solved_globally:
+            attr_val = getattr(self.global_separation_loop_results, attr_name)
         else:
-            if self.solved_globally:
-                attr_val = getattr(self.global_separation_loop_results, attr_name)
+            if self.solved_locally:
+                attr_val = getattr(self.local_separation_loop_results, attr_name)
             else:
                 attr_val = None
 
@@ -598,7 +593,8 @@ def get_violating_attr(self, attr_name):
     @property
     def worst_case_perf_con(self):
         """
-        ...
+        Performance constraint corresponding to the separation
+        solution chosen for the next master problem.
         """
         return self.get_violating_attr("worst_case_perf_con")
 

From fd94521d6234e512fa5bf1d15ab531384bb07583 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 20:41:43 -0400
Subject: [PATCH 36/74] Apply black formatter

---
 pyomo/contrib/pyros/pyros_algorithm_methods.py | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index a5747017016..1b94d61a710 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -628,9 +628,7 @@ def ROSolver_iterative_solve(model_data, config):
         num_violated_cons = len(separation_results.violated_performance_constraints)
 
         all_sep_problems_solved = (
-            len(scaled_violations) == len(
-                separation_model.util.performance_constraints
-            )
+            len(scaled_violations) == len(separation_model.util.performance_constraints)
             and not separation_results.subsolver_error
             and not separation_results.time_out
         )

From 7a73f9bc9f6746ddffbf4f147cad7ca312b36a56 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 10 Sep 2023 20:55:12 -0400
Subject: [PATCH 37/74] Update usage example log outputs

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 27 ++++++++++++-------
 1 file changed, 18 insertions(+), 9 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index c00ce27f38b..f99fa3a94ab 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -538,12 +538,16 @@ correspond to first-stage degrees of freedom.
   ...     solve_master_globally=True,
   ...     load_solution=False,
   ... )
-  ===========================================================================================
-  PyROS: Pyomo Robust Optimization Solver ...
-  ===========================================================================================
+  ==============================================================================
+  PyROS: The Pyomo Robust Optimization Solver.
   ...
-  INFO: Robust optimal solution identified. Exiting PyROS.
-
+  ------------------------------------------------------------------------------
+  Robust optimal solution identified.
+  ------------------------------------------------------------------------------
+  ...
+  ------------------------------------------------------------------------------
+  All done. Exiting PyROS.
+  ==============================================================================
   >>> # === Query results ===
   >>> time = results_1.time
   >>> iterations = results_1.iterations
@@ -627,11 +631,16 @@ In this example, we select affine decision rules by setting
   ...     solve_master_globally=True,
   ...     decision_rule_order=1,
   ... )
-  ===========================================================================================
-  PyROS: Pyomo Robust Optimization Solver ...
+  ==============================================================================
+  PyROS: The Pyomo Robust Optimization Solver.
   ...
-  INFO: Robust optimal solution identified. Exiting PyROS.
-
+  ------------------------------------------------------------------------------
+  Robust optimal solution identified.
+  ------------------------------------------------------------------------------
+  ...
+  ------------------------------------------------------------------------------
+  All done. Exiting PyROS.
+  ==============================================================================
   >>> # === Compare final objective to the single-stage solution
   >>> two_stage_final_objective = round(
   ...     pyo.value(results_2.final_objective_value),

From 873c4f3bcbe4e121d9288fefa8dd1be3e1ba4f52 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 11 Sep 2023 13:10:31 -0400
Subject: [PATCH 38/74] Simplify separation results code + docs

---
 pyomo/contrib/pyros/solve_data.py | 44 +++++++++++++++++--------------
 1 file changed, 24 insertions(+), 20 deletions(-)

diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 10ca1bc6db8..308a0ac3ac4 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -497,6 +497,7 @@ class SeparationResults:
     ----------
     local_separation_loop_results
     global_separation_loop_results
+    main_loop_results
     subsolver_error
     time_out
     solved_locally
@@ -516,7 +517,7 @@ def __init__(self, local_separation_loop_results, global_separation_loop_results
     @property
     def time_out(self):
         """
-        Return True if time out found for local or global
+        bool : True if time out found for local or global
         separation loop, False otherwise.
         """
         local_time_out = (
@@ -530,7 +531,7 @@ def time_out(self):
     @property
     def subsolver_error(self):
         """
-        Return True if subsolver error found for local or global
+        bool : True if subsolver error found for local or global
         separation loop, False otherwise.
         """
         local_subsolver_error = (
@@ -544,7 +545,7 @@ def subsolver_error(self):
     @property
     def solved_locally(self):
         """
-        Return true if local separation loop was invoked,
+        bool : true if local separation loop was invoked,
         False otherwise.
         """
         return self.local_separation_loop_results is not None
@@ -552,13 +553,18 @@ def solved_locally(self):
     @property
     def solved_globally(self):
         """
-        Return True if global separation loop was invoked,
+        bool : True if global separation loop was invoked,
         False otherwise.
         """
         return self.global_separation_loop_results is not None
 
     def get_violating_attr(self, attr_name):
         """
+        If separation problems solved globally, returns
+        value of attribute of global separation loop results.
+
+        Otherwise, if separation problems solved locally,
+        returns value of attribute of local separation loop results.
         If local separation loop results specified, return
         value of attribute of local separation loop results.
 
@@ -580,39 +586,37 @@ def get_violating_attr(self, attr_name):
         object
             Attribute value.
         """
-        if self.solved_globally:
-            attr_val = getattr(self.global_separation_loop_results, attr_name)
-        else:
-            if self.solved_locally:
-                attr_val = getattr(self.local_separation_loop_results, attr_name)
-            else:
-                attr_val = None
-
-        return attr_val
+        return getattr(
+            self.main_loop_results,
+            attr_name,
+            None,
+        )
 
     @property
     def worst_case_perf_con(self):
         """
-        Performance constraint corresponding to the separation
-        solution chosen for the next master problem.
+        ConstraintData : Performance constraint corresponding to the
+        separation solution chosen for the next master problem.
         """
         return self.get_violating_attr("worst_case_perf_con")
 
     @property
     def main_loop_results(self):
         """
-        Get main separation loop results.
+        SeparationLoopResults : Main separation loop results.
+        In particular, this is considered to be the global
+        loop result if solved globally, and the local loop
+        results otherwise.
         """
-        if self.global_separation_loop_results is not None:
+        if self.solved_globally:
             return self.global_separation_loop_results
         return self.local_separation_loop_results
 
     @property
     def found_violation(self):
         """
-        bool: True if ``found_violation`` attribute for
-        local or global separation loop results found
-        to be True, False otherwise.
+        bool : True if ``found_violation`` attribute for
+        main separation loop results is True, False otherwise.
         """
         found_viol = self.get_violating_attr("found_violation")
         if found_viol is None:

From 8b5f51c8cf14fa8311aae40c59fdba35f23772bc Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 11 Sep 2023 14:52:40 -0400
Subject: [PATCH 39/74] Apply black

---
 pyomo/contrib/pyros/solve_data.py | 6 +-----
 1 file changed, 1 insertion(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 308a0ac3ac4..91645921a10 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -586,11 +586,7 @@ def get_violating_attr(self, attr_name):
         object
             Attribute value.
         """
-        return getattr(
-            self.main_loop_results,
-            attr_name,
-            None,
-        )
+        return getattr(self.main_loop_results, attr_name, None)
 
     @property
     def worst_case_perf_con(self):

From 61f42d49f00f6e0dc0022ffaeab2c078c1fcd958 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 21 Sep 2023 20:17:46 -0400
Subject: [PATCH 40/74] Standardize contents of the results object

---
 pyomo/contrib/pyros/pyros.py | 20 ++++++++------------
 1 file changed, 8 insertions(+), 12 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index e8decbea451..4800b346f70 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1007,13 +1007,9 @@ def solve(
                 ):
                     load_final_solution(model_data, pyros_soln.master_soln, config)
 
-                # === Return time info
-                model_data.total_cpu_time = get_main_elapsed_time(model_data.timing)
-                iterations = pyros_soln.total_iters + 1
-
-                # === Return config to user
-                return_soln.config = config
-                # Report the negative of the objective value if it was originally maximize, since we use the minimize form in the algorithm
+                # Report the negative of the objective value if it was
+                # originally maximize, since we use the minimize form
+                # in the algorithm
                 if next(model.component_data_objects(Objective)).sense == maximize:
                     negation = -1
                 else:
@@ -1029,9 +1025,7 @@ def solve(
                 return_soln.pyros_termination_condition = (
                     pyros_soln.pyros_termination_condition
                 )
-
-                return_soln.time = model_data.total_cpu_time
-                return_soln.iterations = iterations
+                return_soln.iterations = pyros_soln.total_iters + 1
 
                 # === Remove util block
                 model.del_component(model_data.util_block)
@@ -1039,13 +1033,15 @@ def solve(
                 del pyros_soln.util_block
                 del pyros_soln.working_model
             else:
+                return_soln.final_objective_value = None
                 return_soln.pyros_termination_condition = (
                     pyrosTerminationCondition.robust_infeasible
                 )
-                return_soln.final_objective_value = None
-                return_soln.time = get_main_elapsed_time(model_data.timing)
                 return_soln.iterations = 0
 
+        return_soln.config = config
+        return_soln.time = model_data.timing.get_main_elapsed_time()
+
         # log termination-related messages
         config.progress_logger.info(return_soln.pyros_termination_condition.message)
         config.progress_logger.info("-" * self._LOG_LINE_LENGTH)

From 0ee1253542ac676106aeb9503d374536abe903a4 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 21 Sep 2023 20:37:01 -0400
Subject: [PATCH 41/74] Modularize logging of config entries

---
 pyomo/contrib/pyros/pyros.py | 59 +++++++++++++++++++++++++-----------
 1 file changed, 42 insertions(+), 17 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 4800b346f70..c17d66485df 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -796,6 +796,40 @@ 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(self, logger, config, exclude_options=None, **log_kwargs):
+        """
+        Log PyROS solver options.
+
+        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()``.
+        """
+        # 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)
+        for key, val in config.items():
+            if key not in exclude_options:
+                logger.log(msg=f" {key}={val!r}", **log_kwargs)
+        logger.log(msg="-" * self._LOG_LINE_LENGTH, **log_kwargs)
+
     def solve(
         self,
         model,
@@ -883,23 +917,14 @@ def solve(
             is_main_timer=True,
         ):
             # output intro and disclaimer
-            self._log_intro(config.progress_logger, level=logging.INFO)
-            self._log_disclaimer(config.progress_logger, level=logging.INFO)
-
-            # log solver options
-            excl_from_config_display = [
-                "first_stage_variables",
-                "second_stage_variables",
-                "uncertain_params",
-                "uncertainty_set",
-                "local_solver",
-                "global_solver",
-            ]
-            config.progress_logger.info("Solver options:")
-            for key, val in config.items():
-                if key not in excl_from_config_display:
-                    config.progress_logger.info(f" {key}={val!r}")
-            config.progress_logger.info("-" * self._LOG_LINE_LENGTH)
+            self._log_intro(logger=config.progress_logger, level=logging.INFO)
+            self._log_disclaimer(logger=config.progress_logger, level=logging.INFO)
+            self._log_config(
+                logger=config.progress_logger,
+                config=config,
+                exclude_options=None,
+                level=logging.INFO,
+            )
 
             # begin preprocessing
             config.progress_logger.info("Preprocessing...")

From f9018a164a20a432d1258697b1ac4431e0517464 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 21 Sep 2023 20:51:05 -0400
Subject: [PATCH 42/74] Ensure objective sense accounted for in results
 reporting

---
 pyomo/contrib/pyros/pyros.py | 15 ++++++---------
 1 file changed, 6 insertions(+), 9 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index c17d66485df..8b463d96169 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1032,19 +1032,16 @@ def solve(
                 ):
                     load_final_solution(model_data, pyros_soln.master_soln, config)
 
-                # Report the negative of the objective value if it was
-                # originally maximize, since we use the minimize form
-                # in the algorithm
-                if next(model.component_data_objects(Objective)).sense == maximize:
-                    negation = -1
-                else:
-                    negation = 1
+                # account for sense of the original model objective
+                # when reporting the final PyROS (master) objective,
+                # since maximization objective is changed to
+                # minimization objective during preprocessing
                 if config.objective_focus == ObjectiveType.nominal:
-                    return_soln.final_objective_value = negation * value(
+                    return_soln.final_objective_value = active_obj.sense * value(
                         pyros_soln.master_soln.master_model.obj
                     )
                 elif config.objective_focus == ObjectiveType.worst_case:
-                    return_soln.final_objective_value = negation * value(
+                    return_soln.final_objective_value = active_obj.sense * value(
                         pyros_soln.master_soln.master_model.zeta
                     )
                 return_soln.pyros_termination_condition = (

From 899faa48c8e58e7f7f4b559900fc82822492625f Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 21 Sep 2023 21:18:41 -0400
Subject: [PATCH 43/74] Add more detailed master feasibility problem logging

---
 pyomo/contrib/pyros/master_problem_methods.py | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 2db9410ca95..9543f8e4df7 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -235,6 +235,11 @@ def solve_master_feasibility_problem(model_data, config):
     """
     model = construct_master_feasibility_problem(model_data, config)
 
+    active_obj = next(model.component_data_objects(Objective, active=True))
+    config.progress_logger.debug(
+        f"Initial master feasibility objective (total slack): {value(active_obj)}"
+    )
+
     if config.solve_master_globally:
         solver = config.global_solver
     else:
@@ -274,6 +279,18 @@ def solve_master_feasibility_problem(model_data, config):
     }
     if results.solver.termination_condition in feasible_terminations:
         model.solutions.load_from(results)
+        config.progress_logger.debug(
+            f"Final master feasibility objective (total slack): {value(active_obj)}"
+        )
+    else:
+        config.progress_logger.warning(
+            "Could not successfully solve master feasibility problem "
+            f" of iteration {model_data.iteration} with primary subordinate "
+            f"{'global' if config.solve_master_globally else 'local'} solver "
+            "to acceptable level. "
+            f"Termination stats:\n{results.solver}"
+            "Maintaining unoptimized point for master problem initialization."
+        )
 
     # load master feasibility point to master model
     for master_var, feas_var in model_data.feasibility_problem_varmap:

From ba67d71ef2d8299a542fe0614a82fab9a3922e2a Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 22 Sep 2023 00:00:11 -0400
Subject: [PATCH 44/74] Update separation initial infeas msgs

---
 .../pyros/separation_problem_methods.py       | 63 +++++++++++++------
 1 file changed, 44 insertions(+), 19 deletions(-)

diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 9e3e0b72f07..ce76afc8ae7 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -537,7 +537,7 @@ def get_worst_discrete_separation_solution(
 
 
 def get_con_name_repr(
-    separation_model, perf_con, with_orig_name=True, with_obj_name=True
+    separation_model, con, with_orig_name=True, with_obj_name=True
 ):
     """
     Get string representation of performance constraint
@@ -548,9 +548,8 @@ def get_con_name_repr(
     ----------
     separation_model : ConcreteModel
         Separation model.
-    perf_con : ScalarConstraint or ConstraintData
-        Performance constraint for which to get the
-        representation
+    con : ScalarConstraint or ConstraintData
+        Constraint for which to get the representation.
     with_orig_name : bool, optional
         If constraint was added during construction of the
         separation problem (i.e. if the constraint is a member of
@@ -559,7 +558,8 @@ def get_con_name_repr(
         `perf_con` was created.
     with_obj_name : bool, optional
         Include name of separation model objective to which
-        performance constraint is mapped.
+        constraint is mapped. Applicable only to performance
+        constraints of the separation problem.
 
     Returns
     -------
@@ -572,18 +572,18 @@ def get_con_name_repr(
         # check performance constraint was not added
         # at construction of separation problem
         orig_con = separation_model.util.map_new_constraint_list_to_original_con.get(
-            perf_con, perf_con
+            con, con
         )
-        if orig_con is not perf_con:
+        if orig_con is not con:
             qual_strs.append(f"originally {orig_con.name!r}")
     if with_obj_name:
         objectives_map = separation_model.util.map_obj_to_constr
-        separation_obj = objectives_map[perf_con]
+        separation_obj = objectives_map[con]
         qual_strs.append(f"mapped to objective {separation_obj.name!r}")
 
-    final_qual_str = f"({', '.join(qual_strs)})" if qual_strs else ""
+    final_qual_str = f" ({', '.join(qual_strs)})" if qual_strs else ""
 
-    return f"{perf_con.name!r} {final_qual_str}"
+    return f"{con.name!r}{final_qual_str}"
 
 
 def perform_separation_loop(model_data, config, solve_globally):
@@ -854,7 +854,7 @@ def evaluate_performance_constraint_violations(
     return (violating_param_realization, scaled_violations, constraint_violated)
 
 
-def initialize_separation(model_data, config):
+def initialize_separation(perf_con_to_maximize, model_data, config):
     """
     Initialize separation problem variables, and fix all first-stage
     variables to their corresponding values from most recent
@@ -862,6 +862,9 @@ def initialize_separation(model_data, config):
 
     Parameters
     ----------
+    perf_con_to_maximize : ConstraintData
+        Performance constraint whose violation is to be maximized
+        for the separation problem of interest.
     model_data : SeparationProblemData
         Separation problem data.
     config : ConfigDict
@@ -943,13 +946,35 @@ def get_parent_master_blk(var):
             "All h(x,q) type constraints must be deactivated in separation."
         )
 
-    # check: initial point feasible?
+    # 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
+    perf_con_name_repr = get_con_name_repr(
+        separation_model=model_data.separation_model,
+        con=perf_con_to_maximize,
+        with_orig_name=True,
+        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):
-        lb, val, ub = value(con.lb), value(con.body), value(con.ub)
-        lb_viol = val < lb - ABS_CON_CHECK_FEAS_TOL if lb is not None else False
-        ub_viol = val > ub + ABS_CON_CHECK_FEAS_TOL if ub is not None else False
-        if lb_viol or ub_viol:
-            config.progress_logger.debug(con.name, lb, val, ub)
+        lslack, uslack = con.lslack(), con.uslack()
+        if (lslack < -tol or uslack < -tol) and not uncertainty_set_is_discrete:
+            con_name_repr = get_con_name_repr(
+                separation_model=model_data.separation_model,
+                con=con,
+                with_orig_name=True,
+                with_obj_name=False,
+            )
+            config.progress_logger.debug(
+                f"Initial point for separation of performance constraint "
+                f"{perf_con_name_repr} violates the model constraint "
+                f"{con_name_repr} by more than {tol}. "
+                f"(lslack={con.lslack()}, uslack={con.uslack()})"
+            )
 
 
 locally_acceptable = {tc.optimal, tc.locallyOptimal, tc.globallyOptimal}
@@ -1000,14 +1025,14 @@ def solver_call_separation(
     # get name of constraint for loggers
     con_name_repr = get_con_name_repr(
         separation_model=nlp_model,
-        perf_con=perf_con_to_maximize,
+        con=perf_con_to_maximize,
         with_orig_name=True,
         with_obj_name=True,
     )
     solve_mode = "global" if solve_globally else "local"
 
     # === Initialize separation problem; fix first-stage variables
-    initialize_separation(model_data, config)
+    initialize_separation(perf_con_to_maximize, model_data, config)
 
     separation_obj.activate()
 

From 442c0a2249493fabb04a0a513f7b5882e443b5a0 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 22 Sep 2023 00:44:40 -0400
Subject: [PATCH 45/74] Update debug-level logging for master problems

---
 pyomo/contrib/pyros/master_problem_methods.py | 36 +++++++++++++------
 1 file changed, 25 insertions(+), 11 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 9543f8e4df7..572e0b790a8 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -236,8 +236,10 @@ def solve_master_feasibility_problem(model_data, config):
     model = construct_master_feasibility_problem(model_data, config)
 
     active_obj = next(model.component_data_objects(Objective, active=True))
+
+    config.progress_logger.debug("Solving master feasibility problem")
     config.progress_logger.debug(
-        f"Initial master feasibility objective (total slack): {value(active_obj)}"
+        f" Initial objective (total slack): {value(active_obj)}"
     )
 
     if config.solve_master_globally:
@@ -260,7 +262,7 @@ def solve_master_feasibility_problem(model_data, config):
         config.progress_logger.error(
             f"Optimizer {repr(solver)} encountered exception "
             "attempting to solve master feasibility problem in iteration "
-            f"{model_data.iteration}"
+            f"{model_data.iteration}."
         )
         raise
     else:
@@ -280,7 +282,13 @@ def solve_master_feasibility_problem(model_data, config):
     if results.solver.termination_condition in feasible_terminations:
         model.solutions.load_from(results)
         config.progress_logger.debug(
-            f"Final master feasibility objective (total slack): {value(active_obj)}"
+            f" Final objective (total slack): {value(active_obj)}"
+        )
+        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"
         )
     else:
         config.progress_logger.warning(
@@ -563,7 +571,7 @@ def minimize_dr_vars(model_data, config):
                 mvar.set_value(value(pvar), skip_validation=True)
 
     config.progress_logger.debug(f" Optimized DR norm: {value(polishing_obj)}")
-    config.progress_logger.debug("Polished Master objective:")
+    config.progress_logger.debug(" Polished Master objective:")
 
     # print master solution
     if config.objective_focus == ObjectiveType.worst_case:
@@ -579,15 +587,15 @@ def minimize_dr_vars(model_data, config):
     # debugging: summarize objective breakdown
     worst_master_blk = model_data.master_model.scenarios[worst_blk_idx]
     config.progress_logger.debug(
-        " First-stage objective " f"{value(worst_master_blk.first_stage_objective)}"
+        "  First-stage objective: " f"{value(worst_master_blk.first_stage_objective)}"
     )
     config.progress_logger.debug(
-        " Second-stage objective " f"{value(worst_master_blk.second_stage_objective)}"
+        "  Second-stage objective: " f"{value(worst_master_blk.second_stage_objective)}"
     )
     polished_master_obj = value(
         worst_master_blk.first_stage_objective + worst_master_blk.second_stage_objective
     )
-    config.progress_logger.debug(f" Objective {polished_master_obj}")
+    config.progress_logger.debug(f"  Objective: {polished_master_obj}")
 
     return results, True
 
@@ -796,17 +804,23 @@ def solver_call_master(model_data, config, solver, solve_data):
             )
 
             # debugging: log breakdown of master objective
-            config.progress_logger.debug("Master objective")
+            config.progress_logger.debug(" Optimized master objective breakdown:")
             config.progress_logger.debug(
-                f" First-stage objective {master_soln.first_stage_objective}"
+                f"  First-stage objective: {master_soln.first_stage_objective}"
             )
             config.progress_logger.debug(
-                f" Second-stage objective {master_soln.second_stage_objective}"
+                f"  Second-stage objective: {master_soln.second_stage_objective}"
             )
             master_obj = (
                 master_soln.first_stage_objective + master_soln.second_stage_objective
             )
-            config.progress_logger.debug(f" Objective {master_obj}")
+            config.progress_logger.debug(f"  Objective: {master_obj}")
+            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"
+            )
 
             master_soln.nominal_block = nlp_model.scenarios[0, 0]
             master_soln.results = results

From c80d64c6edc6c3e376202033b4f58325ef720d9e Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 22 Sep 2023 00:56:54 -0400
Subject: [PATCH 46/74] Apply black

---
 pyomo/contrib/pyros/separation_problem_methods.py | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index ce76afc8ae7..94d9bb53553 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -536,9 +536,7 @@ def get_worst_discrete_separation_solution(
     )
 
 
-def get_con_name_repr(
-    separation_model, con, with_orig_name=True, with_obj_name=True
-):
+def get_con_name_repr(separation_model, con, with_orig_name=True, with_obj_name=True):
     """
     Get string representation of performance constraint
     and any other modeling components to which it has
@@ -957,8 +955,7 @@ def get_parent_master_blk(var):
         with_obj_name=True,
     )
     uncertainty_set_is_discrete = (
-        config.uncertainty_set.geometry
-        is Geometry.DISCRETE_SCENARIOS
+        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()

From e2d642a3b6467157560961deca2de9528dcfb7a4 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 22 Sep 2023 01:15:10 -0400
Subject: [PATCH 47/74] Add additional separation debug message

---
 pyomo/contrib/pyros/separation_problem_methods.py | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 94d9bb53553..81fe06ba6cb 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -770,6 +770,8 @@ def perform_separation_loop(model_data, config, solve_globally):
             # violating separation problem solution now chosen.
             # exit loop
             break
+        else:
+            config.progress_logger.debug("No violated performance constraints found.")
 
     return SeparationLoopResults(
         solver_call_results=all_solve_call_results,

From bea5834bd97d6be29b80299328d597db76b6c6e4 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 22 Sep 2023 01:17:25 -0400
Subject: [PATCH 48/74] Update online doc log level table

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index f99fa3a94ab..485c253e5ce 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -787,10 +787,15 @@ for a basic tutorial, see the :doc:`logging HOWTO <python:howto/logging>`.
        * Iteration log table
        * Termination details: message, timing breakdown, summary of statistics
    * - :py:obj:`logging.DEBUG`
-     - * Termination outcomes (and/or summary of statistics)
-         for every subproblem
+     - * Termination outcomes and summary of statistics for
+         every master feasility, master, and DR polishing problem
+       * Progress updates for the separation procedure
+       * Separation subproblem initial point infeasibilities
        * Summary of separation loop outcomes: performance constraints
-         violated, uncertain parameter value added to master
+         violated, uncertain parameter scenario added to the
+         master problem
+       * Uncertain parameter scenarios added to the master problem
+         thus far
 
 An example of an output log produced through the default PyROS
 progress logger is shown in

From 0bf7b246a36192baf8e99bdedce1d172fb47e8cf Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 25 Sep 2023 14:54:21 -0400
Subject: [PATCH 49/74] Use `Preformatted` API for default progress logger

---
 pyomo/contrib/pyros/pyros.py      |   9 +--
 pyomo/contrib/pyros/solve_data.py |   2 +-
 pyomo/contrib/pyros/util.py       | 105 ++++++++++++++++++++++--------
 3 files changed, 82 insertions(+), 34 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 8b463d96169..ede378fc461 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -521,12 +521,9 @@ def pyros_config():
                 Logger (or name thereof) used for reporting PyROS solver
                 progress. If a `str` is specified, then ``progress_logger``
                 is cast to ``logging.getLogger(progress_logger)``.
-                In the default case, we also configure the logger
-                as follows:
-                set ``propagate=False``,
-                set ``level=logging.INFO``,
-                clear all handlers,
-                and add a single ``StreamHandler`` with default options.
+                In the default case, `progress_logger` is set to
+                a :class:`pyomo.contrib.pyros.util.PreformattedLogger`
+                object of level ``logging.INFO``.
                 """
             ),
             is_optional=True,
diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index 91645921a10..a3062185233 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -66,7 +66,7 @@ def __str__(self):
         )
         for attr_name, (attr_desc, fmt_str) in attr_name_format_dict.items():
             val = getattr(self, attr_name)
-            val_str = eval(fmt_str)
+            val_str = eval(fmt_str) if val is not None else str(val)
             lines.append(f" {attr_desc:<{attr_desc_pad_length}s} : {val_str}")
 
         return "\n".join(lines)
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index fd50df6a92d..b031ac9e2d3 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -42,6 +42,7 @@
 from pprint import pprint
 import math
 from pyomo.common.timing import HierarchicalTimer
+from pyomo.common.log import Preformatted
 
 
 # Tolerances used in the code
@@ -323,34 +324,75 @@ def revert_solver_max_time_adjustment(
                     del solver.options[options_key]
 
 
-def setup_default_pyros_logger():
+class PreformattedLogger(logging.Logger):
+    """
+    A specialized logger object designed to cast log messages
+    to Pyomo `Preformatted` objects prior to logging the messages.
+    Useful for circumventing the formatters of the standard Pyomo
+    logger in the event an instance is a descendant of the Pyomo
+    logger.
     """
-    Setup default PyROS logger.
 
-    Returns
-    -------
-    logging.Logger
-        Default PyROS logger. Settings:
+    def critical(self, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with severity
+        `logging.CRITICAL`.
+        """
+        return super(PreformattedLogger, self).critical(
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
-        - ``name=DEFAULT_LOGGER_NAME``
-        - ``propagate=False``
-        - All handlers cleared, and a single ``StreamHandler``
-          (with default settings) added.
-    """
-    logger = logging.getLogger(DEFAULT_LOGGER_NAME)
+    def error(self, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with severity
+        `logging.ERROR`.
+        """
+        return super(PreformattedLogger, self).error(
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
-    # avoid possible influence of Pyomo logger customizations
-    logger.propagate = False
+    def warning(self, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with severity
+        `logging.WARNING`.
+        """
+        return super(PreformattedLogger, self).warning(
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
-    # clear handlers, want just a single stream handler
-    logger.handlers.clear()
-    ch = logging.StreamHandler()
-    logger.addHandler(ch)
+    def info(self, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with severity
+        `logging.INFO`.
+        """
+        return super(PreformattedLogger, self).info(
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
-    # info level logger
-    logger.setLevel(logging.INFO)
+    def debug(self, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with severity
+        `logging.DEBUG`.
+        """
+        return super(PreformattedLogger, self).debug(
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
-    return logger
+    def log(self, level, msg, *args, **kwargs):
+        """
+        Preformat and log ``msg % args`` with integer
+        severity `level`.
+        """
+        return super(PreformattedLogger, self).log(
+            level,
+            Preformatted(msg % args if args else msg),
+            **kwargs,
+        )
 
 
 def a_logger(str_or_logger):
@@ -367,18 +409,27 @@ def a_logger(str_or_logger):
     logging.Logger
         If `str_or_logger` is of type `logging.Logger`,then
         `str_or_logger` is returned.
-        Otherwise, a logger with name `str_or_logger`, INFO level,
-        ``propagate=False``, and handlers reduced to just a single
-        stream handler, is returned.
+        Otherwise, ``logging.getLogger(str_or_logger)``
+        is returned. In the event `str_or_logger` is
+        the name of the default PyROS logger, the logger level
+        is set to `logging.INFO`, and a `PreformattedLogger`
+        instance is returned in lieu of a standard `Logger`
+        instance.
     """
     if isinstance(str_or_logger, logging.Logger):
-        return str_or_logger
+        logger = logging.getLogger(str_or_logger.name)
     else:
         if str_or_logger == DEFAULT_LOGGER_NAME:
-            logger = setup_default_pyros_logger()
+            # default logger: INFO level, with preformatted messages
+            current_logger_class = logging.getLoggerClass()
+            logging.setLoggerClass(PreformattedLogger)
+            logger = logging.getLogger(str_or_logger)
+            logger.setLevel(logging.INFO)
+            logging.setLoggerClass(current_logger_class)
         else:
             logger = logging.getLogger(str_or_logger)
-        return logger
+
+    return logger
 
 
 def ValidEnum(enum_class):

From 4e830441ebe26a975b48a3769157d365aed4bf6c Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 25 Sep 2023 14:55:47 -0400
Subject: [PATCH 50/74] Apply black

---
 pyomo/contrib/pyros/util.py | 19 ++++++-------------
 1 file changed, 6 insertions(+), 13 deletions(-)

diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index b031ac9e2d3..8ad98e38e89 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -339,8 +339,7 @@ def critical(self, msg, *args, **kwargs):
         `logging.CRITICAL`.
         """
         return super(PreformattedLogger, self).critical(
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            Preformatted(msg % args if args else msg), **kwargs
         )
 
     def error(self, msg, *args, **kwargs):
@@ -349,8 +348,7 @@ def error(self, msg, *args, **kwargs):
         `logging.ERROR`.
         """
         return super(PreformattedLogger, self).error(
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            Preformatted(msg % args if args else msg), **kwargs
         )
 
     def warning(self, msg, *args, **kwargs):
@@ -359,8 +357,7 @@ def warning(self, msg, *args, **kwargs):
         `logging.WARNING`.
         """
         return super(PreformattedLogger, self).warning(
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            Preformatted(msg % args if args else msg), **kwargs
         )
 
     def info(self, msg, *args, **kwargs):
@@ -369,8 +366,7 @@ def info(self, msg, *args, **kwargs):
         `logging.INFO`.
         """
         return super(PreformattedLogger, self).info(
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            Preformatted(msg % args if args else msg), **kwargs
         )
 
     def debug(self, msg, *args, **kwargs):
@@ -379,8 +375,7 @@ def debug(self, msg, *args, **kwargs):
         `logging.DEBUG`.
         """
         return super(PreformattedLogger, self).debug(
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            Preformatted(msg % args if args else msg), **kwargs
         )
 
     def log(self, level, msg, *args, **kwargs):
@@ -389,9 +384,7 @@ def log(self, level, msg, *args, **kwargs):
         severity `level`.
         """
         return super(PreformattedLogger, self).log(
-            level,
-            Preformatted(msg % args if args else msg),
-            **kwargs,
+            level, Preformatted(msg % args if args else msg), **kwargs
         )
 
 

From f8ee13e6e5e6729c6712394276261c455c8d1c29 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 17:03:05 -0400
Subject: [PATCH 51/74] Update separation problem loop progress log msgs

---
 .../pyros/separation_problem_methods.py        | 18 ++++++++++--------
 1 file changed, 10 insertions(+), 8 deletions(-)

diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py
index 81fe06ba6cb..61f347b418d 100644
--- a/pyomo/contrib/pyros/separation_problem_methods.py
+++ b/pyomo/contrib/pyros/separation_problem_methods.py
@@ -681,21 +681,23 @@ def perform_separation_loop(model_data, config, solve_globally):
             )
 
     all_solve_call_results = ComponentMap()
-    for priority, perf_constraints in sorted_priority_groups.items():
+    priority_groups_enum = enumerate(sorted_priority_groups.items())
+    for group_idx, (priority, perf_constraints) in priority_groups_enum:
         priority_group_solve_call_results = ComponentMap()
         for idx, perf_con in enumerate(perf_constraints):
+            # log progress of separation loop
             solve_adverb = "Globally" if solve_globally else "Locally"
             config.progress_logger.debug(
-                f"{solve_adverb} separating constraint "
+                f"{solve_adverb} separating performance constraint "
                 f"{get_con_name_repr(model_data.separation_model, perf_con)} "
-                f"(group priority {priority}, "
-                f"constraint {idx + 1} of {len(perf_constraints)})"
+                f"(priority {priority}, priority group {group_idx + 1} of "
+                f"{len(sorted_priority_groups)}, "
+                f"constraint {idx + 1} of {len(perf_constraints)} "
+                "in priority group, "
+                f"{len(all_solve_call_results) + idx + 1} of "
+                f"{len(all_performance_constraints)} total)"
             )
 
-            # config.progress_logger.info(
-            #     f"Separating constraint {perf_con.name}"
-            # )
-
             # solve separation problem for this performance constraint
             if uncertainty_set_is_discrete:
                 solve_call_results = get_worst_discrete_separation_solution(

From c913dd2b43a1190cb43cd8b30d98b8fa4f8e13c4 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 17:05:01 -0400
Subject: [PATCH 52/74] Fix numpy import

---
 pyomo/contrib/pyros/pyros_algorithm_methods.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 1b94d61a710..5b234b150c8 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -18,7 +18,7 @@
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.core.base.var import _VarData as VarData
 from itertools import chain
-import numpy as np
+from pyomo.common.dependencies import numpy as np
 
 
 def update_grcs_solve_data(

From 4572eb4d1b4b11a41d4a5963e3f0e24e36ab56db Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 19:41:18 -0400
Subject: [PATCH 53/74] Restructure default logger setup

---
 pyomo/contrib/pyros/pyros.py |  7 +++++--
 pyomo/contrib/pyros/util.py  | 28 ++++++++++++++++------------
 2 files changed, 21 insertions(+), 14 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index ede378fc461..07c05142164 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -38,7 +38,7 @@
     turn_bounds_to_constraints,
     replace_uncertain_bounds_with_constraints,
     IterationLogRecord,
-    DEFAULT_LOGGER_NAME,
+    setup_pyros_logger,
     TimingData,
 )
 from pyomo.contrib.pyros.solve_data import ROSolveResults
@@ -52,6 +52,9 @@
 __version__ = "1.2.7"
 
 
+default_pyros_solver_logger = setup_pyros_logger()
+
+
 def _get_pyomo_git_info():
     """
     Get Pyomo git commit hash.
@@ -514,7 +517,7 @@ def pyros_config():
     CONFIG.declare(
         "progress_logger",
         PyROSConfigValue(
-            default=DEFAULT_LOGGER_NAME,
+            default=default_pyros_solver_logger,
             domain=a_logger,
             doc=(
                 """
diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index 8ad98e38e89..cbfd20ccd17 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -388,6 +388,20 @@ def log(self, level, msg, *args, **kwargs):
         )
 
 
+def setup_pyros_logger(name=DEFAULT_LOGGER_NAME):
+    """
+    Set up pyros logger.
+    """
+    # default logger: INFO level, with preformatted messages
+    current_logger_class = logging.getLoggerClass()
+    logging.setLoggerClass(PreformattedLogger)
+    logger = logging.getLogger(DEFAULT_LOGGER_NAME)
+    logger.setLevel(logging.INFO)
+    logging.setLoggerClass(current_logger_class)
+
+    return logger
+
+
 def a_logger(str_or_logger):
     """
     Standardize a string or logger object to a logger object.
@@ -410,19 +424,9 @@ def a_logger(str_or_logger):
         instance.
     """
     if isinstance(str_or_logger, logging.Logger):
-        logger = logging.getLogger(str_or_logger.name)
+        return logging.getLogger(str_or_logger.name)
     else:
-        if str_or_logger == DEFAULT_LOGGER_NAME:
-            # default logger: INFO level, with preformatted messages
-            current_logger_class = logging.getLoggerClass()
-            logging.setLoggerClass(PreformattedLogger)
-            logger = logging.getLogger(str_or_logger)
-            logger.setLevel(logging.INFO)
-            logging.setLoggerClass(current_logger_class)
-        else:
-            logger = logging.getLogger(str_or_logger)
-
-    return logger
+        return logging.getLogger(str_or_logger)
 
 
 def ValidEnum(enum_class):

From 0fff1c68332efe10ee40adceb79d029188b22c44 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 19:49:28 -0400
Subject: [PATCH 54/74] Add tests for `IterationLogRecord` class

---
 pyomo/contrib/pyros/tests/test_grcs.py | 203 +++++++++++++++++++++++++
 1 file changed, 203 insertions(+)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 0b67251e7bd..1ee438530e1 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -20,6 +20,7 @@
     pyrosTerminationCondition,
     coefficient_matching,
     TimingData,
+    IterationLogRecord,
 )
 from pyomo.contrib.pyros.util import replace_uncertain_bounds_with_constraints
 from pyomo.contrib.pyros.util import get_vars_from_component
@@ -63,6 +64,9 @@
 import logging
 
 
+logger = logging.getLogger(__name__)
+
+
 if not (numpy_available and scipy_available):
     raise unittest.SkipTest('PyROS unit tests require numpy and scipy')
 
@@ -5639,5 +5643,204 @@ def test_two_stg_mod_with_intersection_set(self):
         )
 
 
+class TestIterationLogRecord(unittest.TestCase):
+    """
+    Test the PyROS `IterationLogRecord` class.
+    """
+
+    def test_log_header(self):
+        """Test method for logging iteration log table header."""
+        ans = (
+            "------------------------------------------------------------------------------\n"
+            "Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol     Wall Time (s)\n"
+            "------------------------------------------------------------------------------\n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            IterationLogRecord.log_header(logger.info)
+
+        self.assertEqual(
+            LOG.getvalue(),
+            ans,
+            msg="Messages logged for iteration table header do not match expected result",
+        )
+
+    def test_log_standard_iter_record(self):
+        """Test logging function for PyROS IterationLogRecord."""
+
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=4,
+            objective=1.234567,
+            first_stage_var_shift=2.3456789e-8,
+            dr_var_shift=3.456789e-7,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=True,
+            all_sep_problems_solved=True,
+            global_separation=False,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "4     1.2346e+00  2.3457e-08   3.4568e-07   10      7.6543e-03   "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
+    def test_log_iter_record_polishing_failed(self):
+        """Test iteration log record in event of polishing failure."""
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=4,
+            objective=1.234567,
+            first_stage_var_shift=2.3456789e-8,
+            dr_var_shift=3.456789e-7,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=False,
+            all_sep_problems_solved=True,
+            global_separation=False,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "4     1.2346e+00  2.3457e-08   3.4568e-07*  10      7.6543e-03   "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
+    def test_log_iter_record_global_separation(self):
+        """
+        Test iteration log record in event global separation performed.
+        In this case, a 'g' should be appended to the max violation
+        reported. Useful in the event neither local nor global separation
+        was bypassed.
+        """
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=4,
+            objective=1.234567,
+            first_stage_var_shift=2.3456789e-8,
+            dr_var_shift=3.456789e-7,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=True,
+            all_sep_problems_solved=True,
+            global_separation=True,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "4     1.2346e+00  2.3457e-08   3.4568e-07   10      7.6543e-03g  "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
+    def test_log_iter_record_not_all_sep_solved(self):
+        """
+        Test iteration log record in event not all separation problems
+        were solved successfully. This may have occurred if the PyROS
+        solver time limit was reached, or the user-provides subordinate
+        optimizer(s) were unable to solve a separation subproblem
+        to an acceptable level.
+        A '+' should be appended to the number of performance constraints
+        found to be violated.
+        """
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=4,
+            objective=1.234567,
+            first_stage_var_shift=2.3456789e-8,
+            dr_var_shift=3.456789e-7,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=True,
+            all_sep_problems_solved=False,
+            global_separation=False,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "4     1.2346e+00  2.3457e-08   3.4568e-07   10+     7.6543e-03   "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
+    def test_log_iter_record_all_special(self):
+        """
+        Test iteration log record in event DR polishing and global
+        separation failed.
+        """
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=4,
+            objective=1.234567,
+            first_stage_var_shift=2.3456789e-8,
+            dr_var_shift=3.456789e-7,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=False,
+            all_sep_problems_solved=False,
+            global_separation=True,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "4     1.2346e+00  2.3457e-08   3.4568e-07*  10+     7.6543e-03g  "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
+
 if __name__ == "__main__":
     unittest.main()

From 5b071c342d9693d75227b058f754ae54b6d4c52b Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 22:07:11 -0400
Subject: [PATCH 55/74] Update max iter termination test

---
 pyomo/contrib/pyros/tests/test_grcs.py | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 1ee438530e1..8bdf5af8397 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -3970,7 +3970,8 @@ def test_identifying_violating_param_realization(self):
         baron_license_is_valid, "Global NLP solver is not available and licensed."
     )
     @unittest.skipUnless(
-        baron_version < (23, 1, 5), "Test known to fail beginning with Baron 23.1.5"
+        baron_version < (23, 1, 5) or baron_version >= (23, 6, 23),
+        "Test known to fail for BARON 23.1.5 and versions preceding 23.6.23",
     )
     def test_terminate_with_max_iter(self):
         m = ConcreteModel()
@@ -4017,6 +4018,15 @@ def test_terminate_with_max_iter(self):
             msg="Returned termination condition is not return max_iter.",
         )
 
+        self.assertEqual(
+            results.iterations,
+            1,
+            msg=(
+                f"Number of iterations in results object is {results.iterations}, "
+                f"but expected value 1."
+            )
+        )
+
     @unittest.skipUnless(
         baron_license_is_valid, "Global NLP solver is not available and licensed."
     )

From f11792f4f56839bf0e40e3a238b2f8a64a1be436 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 22:14:52 -0400
Subject: [PATCH 56/74] Apply black

---
 pyomo/contrib/pyros/tests/test_grcs.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 8bdf5af8397..e37524e4f56 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -4024,7 +4024,7 @@ def test_terminate_with_max_iter(self):
             msg=(
                 f"Number of iterations in results object is {results.iterations}, "
                 f"but expected value 1."
-            )
+            ),
         )
 
     @unittest.skipUnless(

From 5dce537e389ee8b096f51c94e7978ecf909ea487 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sat, 30 Sep 2023 22:39:41 -0400
Subject: [PATCH 57/74] Fix accounting for model objective sense

---
 pyomo/contrib/pyros/pyros.py           | 11 +++++++----
 pyomo/contrib/pyros/tests/test_grcs.py | 16 +++++++++++++++-
 2 files changed, 22 insertions(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 07c05142164..128f59226c8 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -961,6 +961,7 @@ def solve(
             )
             assert len(active_objs) == 1
             active_obj = active_objs[0]
+            active_obj_original_sense = active_obj.sense
             recast_to_min_obj(model_data.working_model, active_obj)
 
             # === Determine first and second-stage objectives
@@ -1037,12 +1038,14 @@ def solve(
                 # since maximization objective is changed to
                 # minimization objective during preprocessing
                 if config.objective_focus == ObjectiveType.nominal:
-                    return_soln.final_objective_value = active_obj.sense * value(
-                        pyros_soln.master_soln.master_model.obj
+                    return_soln.final_objective_value = (
+                        active_obj_original_sense
+                        * value(pyros_soln.master_soln.master_model.obj)
                     )
                 elif config.objective_focus == ObjectiveType.worst_case:
-                    return_soln.final_objective_value = active_obj.sense * value(
-                        pyros_soln.master_soln.master_model.zeta
+                    return_soln.final_objective_value = (
+                        active_obj_original_sense
+                        * value(pyros_soln.master_soln.master_model.zeta)
                     )
                 return_soln.pyros_termination_condition = (
                     pyros_soln.pyros_termination_condition
diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index e37524e4f56..40c0d745cb9 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5221,12 +5221,26 @@ def test_multiple_objs(self):
         # and solve again
         m.obj_max = Objective(expr=-m.obj.expr, sense=pyo_max)
         m.obj.deactivate()
-        res = pyros_solver.solve(**solve_kwargs)
+        max_obj_res = pyros_solver.solve(**solve_kwargs)
 
         # check active objectives
         self.assertEqual(len(list(m.component_data_objects(Objective, active=True))), 1)
         self.assertTrue(m.obj_max.active)
 
+        self.assertTrue(
+            math.isclose(
+                res.final_objective_value,
+                -max_obj_res.final_objective_value,
+                abs_tol=2e-4,  # 2x the default robust feasibility tolerance
+            ),
+            msg=(
+                f"Robust optimal objective value {res.final_objective_value} "
+                "for problem with minimization objective not close to "
+                f"negative of value {max_obj_res.final_objective_value} "
+                "of equivalent maximization objective."
+            ),
+        )
+
 
 class testModelIdentifyObjectives(unittest.TestCase):
     """

From 3d5fe78e9da7dfef026044f260a3fd76bb5bd949 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 17:01:23 -0400
Subject: [PATCH 58/74] Tweak `ROSolveResults.__str__`; add tests

---
 pyomo/contrib/pyros/solve_data.py      |  2 +-
 pyomo/contrib/pyros/tests/test_grcs.py | 66 +++++++++++++++++++++++++-
 2 files changed, 66 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py
index a3062185233..40a52757bae 100644
--- a/pyomo/contrib/pyros/solve_data.py
+++ b/pyomo/contrib/pyros/solve_data.py
@@ -61,7 +61,7 @@ def __str__(self):
             "final_objective_value": ("Final objective value", "f'{val:.4e}'"),
             "pyros_termination_condition": ("Termination condition", "f'{val}'"),
         }
-        attr_desc_pad_length = 1 + max(
+        attr_desc_pad_length = max(
             len(desc) for desc, _ in attr_name_format_dict.values()
         )
         for attr_name, (attr_desc, fmt_str) in attr_name_format_dict.items():
diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 40c0d745cb9..44c96f14499 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -35,7 +35,7 @@
     solve_master,
     minimize_dr_vars,
 )
-from pyomo.contrib.pyros.solve_data import MasterProblemData
+from pyomo.contrib.pyros.solve_data import MasterProblemData, ROSolveResults
 from pyomo.common.dependencies import numpy as np, numpy_available
 from pyomo.common.dependencies import scipy as sp, scipy_available
 from pyomo.environ import maximize as pyo_max
@@ -5866,5 +5866,69 @@ def test_log_iter_record_all_special(self):
         )
 
 
+class TestROSolveResults(unittest.TestCase):
+    """
+    Test PyROS solver results object.
+    """
+
+    def test_ro_solve_results_str(self):
+        """
+        Test string representation of RO solve results object.
+        """
+        res = ROSolveResults(
+            config=SolverFactory("pyros").CONFIG(),
+            iterations=4,
+            final_objective_value=123.456789,
+            time=300.34567,
+            pyros_termination_condition=pyrosTerminationCondition.robust_optimal,
+        )
+        ans = (
+            "Termination stats:\n"
+            " Iterations            : 4\n"
+            " Solve time (wall s)   : 300.346\n"
+            " Final objective value : 1.2346e+02\n"
+            " Termination condition : pyrosTerminationCondition.robust_optimal"
+        )
+        self.assertEqual(
+            str(res),
+            ans,
+            msg=(
+                "String representation of PyROS results object does not "
+                "match expected value"
+            ),
+        )
+
+    def test_ro_solve_results_str_attrs_none(self):
+        """
+        Test string representation of PyROS solve results in event
+        one of the printed attributes is of value `None`.
+        This may occur at instantiation or, for example,
+        whenever the PyROS solver confirms robust infeasibility through
+        coefficient matching.
+        """
+        res = ROSolveResults(
+            config=SolverFactory("pyros").CONFIG(),
+            iterations=0,
+            final_objective_value=None,
+            time=300.34567,
+            pyros_termination_condition=pyrosTerminationCondition.robust_optimal,
+        )
+        ans = (
+            "Termination stats:\n"
+            " Iterations            : 0\n"
+            " Solve time (wall s)   : 300.346\n"
+            " Final objective value : None\n"
+            " Termination condition : pyrosTerminationCondition.robust_optimal"
+        )
+        self.assertEqual(
+            str(res),
+            ans,
+            msg=(
+                "String representation of PyROS results object does not "
+                "match expected value"
+            ),
+        )
+
+
 if __name__ == "__main__":
     unittest.main()

From 832853a956121d429c7e678ae38f8f6e098f9aaf Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 18:04:08 -0400
Subject: [PATCH 59/74] Test logging of PyROS solver options

---
 pyomo/contrib/pyros/tests/test_grcs.py | 49 ++++++++++++++++++++++++++
 1 file changed, 49 insertions(+)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 44c96f14499..d9dc6a9d1eb 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5930,5 +5930,54 @@ def test_ro_solve_results_str_attrs_none(self):
         )
 
 
+class TestPyROSSolverLogIntros(unittest.TestCase):
+    """
+    Test logging of introductory information by PyROS solver.
+    """
+    def test_log_config(self):
+        """
+        Test method for logging PyROS solver config dict.
+        """
+        pyros_solver = SolverFactory("pyros")
+        config = pyros_solver.CONFIG(dict(
+            nominal_uncertain_param_vals=[0.5],
+        ))
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            pyros_solver._log_config(logger=logger, config=config, level=logging.INFO)
+
+        ans = (
+            "Solver options:\n"
+            " time_limit=None\n"
+            " keepfiles=False\n"
+            " tee=False\n"
+            " load_solution=True\n"
+            " objective_focus=<ObjectiveType.nominal: 2>\n"
+            " nominal_uncertain_param_vals=[0.5]\n"
+            " decision_rule_order=0\n"
+            " solve_master_globally=False\n"
+            " max_iter=-1\n"
+            " robust_feasibility_tolerance=0.0001\n"
+            " separation_priority_order={}\n"
+            " progress_logger=<PreformattedLogger pyomo.contrib.pyros (INFO)>\n"
+            " backup_local_solvers=[]\n"
+            " backup_global_solvers=[]\n"
+            " subproblem_file_directory=None\n"
+            " bypass_local_separation=False\n"
+            " bypass_global_separation=False\n"
+            " p_robustness={}\n"
+            + "-" * 78 + "\n"
+        )
+
+        logged_str = LOG.getvalue()
+        self.assertEqual(
+            logged_str,
+            ans,
+            msg=(
+                "Logger output for PyROS solver config (default case) "
+                "does not match expected result."
+            ),
+        )
+
+
 if __name__ == "__main__":
     unittest.main()

From 0303469fad6e26d95f9d45d38e24e5c9cf235ac6 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 22:06:34 -0400
Subject: [PATCH 60/74] Test introductory PyROS solver message

---
 pyomo/contrib/pyros/tests/test_grcs.py | 33 ++++++++++++++++++++++++++
 1 file changed, 33 insertions(+)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index d9dc6a9d1eb..1052b13425f 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5978,6 +5978,39 @@ def test_log_config(self):
             ),
         )
 
+    def test_log_intro(self):
+        """
+        Test logging of PyROS solver introductory messages.
+        """
+        pyros_solver = SolverFactory("pyros")
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            pyros_solver._log_intro(logger=logger, level=logging.INFO)
+
+        intro_msgs = LOG.getvalue()
+
+        # last character should be newline; disregard it
+        intro_msg_lines = intro_msgs.split("\n")[:-1]
+
+        # check number of lines is as expected
+        self.assertEqual(
+            len(intro_msg_lines),
+            13,
+            msg=(
+                "PyROS solver introductory message does not contain"
+                "the expected number of lines."
+            ),
+        )
+
+        # first and last lines of the introductory section
+        self.assertEqual(intro_msg_lines[0], "=" * 78)
+        self.assertEqual(intro_msg_lines[-1], "=" * 78)
+
+        # check regex main text
+        self.assertRegex(
+            " ".join(intro_msg_lines[1:-1]),
+            r"PyROS: The Pyomo Robust Optimization Solver\..* \(IDAES\)\.",
+        )
+
 
 if __name__ == "__main__":
     unittest.main()

From f69378dfd2be3b75453bc90fb1c848b25a98e6d9 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 22:23:07 -0400
Subject: [PATCH 61/74] Test PyROS solver disclaimer messages

---
 pyomo/contrib/pyros/tests/test_grcs.py | 37 ++++++++++++++++++++++++++
 1 file changed, 37 insertions(+)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index 1052b13425f..a11547eed46 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -6011,6 +6011,43 @@ def test_log_intro(self):
             r"PyROS: The Pyomo Robust Optimization Solver\..* \(IDAES\)\.",
         )
 
+    def test_log_disclaimer(self):
+        """
+        Test logging of PyROS solver disclaimer messages.
+        """
+        pyros_solver = SolverFactory("pyros")
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            pyros_solver._log_disclaimer(logger=logger, level=logging.INFO)
+
+        disclaimer_msgs = LOG.getvalue()
+
+        # last character should be newline; disregard it
+        disclaimer_msg_lines = disclaimer_msgs.split("\n")[:-1]
+
+        # check number of lines is as expected
+        self.assertEqual(
+            len(disclaimer_msg_lines),
+            5,
+            msg=(
+                "PyROS solver disclaimer message does not contain"
+                "the expected number of lines."
+            ),
+        )
+
+        # regex first line of disclaimer section
+        self.assertRegex(
+            disclaimer_msg_lines[0],
+            r"=.* DISCLAIMER .*=",
+        )
+        # check last line of disclaimer section
+        self.assertEqual(disclaimer_msg_lines[-1], "=" * 78)
+
+        # check regex main text
+        self.assertRegex(
+            " ".join(disclaimer_msg_lines[1:-1]),
+            r"PyROS is still under development.*ticket at.*",
+        )
+
 
 if __name__ == "__main__":
     unittest.main()

From f47dbe95b44cd98d9f6d65528ed2bd0236c067f0 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 22:23:35 -0400
Subject: [PATCH 62/74] Apply black

---
 pyomo/contrib/pyros/tests/test_grcs.py | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index a11547eed46..d3d8b76483a 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5934,14 +5934,13 @@ class TestPyROSSolverLogIntros(unittest.TestCase):
     """
     Test logging of introductory information by PyROS solver.
     """
+
     def test_log_config(self):
         """
         Test method for logging PyROS solver config dict.
         """
         pyros_solver = SolverFactory("pyros")
-        config = pyros_solver.CONFIG(dict(
-            nominal_uncertain_param_vals=[0.5],
-        ))
+        config = pyros_solver.CONFIG(dict(nominal_uncertain_param_vals=[0.5]))
         with LoggingIntercept(level=logging.INFO) as LOG:
             pyros_solver._log_config(logger=logger, config=config, level=logging.INFO)
 
@@ -5964,8 +5963,7 @@ def test_log_config(self):
             " subproblem_file_directory=None\n"
             " bypass_local_separation=False\n"
             " bypass_global_separation=False\n"
-            " p_robustness={}\n"
-            + "-" * 78 + "\n"
+            " p_robustness={}\n" + "-" * 78 + "\n"
         )
 
         logged_str = LOG.getvalue()
@@ -6035,10 +6033,7 @@ def test_log_disclaimer(self):
         )
 
         # regex first line of disclaimer section
-        self.assertRegex(
-            disclaimer_msg_lines[0],
-            r"=.* DISCLAIMER .*=",
-        )
+        self.assertRegex(disclaimer_msg_lines[0], r"=.* DISCLAIMER .*=")
         # check last line of disclaimer section
         self.assertEqual(disclaimer_msg_lines[-1], "=" * 78)
 

From b0b124fb08e51bf08b20eb4bc5016f29751be9ad Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 22:40:10 -0400
Subject: [PATCH 63/74] Test coefficient matching detailed error message

---
 pyomo/contrib/pyros/tests/test_grcs.py | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index d3d8b76483a..c949af1ed15 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -4887,13 +4887,16 @@ def test_coefficient_matching_raises_error_4_3(self):
         # solve with PyROS
         dr_orders = [1, 2]
         for dr_order in dr_orders:
-            with self.assertRaisesRegex(
+            regex_assert_mgr = self.assertRaisesRegex(
                 ValueError,
                 expected_regex=(
                     "Coefficient matching unsuccessful. See the solver logs."
                 ),
-            ):
-                res = pyros_solver.solve(
+            )
+            logging_intercept_mgr = LoggingIntercept(level=logging.ERROR)
+
+            with regex_assert_mgr, logging_intercept_mgr as LOG:
+                pyros_solver.solve(
                     model=m,
                     first_stage_variables=[],
                     second_stage_variables=[m.x1, m.x2, m.x3],
@@ -4908,6 +4911,16 @@ def test_coefficient_matching_raises_error_4_3(self):
                     robust_feasibility_tolerance=1e-4,
                 )
 
+            detailed_error_msg = LOG.getvalue()
+            self.assertRegex(
+                detailed_error_msg[:-1],
+                (
+                    r"Equality constraint.*cannot be guaranteed to "
+                    r"be robustly feasible.*"
+                    r"Consider editing this constraint.*"
+                ),
+            )
+
     def test_coefficient_matching_robust_infeasible_proof_in_pyros(self):
         # Write the deterministic Pyomo model
         m = ConcreteModel()

From b322c7c0351dfbb43a0e071cc9c6d67a7319c621 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 23:01:09 -0400
Subject: [PATCH 64/74] Cleanup docs and implementation of `TimingData`

---
 pyomo/contrib/pyros/util.py | 42 ++++++++++++++++++++++++++++++++-----
 1 file changed, 37 insertions(+), 5 deletions(-)

diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py
index cbfd20ccd17..a956e17b089 100644
--- a/pyomo/contrib/pyros/util.py
+++ b/pyomo/contrib/pyros/util.py
@@ -59,7 +59,7 @@ class TimingData:
     """
     PyROS solver timing data object.
 
-    A wrapper around `common.timing.HierarchicalTimer`,
+    Implemented as a wrapper around `common.timing.HierarchicalTimer`,
     with added functionality for enforcing a standardized
     hierarchy of identifiers.
 
@@ -100,10 +100,15 @@ def _validate_full_identifier(self, full_identifier):
         """
         Validate identifier for hierarchical timer.
 
+        Parameters
+        ----------
+        full_identifier : str
+            Identifier to validate.
+
         Raises
         ------
         ValueError
-            If identifier not in `self.hierarchical_timer_full_ids`.
+            If identifier not in `TimingData.hierarchical_timer_full_ids`.
         """
         if full_identifier not in self.hierarchical_timer_full_ids:
             raise ValueError(
@@ -112,13 +117,31 @@ def _validate_full_identifier(self, full_identifier):
             )
 
     def start_timer(self, full_identifier):
-        """Start timer for `self.hierarchical_timer`."""
+        """
+        Start timer for `self.hierarchical_timer`.
+
+        Parameters
+        ----------
+        full_identifier : str
+            Full identifier for the timer to be started.
+            Must be an entry of
+            `TimingData.hierarchical_timer_full_ids`.
+        """
         self._validate_full_identifier(full_identifier)
         identifier = full_identifier.split(".")[-1]
         return self._hierarchical_timer.start(identifier=identifier)
 
     def stop_timer(self, full_identifier):
-        """Stop timer for `self.hierarchical_timer`."""
+        """
+        Stop timer for `self.hierarchical_timer`.
+
+        Parameters
+        ----------
+        full_identifier : str
+            Full identifier for the timer to be stopped.
+            Must be an entry of
+            `TimingData.hierarchical_timer_full_ids`.
+        """
         self._validate_full_identifier(full_identifier)
         identifier = full_identifier.split(".")[-1]
         return self._hierarchical_timer.stop(identifier=identifier)
@@ -126,8 +149,17 @@ def stop_timer(self, full_identifier):
     def get_total_time(self, full_identifier):
         """
         Get total time spent with identifier active.
+
+        Parameters
+        ----------
+        full_identifier : str
+            Full identifier for the timer of interest.
+
+        Returns
+        -------
+        float
+            Total time spent with identifier active.
         """
-        self._validate_full_identifier(full_identifier)
         return self._hierarchical_timer.get_total_time(identifier=full_identifier)
 
     def get_main_elapsed_time(self):

From 2ce72647eb59e5b5969c547a7f97f58b4fc84d2f Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 23:08:56 -0400
Subject: [PATCH 65/74] Update total solve time retrieval at termination

---
 pyomo/contrib/pyros/pyros.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 128f59226c8..85e1a470aeb 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -1065,7 +1065,7 @@ def solve(
                 return_soln.iterations = 0
 
         return_soln.config = config
-        return_soln.time = model_data.timing.get_main_elapsed_time()
+        return_soln.time = model_data.timing.get_total_time("main")
 
         # log termination-related messages
         config.progress_logger.info(return_soln.pyros_termination_condition.message)

From a866ad4c72d8fd015484adbc8c196b06e89e620a Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 23:27:15 -0400
Subject: [PATCH 66/74] Ensure bypass global separation message tested

---
 pyomo/contrib/pyros/tests/test_grcs.py | 44 +++++++++++++++++---------
 1 file changed, 29 insertions(+), 15 deletions(-)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index c949af1ed15..af9dbc63255 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5046,28 +5046,42 @@ def test_bypass_global_separation(self):
         global_subsolver = SolverFactory("baron")
 
         # Call the PyROS solver
-        results = pyros_solver.solve(
-            model=m,
-            first_stage_variables=[m.x1],
-            second_stage_variables=[m.x2],
-            uncertain_params=[m.u],
-            uncertainty_set=interval,
-            local_solver=local_subsolver,
-            global_solver=global_subsolver,
-            options={
-                "objective_focus": ObjectiveType.worst_case,
-                "solve_master_globally": True,
-                "decision_rule_order": 0,
-                "bypass_global_separation": True,
-            },
-        )
+        with LoggingIntercept(level=logging.WARNING) as LOG:
+            results = pyros_solver.solve(
+                model=m,
+                first_stage_variables=[m.x1],
+                second_stage_variables=[m.x2],
+                uncertain_params=[m.u],
+                uncertainty_set=interval,
+                local_solver=local_subsolver,
+                global_solver=global_subsolver,
+                options={
+                    "objective_focus": ObjectiveType.worst_case,
+                    "solve_master_globally": True,
+                    "decision_rule_order": 0,
+                    "bypass_global_separation": True,
+                },
+            )
 
+        # check termination robust optimal
         self.assertEqual(
             results.pyros_termination_condition,
             pyrosTerminationCondition.robust_optimal,
             msg="Returned termination condition is not return robust_optimal.",
         )
 
+        # since robust optimal, we also expect warning-level logger
+        # message about bypassing of global separation subproblems
+        warning_msgs = LOG.getvalue()
+        self.assertRegex(
+            warning_msgs,
+            (
+                r".*Option to bypass global separation was chosen\. "
+                r"Robust feasibility and optimality of the reported "
+                r"solution are not guaranteed\."
+            ),
+        )
+
 
 @unittest.skipUnless(
     baron_available and baron_license_is_valid,

From 40e1b6db183f6b3f71ce21c990e2680fda9eeef2 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 23:34:28 -0400
Subject: [PATCH 67/74] Add another `IterationLogRecord` test

---
 pyomo/contrib/pyros/tests/test_grcs.py | 38 ++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index af9dbc63255..b661f18752c 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -5892,6 +5892,44 @@ def test_log_iter_record_all_special(self):
             msg="Iteration log record message does not match expected result",
         )
 
+    def test_log_iter_record_attrs_none(self):
+        """
+        Test logging of iteration record in event some
+        attributes are of value `None`. In this case, a '-'
+        should be printed in lieu of a numerical value.
+        Example where this occurs: the first iteration,
+        in which there is no first-stage shift or DR shift.
+        """
+        # for some fields, we choose floats with more than four
+        # four decimal points to ensure rounding also matches
+        iter_record = IterationLogRecord(
+            iteration=0,
+            objective=-1.234567,
+            first_stage_var_shift=None,
+            dr_var_shift=None,
+            num_violated_cons=10,
+            max_violation=7.654321e-3,
+            elapsed_time=21.2,
+            dr_polishing_success=True,
+            all_sep_problems_solved=False,
+            global_separation=True,
+        )
+
+        # now check record logged as expected
+        ans = (
+            "0    -1.2346e+00  -            -            10+     7.6543e-03g  "
+            "21.200       \n"
+        )
+        with LoggingIntercept(level=logging.INFO) as LOG:
+            iter_record.log(logger.info)
+        result = LOG.getvalue()
+
+        self.assertEqual(
+            ans,
+            result,
+            msg="Iteration log record message does not match expected result",
+        )
+
 
 class TestROSolveResults(unittest.TestCase):
     """

From 936182af22b57bb8f4304ff580c69b9fe9d336c6 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Sun, 1 Oct 2023 23:51:26 -0400
Subject: [PATCH 68/74] Update example solver log in online docs

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 485c253e5ce..81fbeae7f1c 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -856,7 +856,7 @@ Observe that the log contains the following information:
    ==============================================================================
    PyROS: The Pyomo Robust Optimization Solver.
           Version 1.2.7 | Git branch: unknown, commit hash: unknown
-          Invoked at UTC 2023-09-09T18:13:21.893626
+          Invoked at UTC 2023-10-02T03:42:54.264507
 
    Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),
                  John D. Siirola (2), Chrysanthos E. Gounaris (1)
@@ -883,7 +883,7 @@ Observe that the log contains the following information:
     max_iter=-1
     robust_feasibility_tolerance=0.0001
     separation_priority_order={}
-    progress_logger=<Logger pyomo.contrib.pyros (INFO)>
+    progress_logger=<PreformattedLogger pyomo.contrib.pyros (INFO)>
     backup_local_solvers=[]
     backup_global_solvers=[]
     subproblem_file_directory=None

From 94efcb16d18d1ae98e875445f5101455ffa3f825 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 2 Oct 2023 17:59:52 -0400
Subject: [PATCH 69/74] Add warning-level DR polishing failure log message

---
 pyomo/contrib/pyros/master_problem_methods.py | 8 ++++++++
 pyomo/contrib/pyros/tests/test_grcs.py        | 1 +
 2 files changed, 9 insertions(+)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index 572e0b790a8..c0f6093b3a1 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -543,6 +543,14 @@ def minimize_dr_vars(model_data, config):
     acceptable = {tc.globallyOptimal, tc.optimal, tc.locallyOptimal, tc.feasible}
     if results.solver.termination_condition not in acceptable:
         # continue with "unpolished" master model solution
+        config.progress_logger.warning(
+            "Could not successfully solve DR polishing problem "
+            f"of iteration {model_data.iteration} with primary subordinate "
+            f"{'global' if config.solve_master_globally else 'local'} solver "
+            "to acceptable level. "
+            f"Termination stats:\n{results.solver}\n"
+            "Maintaining unpolished master problem solution."
+        )
         return results, False
 
     # update master model second-stage, state, and decision rule
diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index b661f18752c..a76e531d666 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -3902,6 +3902,7 @@ def test_minimize_dr_norm(self):
         master_data.master_model = master
         master_data.master_model.const_efficiency_applied = False
         master_data.master_model.linear_efficiency_applied = False
+        master_data.iteration = 0
 
         master_data.timing = TimingData()
         with time_code(master_data.timing, "main", is_main_timer=True):

From 0c3f069cb400bc0a40ce5fe3013c30e35bfb8881 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Mon, 2 Oct 2023 19:09:40 -0400
Subject: [PATCH 70/74] Tweak master feasibility failure message

---
 pyomo/contrib/pyros/master_problem_methods.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py
index c0f6093b3a1..dc4b6b957bb 100644
--- a/pyomo/contrib/pyros/master_problem_methods.py
+++ b/pyomo/contrib/pyros/master_problem_methods.py
@@ -293,10 +293,10 @@ def solve_master_feasibility_problem(model_data, config):
     else:
         config.progress_logger.warning(
             "Could not successfully solve master feasibility problem "
-            f" of iteration {model_data.iteration} with primary subordinate "
+            f"of iteration {model_data.iteration} with primary subordinate "
             f"{'global' if config.solve_master_globally else 'local'} solver "
             "to acceptable level. "
-            f"Termination stats:\n{results.solver}"
+            f"Termination stats:\n{results.solver}\n"
             "Maintaining unoptimized point for master problem initialization."
         )
 

From 0fdd4dc6e64b5c58fac1d59f8b4634e6f7f97a6c Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 12 Oct 2023 11:35:01 -0400
Subject: [PATCH 71/74] Update version number, changelog

---
 pyomo/contrib/pyros/CHANGELOG.txt | 12 ++++++++++++
 pyomo/contrib/pyros/pyros.py      |  2 +-
 2 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/CHANGELOG.txt b/pyomo/contrib/pyros/CHANGELOG.txt
index b1866ed955c..7977c37fb95 100644
--- a/pyomo/contrib/pyros/CHANGELOG.txt
+++ b/pyomo/contrib/pyros/CHANGELOG.txt
@@ -2,6 +2,18 @@
 PyROS CHANGELOG
 ===============
 
+-------------------------------------------------------------------------------
+PyROS 1.2.8    12 Oct 2023
+-------------------------------------------------------------------------------
+- Refactor PyROS separation routine, fix scenario selection heuristic
+- Add efficiency for discrete uncertainty set separation
+- Fix coefficient matching routine
+- Fix subproblem timers and time accumulators
+- Update and document PyROS solver logging system
+- Fix iteration overcounting in event of `max_iter` termination status
+- Fixes to (assembly of) PyROS `ROSolveResults` object
+
+
 -------------------------------------------------------------------------------
 PyROS 1.2.7    26 Apr 2023
 -------------------------------------------------------------------------------
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index 85e1a470aeb..e48690da5d6 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -49,7 +49,7 @@
 from datetime import datetime
 
 
-__version__ = "1.2.7"
+__version__ = "1.2.8"
 
 
 default_pyros_solver_logger = setup_pyros_logger()

From 7d86a3410d5bd0d7f177072591b0d1c6abd24b7d Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Thu, 12 Oct 2023 11:40:48 -0400
Subject: [PATCH 72/74] Update solver log docs

---
 doc/OnlineDocs/contributed_packages/pyros.rst | 48 +++++++++----------
 1 file changed, 24 insertions(+), 24 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 81fbeae7f1c..0bf8fa93be6 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -855,8 +855,8 @@ Observe that the log contains the following information:
 
    ==============================================================================
    PyROS: The Pyomo Robust Optimization Solver.
-          Version 1.2.7 | Git branch: unknown, commit hash: unknown
-          Invoked at UTC 2023-10-02T03:42:54.264507
+          Version 1.2.8 | Git branch: unknown, commit hash: unknown
+          Invoked at UTC 2023-10-12T15:36:19.035916
 
    Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),
                  John D. Siirola (2), Chrysanthos E. Gounaris (1)
@@ -892,7 +892,7 @@ Observe that the log contains the following information:
     p_robustness={}
    ------------------------------------------------------------------------------
    Preprocessing...
-   Done preprocessing; required wall time of 0.232s.
+   Done preprocessing; required wall time of 0.175s.
    ------------------------------------------------------------------------------
    Model statistics:
      Number of variables : 62
@@ -911,16 +911,16 @@ Observe that the log contains the following information:
          First-stage inequalities (incl. certain var bounds) : 10
          Performance constraints (incl. var bounds) : 47
    ------------------------------------------------------------------------------
-   Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol     Wall Time (s) 
+   Itn  Objective    1-Stg Shift  DR Shift     #CViol  Max Viol     Wall Time (s)
    ------------------------------------------------------------------------------
-   0     3.5838e+07  -            -            5       1.8832e+04   1.212         
-   1     3.5838e+07  7.4506e-09   1.6105e+03   7       3.7766e+04   2.712         
-   2     3.6116e+07  2.7803e+05   1.2918e+03   8       1.3466e+06   4.548         
-   3     3.6285e+07  1.6957e+05   5.8386e+03   6       4.8734e+03   6.542         
-   4     3.6285e+07  1.4901e-08   3.3097e+03   1       3.5036e+01   8.916         
-   5     3.6285e+07  2.9786e-10   3.3597e+03   6       2.9103e+00   11.204        
-   6     3.6285e+07  7.4506e-07   8.7228e+02   5       4.1726e-01   13.546        
-   7     3.6285e+07  7.4506e-07   8.1995e+02   0       9.3279e-10g  20.666        
+   0     3.5838e+07  -            -            5       1.8832e+04   1.198        
+   1     3.5838e+07  7.4506e-09   1.6105e+03   7       3.7766e+04   2.893        
+   2     3.6116e+07  2.7803e+05   1.2918e+03   8       1.3466e+06   4.732        
+   3     3.6285e+07  1.6957e+05   5.8386e+03   6       4.8734e+03   6.740        
+   4     3.6285e+07  1.4901e-08   3.3097e+03   1       3.5036e+01   9.099        
+   5     3.6285e+07  2.9786e-10   3.3597e+03   6       2.9103e+00   11.588       
+   6     3.6285e+07  7.4506e-07   8.7228e+02   5       4.1726e-01   14.360       
+   7     3.6285e+07  7.4506e-07   8.1995e+02   0       9.3279e-10g  21.597       
    ------------------------------------------------------------------------------
    Robust optimal solution identified.
    ------------------------------------------------------------------------------
@@ -928,24 +928,24 @@ Observe that the log contains the following information:
 
    Identifier                ncalls   cumtime   percall      %
    -----------------------------------------------------------
-   main                           1    20.668    20.668  100.0
+   main                           1    21.598    21.598  100.0
         ------------------------------------------------------
-        dr_polishing              7     1.459     0.208    7.1
-        global_separation        47     1.281     0.027    6.2
-        local_separation        376     9.105     0.024   44.1
-        master                    8     5.356     0.669   25.9
-        master_feasibility        7     0.456     0.065    2.2
-        preprocessing             1     0.232     0.232    1.1
-        other                   n/a     2.779       n/a   13.4
+        dr_polishing              7     1.502     0.215    7.0
+        global_separation        47     1.300     0.028    6.0
+        local_separation        376     9.779     0.026   45.3
+        master                    8     5.385     0.673   24.9
+        master_feasibility        7     0.531     0.076    2.5
+        preprocessing             1     0.175     0.175    0.8
+        other                   n/a     2.926       n/a   13.5
         ======================================================
    ===========================================================
 
    ------------------------------------------------------------------------------
    Termination stats:
-    Iterations             : 8
-    Solve time (wall s)    : 20.668
-    Final objective value  : 3.6285e+07
-    Termination condition  : pyrosTerminationCondition.robust_optimal
+    Iterations            : 8
+    Solve time (wall s)   : 21.598
+    Final objective value : 3.6285e+07
+    Termination condition : pyrosTerminationCondition.robust_optimal
    ------------------------------------------------------------------------------
    All done. Exiting PyROS.
    ==============================================================================

From 6cf7e68a50016850426f7d1ce477c9a3fcf63807 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 3 Nov 2023 00:44:01 -0400
Subject: [PATCH 73/74] Update version info retrieval logic

---
 doc/OnlineDocs/contributed_packages/pyros.rst |  9 +--
 pyomo/contrib/pyros/pyros.py                  | 56 ++++++++++---------
 pyomo/contrib/pyros/tests/test_grcs.py        |  4 +-
 3 files changed, 38 insertions(+), 31 deletions(-)

diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst
index 0bf8fa93be6..23ec60f2e20 100644
--- a/doc/OnlineDocs/contributed_packages/pyros.rst
+++ b/doc/OnlineDocs/contributed_packages/pyros.rst
@@ -632,7 +632,7 @@ In this example, we select affine decision rules by setting
   ...     decision_rule_order=1,
   ... )
   ==============================================================================
-  PyROS: The Pyomo Robust Optimization Solver.
+  PyROS: The Pyomo Robust Optimization Solver...
   ...
   ------------------------------------------------------------------------------
   Robust optimal solution identified.
@@ -854,9 +854,10 @@ Observe that the log contains the following information:
    :linenos:
 
    ==============================================================================
-   PyROS: The Pyomo Robust Optimization Solver.
-          Version 1.2.8 | Git branch: unknown, commit hash: unknown
-          Invoked at UTC 2023-10-12T15:36:19.035916
+   PyROS: The Pyomo Robust Optimization Solver, v1.2.8.
+          Pyomo version: 6.7.0
+          Commit hash: unknown
+          Invoked at UTC 2023-11-03T04:27:42.954101
 
    Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),
                  John D. Siirola (2), Chrysanthos E. Gounaris (1)
diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py
index e48690da5d6..5b37b114722 100644
--- a/pyomo/contrib/pyros/pyros.py
+++ b/pyomo/contrib/pyros/pyros.py
@@ -55,29 +55,34 @@
 default_pyros_solver_logger = setup_pyros_logger()
 
 
-def _get_pyomo_git_info():
+def _get_pyomo_version_info():
     """
-    Get Pyomo git commit hash.
+    Get Pyomo version information.
     """
     import os
     import subprocess
+    from pyomo.version import version
 
-    pyros_dir = os.path.join(*os.path.split(__file__)[:-1])
-
-    git_info_dict = {}
-    commands_dict = {
-        "branch": ["git", "-C", f"{pyros_dir}", "rev-parse", "--abbrev-ref", "HEAD"],
-        "commit hash": ["git", "-C", f"{pyros_dir}", "rev-parse", "--short", "HEAD"],
-    }
-    for field, command in commands_dict.items():
-        try:
-            field_val = subprocess.check_output(command).decode("ascii").strip()
-        except subprocess.CalledProcessError:
-            field_val = "unknown"
+    pyomo_version = version
+    commit_hash = "unknown"
 
-        git_info_dict[field] = field_val
+    pyros_dir = os.path.join(*os.path.split(__file__)[:-1])
+    commit_hash_command_args = [
+        "git",
+        "-C",
+        f"{pyros_dir}",
+        "rev-parse",
+        "--short",
+        "HEAD",
+    ]
+    try:
+        commit_hash = (
+            subprocess.check_output(commit_hash_command_args).decode("ascii").strip()
+        )
+    except subprocess.CalledProcessError:
+        commit_hash = "unknown"
 
-    return git_info_dict
+    return {"Pyomo version": pyomo_version, "Commit hash": commit_hash}
 
 
 def NonNegIntOrMinusOne(obj):
@@ -712,18 +717,19 @@ def _log_intro(self, logger, **log_kwargs):
             Should not include `msg`.
         """
         logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs)
-        logger.log(msg="PyROS: The Pyomo Robust Optimization Solver.", **log_kwargs)
-
-        git_info_str = ", ".join(
-            f"{field}: {val}" for field, val in _get_pyomo_git_info().items()
-        )
         logger.log(
-            msg=(
-                f"{' ' * len('PyROS:')} Version {self.version()} | "
-                f"Git {git_info_str}"
-            ),
+            msg=f"PyROS: The Pyomo Robust Optimization Solver, v{self.version()}.",
             **log_kwargs,
         )
+
+        # git_info_str = ", ".join(
+        #     f"{field}: {val}" for field, val in _get_pyomo_git_info().items()
+        # )
+        version_info = _get_pyomo_version_info()
+        version_info_str = ' ' * len("PyROS: ") + ("\n" + ' ' * len("PyROS: ")).join(
+            f"{key}: {val}" for key, val in version_info.items()
+        )
+        logger.log(msg=version_info_str, **log_kwargs)
         logger.log(
             msg=(
                 f"{' ' * len('PyROS:')} "
diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py
index a76e531d666..2be73826f61 100644
--- a/pyomo/contrib/pyros/tests/test_grcs.py
+++ b/pyomo/contrib/pyros/tests/test_grcs.py
@@ -6058,7 +6058,7 @@ def test_log_intro(self):
         # check number of lines is as expected
         self.assertEqual(
             len(intro_msg_lines),
-            13,
+            14,
             msg=(
                 "PyROS solver introductory message does not contain"
                 "the expected number of lines."
@@ -6072,7 +6072,7 @@ def test_log_intro(self):
         # check regex main text
         self.assertRegex(
             " ".join(intro_msg_lines[1:-1]),
-            r"PyROS: The Pyomo Robust Optimization Solver\..* \(IDAES\)\.",
+            r"PyROS: The Pyomo Robust Optimization Solver, v.* \(IDAES\)\.",
         )
 
     def test_log_disclaimer(self):

From 3e9f156d4e896e9e8be736a33cabecb9147ee191 Mon Sep 17 00:00:00 2001
From: jasherma <jasherma@andrew.cmu.edu>
Date: Fri, 3 Nov 2023 00:46:58 -0400
Subject: [PATCH 74/74] Fix coefficient matching failure message grammar

---
 pyomo/contrib/pyros/pyros_algorithm_methods.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py
index 5b234b150c8..df0d539a70d 100644
--- a/pyomo/contrib/pyros/pyros_algorithm_methods.py
+++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py
@@ -222,7 +222,7 @@ def ROSolver_iterative_solve(model_data, config):
             config.progress_logger.error(
                 f"Equality constraint {c.name!r} cannot be guaranteed to "
                 "be robustly feasible, given the current partitioning "
-                "between first-stage, second-stage, and state variables. "
+                "among first-stage, second-stage, and state variables. "
                 "Consider editing this constraint to reference some "
                 "second-stage and/or state variable(s)."
             )