Merge pull request #3475 from shermanjasonaf/fix-docs-and-logging

Fix/Tweak PyROS Documentation and Solver Output Logging

doc/OnlineDocs/explanation/solvers/pyros.rst

@@ -66,10 +66,8 @@ where:
     PyROS accepts models in which there are:
 
     1. Bounds declared on the ``Var`` objects representing
-       components of the variable vectors :math:`z` and :math:`y`.
-       These bounds are reformulated to inequality constraints.
-    2. Ranged inequality constraints. These are easily reformulated to
-       single inequality constraints.
+       components of the variable vectors
+    2. Ranged inequality constraints
 
 In order to cast the robust optimization counterpart of the
 :ref:`deterministic model <deterministic-model>`,
@@ -186,9 +184,9 @@ The PyROS solver is invoked through the
     Upon successful convergence of PyROS, the solution returned is
     certified to be robust optimal only if:
 
-    1. master problems are solved to global optimality
+    1. Master problems are solved to global optimality
        (by specifying ``solve_master_globally=True``)
-    2. a worst-case objective focus is chosen
+    2. A worst-case objective focus is chosen
        (by specifying ``objective_focus=ObjectiveType.worst_case``)
 
     Otherwise, the solution returned is certified to only be robust feasible.
@@ -998,7 +996,7 @@ Observe that the log contains the following information:
     p_robustness={}
    ------------------------------------------------------------------------------
    Preprocessing...
-   Done preprocessing; required wall time of 0.018s.
+   Done preprocessing; required wall time of 0.009s.
    ------------------------------------------------------------------------------
    Model Statistics:
      Number of variables : 62
@@ -1020,34 +1018,33 @@ Observe that the log contains the following information:
    ------------------------------------------------------------------------------
    Itn  Objective    1-Stg Shift  2-Stg Shift  #CViol  Max Viol     Wall Time (s)
    ------------------------------------------------------------------------------
-   0     3.5838e+07  -            -            1       2.7000e+02   0.657
-   1     3.6087e+07  8.0199e-01   1.2807e-01   5       4.1852e+04   1.460
-   2     3.6125e+07  8.7068e-01   2.7098e-01   8       2.7711e+01   3.041
-   3     3.6174e+07  7.6526e-01   2.2357e-01   4       1.3893e+02   4.186
-   4     3.6285e+07  2.8923e-01   3.4064e-01   0       1.2670e-09g  7.162
+   0     3.5838e+07  -            -            5       1.8832e+04   0.412
+   1     3.5838e+07  1.2289e-09   1.5886e-12   5       2.8919e+02   0.992
+   2     3.6269e+07  3.1647e-01   1.0432e-01   4       2.9020e+02   1.865
+   3     3.6285e+07  7.6526e-01   2.2258e-01   0       2.3874e-12g  3.508
    ------------------------------------------------------------------------------
    Robust optimal solution identified.
    ------------------------------------------------------------------------------
    Timing breakdown:
    
    Identifier                ncalls   cumtime   percall      %
    -----------------------------------------------------------
-   main                           1     7.163     7.163  100.0
+   main                           1     3.509     3.509  100.0
         ------------------------------------------------------
-        dr_polishing              4     0.293     0.073    4.1
-        global_separation        27     1.106     0.041   15.4
-        local_separation        135     3.385     0.025   47.3
-        master                    5     1.396     0.279   19.5
-        master_feasibility        4     0.155     0.039    2.2
-        preprocessing             1     0.018     0.018    0.2
-        other                   n/a     0.811       n/a   11.3
+        dr_polishing              3     0.209     0.070    6.0
+        global_separation        27     0.590     0.022   16.8
+        local_separation        108     1.569     0.015   44.7
+        master                    4     0.654     0.163   18.6
+        master_feasibility        3     0.083     0.028    2.4
+        preprocessing             1     0.009     0.009    0.3
+        other                   n/a     0.394       n/a   11.2
         ======================================================
    ===========================================================
    
    ------------------------------------------------------------------------------
    Termination stats:
-    Iterations            : 5
-    Solve time (wall s)   : 7.163
+    Iterations            : 4
+    Solve time (wall s)   : 3.509
     Final objective value : 3.6285e+07
     Termination condition : pyrosTerminationCondition.robust_optimal
    ------------------------------------------------------------------------------

pyomo/contrib/pyros/CHANGELOG.txt

@@ -3,6 +3,19 @@ PyROS CHANGELOG
 ===============
 
 
+-------------------------------------------------------------------------------
+PyROS 1.3.5    13 Feb 2025
+-------------------------------------------------------------------------------
+- Tweak online documentation, including solver logging output example
+- Adjust UTC invocation time retrieval in PyROS logging to
+  deprecation of `datetime.datetime.now()` in Python 3.12
+- Suppress error message emitted to console when PyROS
+  attempts to retrieve git commit hash of Pyomo installation that
+  is not a git repository
+- Add more information to solver output logging message emitted upon
+  failure to solve deterministic (i.e., initial master) problem
+
+
 -------------------------------------------------------------------------------
 PyROS 1.3.4    22 Jan 2025
 -------------------------------------------------------------------------------

pyomo/contrib/pyros/master_problem_methods.py

@@ -845,7 +845,9 @@ def solver_call_master(master_data):
     )
     deterministic_msg = (
         (
-            " Please ensure your deterministic model "
+            " Please ensure that your deterministic model, "
+            "subject to the nominal uncertain parameter realization "
+            "you have provided, "
             f"is solvable by at least one of the subordinate {solve_mode} "
             "optimizers provided."
         )

pyomo/contrib/pyros/pyros.py

@@ -10,7 +10,7 @@
 #  ___________________________________________________________________________
 
 # pyros.py: Generalized Robust Cutting-Set Algorithm for Pyomo
-from datetime import datetime
+from datetime import datetime, timezone
 import logging
 
 from pyomo.common.config import document_kwargs_from_configdict
@@ -33,7 +33,7 @@
 )
 
 
-__version__ = "1.3.4"
+__version__ = "1.3.5"
 
 
 default_pyros_solver_logger = setup_pyros_logger()
@@ -61,7 +61,14 @@ def _get_pyomo_version_info():
     ]
     try:
         commit_hash = (
-            subprocess.check_output(commit_hash_command_args).decode("ascii").strip()
+            subprocess.check_output(
+                commit_hash_command_args,
+                # suppress git error if Pyomo installation
+                # is not a git repo
+                stderr=subprocess.DEVNULL,
+            )
+            .decode("ascii")
+            .strip()
         )
     except subprocess.CalledProcessError:
         commit_hash = "unknown"
@@ -133,7 +140,8 @@ def _log_intro(self, logger, **log_kwargs):
         logger.log(
             msg=(
                 f"{' ' * len('PyROS:')} "
-                f"Invoked at UTC {datetime.utcnow().isoformat()}"
+                "Invoked at UTC "
+                f"{datetime.now(timezone.utc).isoformat()}"
             ),
             **log_kwargs,
         )

pyomo/contrib/pyros/tests/test_grcs.py

@@ -19,9 +19,10 @@
 
 from parameterized import parameterized
 import pyomo.common.unittest as unittest
-from pyomo.common.log import LoggingIntercept
 from pyomo.common.collections import Bunch
 from pyomo.common.errors import InvalidValueError
+from pyomo.common.log import LoggingIntercept
+from pyomo.common.tee import capture_output
 from pyomo.core.base.set_types import NonNegativeIntegers
 from pyomo.repn.plugins import nl_writer as pyomo_nl_writer
 import pyomo.repn.ampl as pyomo_ampl_repn
@@ -2740,8 +2741,13 @@ 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)
+        with capture_output(capture_fd=True) as OUT:
+            with LoggingIntercept(level=logging.INFO) as LOG:
+                pyros_solver._log_intro(logger=logger, level=logging.INFO)
+
+        # ensure git repo commit check error messages suppressed
+        err_msgs = OUT.getvalue()
+        self.assertEqual(err_msgs, "")
 
         intro_msgs = LOG.getvalue()