diff --git a/pyomo/contrib/solver/solvers/ipopt.py b/pyomo/contrib/solver/solvers/ipopt.py index a7ed5435aa7..7c73e07af38 100644 --- a/pyomo/contrib/solver/solvers/ipopt.py +++ b/pyomo/contrib/solver/solvers/ipopt.py @@ -62,7 +62,7 @@ # Acceptable chars for the end of the alpha_pr column # in ipopt's output, per https://coin-or.github.io/Ipopt/OUTPUT.html -_ALPHA_PR_CHARS = set("fFhHkKnNRwstTr") +_ALPHA_PR_CHARS = set("fFhHkKnNRwSstTr") class IpoptConfig(SolverConfig): @@ -115,6 +115,9 @@ def get_reduced_costs( self, vars_to_load: Optional[Sequence[VarData]] = None ) -> Mapping[VarData, float]: self._error_check() + # If the NL instance has no objectives, report zeros + if not len(self._nl_info.objectives): + return ComponentMap() if self._nl_info.scaling is None: scale_list = [1] * len(self._nl_info.variables) obj_scale = 1 @@ -294,7 +297,7 @@ def has_linear_solver(self, linear_solver: str) -> bool: def _verify_ipopt_options(self, config: IpoptConfig) -> None: for key, msg in unallowed_ipopt_options.items(): if key in config.solver_options: - raise ValueError(f"unallowed ipopt option '{key}': {msg}") + raise ValueError(f"unallowed Ipopt option '{key}': {msg}") # Map standard Pyomo solver options to Ipopt options: standard # options override ipopt-specific options. if config.time_limit is not None: @@ -505,12 +508,10 @@ def solve(self, model, **kwds) -> Results: for k, v in cpu_seconds.items(): results.timing_info[k] = v results.extra_info = parsed_output_data - # Set iteration_log visibility to ADVANCED_OPTION because it's - # a lot to print out with `display` - results.extra_info.get("iteration_log")._visibility = ( - ADVANCED_OPTION - ) - except KeyError as e: + iter_log = results.extra_info.get("iteration_log", None) + if iter_log is not None: + iter_log._visibility = ADVANCED_OPTION + except Exception as e: logger.log( logging.WARNING, "The solver output data is empty or incomplete.\n" @@ -610,42 +611,70 @@ def _parse_ipopt_output(self, output: Union[str, io.StringIO]) -> Dict[str, Any] "ls", ] iterations = [] + n_expected_columns = len(columns) for line in iter_table: tokens = line.strip().split() - if len(tokens) != len(columns): - continue + # IPOPT sometimes mashes the first two column values together + # (e.g., "2r-4.93e-03"). We need to split them. + try: + idx = tokens[0].index('-') + head = tokens[0][:idx] + if head and head.rstrip('r').isdigit(): + tokens[:1] = (head, tokens[0][idx:]) + except ValueError: + pass + iter_data = dict(zip(columns, tokens)) + extra_tokens = tokens[n_expected_columns:] # Extract restoration flag from 'iter' - iter_data['restoration'] = iter_data['iter'].endswith('r') - if iter_data['restoration']: - iter_data['iter'] = iter_data['iter'][:-1] + iter_num = iter_data.pop("iter") + restoration = iter_num.endswith("r") + if restoration: + iter_num = iter_num[:-1] + + try: + iter_num = int(iter_num) + except ValueError: + logger.warning( + f"Could not parse Ipopt iteration number: {iter_num}" + ) + + iter_data["restoration"] = restoration + iter_data["iter"] = iter_num - # Separate alpha_pr into numeric part and optional tag - iter_data['step_acceptance'] = iter_data['alpha_pr'][-1] - if iter_data['step_acceptance'] in _ALPHA_PR_CHARS: + # Separate alpha_pr into numeric part and optional tag (f, D, R, etc.) + step_acceptance_tag = iter_data['alpha_pr'][-1] + if step_acceptance_tag in _ALPHA_PR_CHARS: + iter_data['step_acceptance'] = step_acceptance_tag iter_data['alpha_pr'] = iter_data['alpha_pr'][:-1] else: iter_data['step_acceptance'] = None + # Capture optional IPOPT diagnostic tags if present + if extra_tokens: + iter_data['diagnostic_tags'] = " ".join(extra_tokens) + # Attempt to cast all values to float where possible - for key in columns: - if iter_data[key] == '-': + for key in columns[1:]: + val = iter_data[key] + if val == '-': iter_data[key] = None else: try: - iter_data[key] = float(iter_data[key]) + iter_data[key] = float(val) except (ValueError, TypeError): logger.warning( "Error converting Ipopt log entry to " f"float:\n\t{sys.exc_info()[1]}\n\t{line}" ) - assert len(iterations) == iter_data.pop('iter'), ( - f"Parsed row in the iterations table\n\t{line}\ndoes not " - f"match the next expected iteration number ({len(iterations)})" - ) + if len(iterations) != iter_num: + logger.warning( + f"Total number of iterations parsed {len(iterations)} " + f"does not match the expected iteration number ({iter_num})." + ) iterations.append(iter_data) parsed_data['iteration_log'] = iterations @@ -674,7 +703,6 @@ def _parse_ipopt_output(self, output: Union[str, io.StringIO]) -> Dict[str, Any] "complementarity_error", "overall_nlp_error", ] - # Filter out None values and create final fields and values. # Nones occur in old-style IPOPT output (<= 3.13) zipped = [ @@ -684,10 +712,8 @@ def _parse_ipopt_output(self, output: Union[str, io.StringIO]) -> Dict[str, Any] ) if scaled is not None and unscaled is not None ] - scaled = {k: float(s) for k, s, _ in zipped} unscaled = {k: float(u) for k, _, u in zipped} - parsed_data.update(unscaled) parsed_data['final_scaled_results'] = scaled diff --git a/pyomo/contrib/solver/solvers/sol_reader.py b/pyomo/contrib/solver/solvers/sol_reader.py index e580e2a72f9..7d2f613eb6a 100644 --- a/pyomo/contrib/solver/solvers/sol_reader.py +++ b/pyomo/contrib/solver/solvers/sol_reader.py @@ -122,6 +122,12 @@ def get_duals( 'Solution loader does not currently have a valid solution. Please ' 'check results.termination_condition and/or results.solution_status.' ) + # If the NL instance has no objectives, report zeros + if not self._nl_info.objectives: + cons = ( + cons_to_load if cons_to_load is not None else self._nl_info.constraints + ) + return {c: 0.0 for c in cons} if len(self._nl_info.eliminated_vars) > 0: raise NotImplementedError( 'For now, turn presolve off (opt.config.writer_config.linear_presolve=False) ' @@ -133,21 +139,20 @@ def get_duals( "have happened. Report this error to the Pyomo Developers." ) res = {} - if self._nl_info.scaling is None: - scale_list = [1] * len(self._nl_info.constraints) - obj_scale = 1 - else: - scale_list = self._nl_info.scaling.constraints + scaling = self._nl_info.scaling + if scaling: + _iter = zip( + self._nl_info.constraints, self._sol_data.duals, scaling.constraints + ) obj_scale = self._nl_info.scaling.objectives[0] - if cons_to_load is None: - cons_to_load = set(self._nl_info.constraints) else: - cons_to_load = set(cons_to_load) - for con, val, scale in zip( - self._nl_info.constraints, self._sol_data.duals, scale_list - ): - if con in cons_to_load: - res[con] = val * scale / obj_scale + _iter = zip(self._nl_info.constraints, self._sol_data.duals) + if cons_to_load is not None: + _iter = filter(lambda x: x[0] in cons_to_load, _iter) + if scaling: + res = {con: val * scale / obj_scale for con, val, scale in _iter} + else: + res = {con: val for con, val in _iter} return res diff --git a/pyomo/contrib/solver/tests/solvers/test_ipopt.py b/pyomo/contrib/solver/tests/solvers/test_ipopt.py index 06553da1bf0..f88b18300f4 100644 --- a/pyomo/contrib/solver/tests/solvers/test_ipopt.py +++ b/pyomo/contrib/solver/tests/solvers/test_ipopt.py @@ -9,8 +9,9 @@ # This software is distributed under the 3-clause BSD License. # ___________________________________________________________________________ -import os +import os, sys import subprocess +from contextlib import contextmanager import pyomo.environ as pyo from pyomo.common.envvar import is_windows @@ -29,6 +30,23 @@ ipopt_available = ipopt.Ipopt().available() +@contextmanager +def windows_tee_buffer(size=1 << 20): + """Temporarily increase TeeStream buffer size on Windows""" + if not sys.platform.startswith("win"): + # Only windows has an issue + yield + return + import pyomo.common.tee as tee + + old = tee._pipe_buffersize + tee._pipe_buffersize = size + try: + yield + finally: + tee._pipe_buffersize = old + + @unittest.skipIf(not ipopt_available, "The 'ipopt' command is not available") class TestIpoptSolverConfig(unittest.TestCase): def test_default_instantiation(self): @@ -321,6 +339,99 @@ def test_empty_output_parsing(self): logs.output[0], ) + def test_parse_output_diagnostic_tags(self): + output = """****************************************************************************** +This program contains Ipopt, a library for large-scale nonlinear optimization. + Ipopt is released as open source code under the Eclipse Public License (EPL). + For more information visit http://projects.coin-or.org/Ipopt + +This version of Ipopt was compiled from source code available at + https://github.com/IDAES/Ipopt as part of the Institute for the Design of + Advanced Energy Systems Process Systems Engineering Framework (IDAES PSE + Framework) Copyright (c) 2018-2019. See https://github.com/IDAES/idaes-pse. + +This version of Ipopt was compiled using HSL, a collection of Fortran codes + for large-scale scientific computation. All technical papers, sales and + publicity material resulting from use of the HSL codes within IPOPT must + contain the following acknowledgement: + HSL, a collection of Fortran codes for large-scale scientific + computation. See http://www.hsl.rl.ac.uk/. +****************************************************************************** + +This is Ipopt version 3.13.2, running with linear solver ma57. + +Number of nonzeros in equality constraint Jacobian...: 77541 +Number of nonzeros in inequality constraint Jacobian.: 0 +Number of nonzeros in Lagrangian Hessian.............: 51855 + +Total number of variables............................: 15468 + variables with only lower bounds: 3491 + variables with lower and upper bounds: 5026 + variables with only upper bounds: 186 +Total number of equality constraints.................: 15417 +Total number of inequality constraints...............: 0 + inequality constraints with only lower bounds: 0 + inequality constraints with lower and upper bounds: 0 + inequality constraints with only upper bounds: 0 + +iter objective inf_pr inf_du lg(mu) ||d|| lg(rg) alpha_du alpha_pr ls + 0 4.3126674e+00 1.34e+00 1.00e+00 -5.0 0.00e+00 - 0.00e+00 0.00e+00 0 +Reallocating memory for MA57: lfact (2247250) + 1r 4.3126674e+00 1.34e+00 9.99e+02 0.1 0.00e+00 -4.0 0.00e+00 3.29e-10R 2 + 2r 3.0519246e+08 1.13e+00 9.90e+02 0.1 2.30e+02 - 2.60e-02 9.32e-03f 1 + 3r 2.2712595e+09 1.69e+00 9.73e+02 0.1 2.23e+02 - 2.54e-02 1.71e-02f 1 Nhj + 4 2.2712065e+09 1.69e+00 1.37e+09 -5.0 3.08e+03 - 1.32e-05 1.17e-05f 1 q + 5 1.9062986e+09 1.55e+00 1.25e+09 -5.0 5.13e+03 - 1.19e-01 8.38e-02f 1 + 6 1.7041594e+09 1.46e+00 1.18e+09 -5.0 5.66e+03 - 7.06e-02 5.45e-02f 1 + 7 1.4763158e+09 1.36e+00 1.10e+09 -5.0 3.94e+03 - 2.30e-01 6.92e-02f 1 + 8 8.5873108e+08 1.04e+00 8.41e+08 -5.0 2.38e+05 - 3.49e-06 2.37e-01f 1 + 9 4.4215572e+08 7.45e-01 6.03e+08 -5.0 1.63e+06 - 7.97e-02 2.82e-01f 1 +iter objective inf_pr inf_du lg(mu) ||d|| lg(rg) alpha_du alpha_pr ls + 10 5.0251884e+01 1.65e-01 1.57e+04 -5.0 1.24e+06 - 3.92e-05 1.00e+00f 1 + 11 4.9121733e+01 4.97e-02 4.68e+03 -5.0 8.11e+04 - 4.31e-02 7.01e-01h 1 + 12 4.1483985e+01 2.24e-02 5.97e+03 -5.0 1.15e+06 - 5.93e-02 1.00e+00f 1 + 13 3.5762585e+01 1.75e-02 5.00e+03 -5.0 1.03e+06 - 1.25e-01 1.00e+00f 1 + 14 3.2291014e+01 1.08e-02 3.51e+03 -5.0 8.25e+05 - 6.68e-01 1.00e+00f 1 + 15 3.2274630e+01 3.31e-05 1.17e+00 -5.0 4.26e+04 - 9.92e-01 1.00e+00h 1 + 16 3.2274631e+01 7.45e-09 2.71e-03 -5.0 6.11e+02 - 8.97e-01 1.00e+00h 1 + 17 3.2274635e+01 7.45e-09 2.35e-03 -5.0 2.71e+04 - 1.32e-01 1.00e+00f 1 + 18 3.2274635e+01 7.45e-09 1.15e-04 -5.0 5.53e+03 - 9.51e-01 1.00e+00h 1 + 19 3.2274635e+01 7.45e-09 2.84e-05 -5.0 4.41e+04 - 7.54e-01 1.00e+00f 1 +iter objective inf_pr inf_du lg(mu) ||d|| lg(rg) alpha_du alpha_pr ls + 20 3.2274635e+01 7.45e-09 8.54e-07 -5.0 1.83e+04 - 1.00e+00 1.00e+00h 1 + +Number of Iterations....: 20 + + (scaled) (unscaled) +Objective...............: 3.2274635418964841e+01 3.2274635418964841e+01 +Dual infeasibility......: 8.5365078678328669e-07 8.5365078678328669e-07 +Constraint violation....: 8.0780625068607930e-13 7.4505805969238281e-09 +Complementarity.........: 1.2275904566414160e-05 1.2275904566414160e-05 +Overall NLP error.......: 1.2275904566414160e-05 1.2275904566414160e-05 + + +Number of objective function evaluations = 23 +Number of objective gradient evaluations = 20 +Number of equality constraint evaluations = 23 +Number of inequality constraint evaluations = 0 +Number of equality constraint Jacobian evaluations = 22 +Number of inequality constraint Jacobian evaluations = 0 +Number of Lagrangian Hessian evaluations = 20 +Total CPU secs in IPOPT (w/o function evaluations) = 10.450 +Total CPU secs in NLP function evaluations = 1.651 + +EXIT: Optimal Solution Found. + """ + parsed_output = ipopt.Ipopt()._parse_ipopt_output(output) + self.assertEqual(parsed_output["iters"], 20) + self.assertEqual(len(parsed_output["iteration_log"]), 21) + self.assertEqual(parsed_output["incumbent_objective"], 3.2274635418964841e01) + self.assertEqual(parsed_output["iteration_log"][3]["diagnostic_tags"], 'Nhj') + self.assertIn("final_scaled_results", parsed_output.keys()) + self.assertIn( + 'IPOPT (w/o function evaluations)', parsed_output['cpu_seconds'].keys() + ) + def test_verify_ipopt_options(self): opt = ipopt.Ipopt(solver_options={'max_iter': 4}) opt._verify_ipopt_options(opt.config) @@ -478,6 +589,37 @@ def test_ipopt_solve(self): self.assertAlmostEqual(model.x.value, 1) self.assertAlmostEqual(model.y.value, 1) + def test_ipopt_quiet_print_level(self): + model = self.create_model() + result = ipopt.Ipopt().solve(model, solver_options={'print_level': 0}) + # IPOPT doesn't tell us anything about the iters if the print level + # is set to 0 + self.assertIsNone(result.iteration_count) + self.assertFalse(hasattr(result.extra_info, 'iteration_log')) + model = self.create_model() + result = ipopt.Ipopt().solve(model, solver_options={'print_level': 3}) + # At a slightly higher level, we get some of the info, like + # iteration count, but NOT iteration_log + self.assertEqual(result.iteration_count, 11) + self.assertFalse(hasattr(result.extra_info, 'iteration_log')) + + def test_ipopt_loud_print_level(self): + with windows_tee_buffer(1 << 20): + model = self.create_model() + result = ipopt.Ipopt().solve(model, solver_options={'print_level': 8}) + # Nothing unexpected should be in the results object at this point, + # except that the solver_log is significantly longer + self.assertEqual(result.iteration_count, 11) + self.assertEqual(result.incumbent_objective, 7.013645951336496e-25) + self.assertIn('Optimal Solution Found', result.extra_info.solver_message) + self.assertTrue(hasattr(result.extra_info, 'iteration_log')) + model = self.create_model() + result = ipopt.Ipopt().solve(model, solver_options={'print_level': 12}) + self.assertEqual(result.iteration_count, 11) + self.assertEqual(result.incumbent_objective, 7.013645951336496e-25) + self.assertIn('Optimal Solution Found', result.extra_info.solver_message) + self.assertTrue(hasattr(result.extra_info, 'iteration_log')) + def test_ipopt_results(self): model = self.create_model() results = ipopt.Ipopt().solve(model) @@ -612,14 +754,13 @@ def test_map_OF_options(self): solver_options={'OF_bogus_option': 5}, load_solutions=False, ) - print(LOG.getvalue()) self.assertIn('OPTION_INVALID', LOG.getvalue()) # Note: OF_ is stripped self.assertIn( 'Read Option: "bogus_option". It is not a valid option', LOG.getvalue() ) - with self.assertRaisesRegex(ValueError, "unallowed ipopt option 'wantsol'"): + with self.assertRaisesRegex(ValueError, "unallowed Ipopt option 'wantsol'"): results = ipopt.LegacyIpoptSolver().solve( model, tee=True, diff --git a/pyomo/contrib/solver/tests/solvers/test_sol_reader.py b/pyomo/contrib/solver/tests/solvers/test_sol_reader.py index 0db7934cd86..62d77341f65 100644 --- a/pyomo/contrib/solver/tests/solvers/test_sol_reader.py +++ b/pyomo/contrib/solver/tests/solvers/test_sol_reader.py @@ -9,10 +9,19 @@ # This software is distributed under the 3-clause BSD License. # ___________________________________________________________________________ +import io + +import pyomo.environ as pyo from pyomo.common import unittest +from pyomo.common.errors import PyomoException from pyomo.common.fileutils import this_file_dir from pyomo.common.tempfiles import TempfileManager -from pyomo.contrib.solver.solvers.sol_reader import SolFileData +from pyomo.contrib.solver.solvers.sol_reader import ( + SolSolutionLoader, + SolFileData, + parse_sol_file, +) +from pyomo.contrib.solver.common.results import Results currdir = this_file_dir() @@ -30,22 +39,118 @@ def test_default_instantiation(self): class TestSolParser(unittest.TestCase): - # I am not sure how to write these tests best since the sol parser requires - # not only a file but also the nl_info and results objects. def setUp(self): TempfileManager.push() def tearDown(self): TempfileManager.pop(remove=True) - def test_default_behavior(self): - pass + class _FakeNLInfo: + def __init__( + self, + variables, + constraints, + objectives=None, + scaling=None, + eliminated_vars=None, + ): + self.variables = variables + self.constraints = constraints + self.objectives = objectives or [] + self.scaling = scaling + self.eliminated_vars = eliminated_vars or [] + + class _FakeSolData: + def __init__(self, primals=None, duals=None): + self.primals = primals or [] + self.duals = duals or [] + self.var_suffixes = {} + self.con_suffixes = {} + self.obj_suffixes = {} + self.problem_suffixes = {} + self.other = [] + + def test_get_duals_no_objective_returns_zeros(self): + # model with 2 cons, no objective + m = pyo.ConcreteModel() + m.x = pyo.Var(initialize=1.0) + m.y = pyo.Var(initialize=2.0) + m.c1 = pyo.Constraint(expr=m.x + m.y >= 0) + m.c2 = pyo.Constraint(expr=m.x - m.y <= 3) + + nl_info = self._FakeNLInfo( + variables=[m.x, m.y], constraints=[m.c1, m.c2], objectives=[], scaling=None + ) + # solver returned some (non-zero) duals, but we should zero them out + sol_data = self._FakeSolData(duals=[123.0, -7.5]) + + loader = SolSolutionLoader(sol_data, nl_info) + duals = loader.get_duals() + self.assertEqual(duals[m.c1], 0.0) + self.assertEqual(duals[m.c2], 0.0) + + def test_parse_sol_file(self): + # Build a tiny .sol text stream: + # - "Options" block with number_of_options = 0, then 4 model_object ints + # model_objects[1] = #cons, model_objects[3] = #vars + # - #cons duals lines + # - #vars primals lines + # - "objno " + n_cons = 2 + n_vars = 3 + sol_content = ( + "Solver message preamble\n" + "Options\n" + "0\n" + f"0\n{n_cons}\n0\n{n_vars}\n" # model_objects (4 ints) + "1.5\n-2.25\n" # duals (2 lines) + "10.0\n20.0\n30.0\n" # primals (3 lines) + "objno 0 0\n" # exit code line + ) + stream = io.StringIO(sol_content) + + # Minimal NL info matching sizes + m = pyo.ConcreteModel() + m.v = pyo.Var(range(n_vars)) + m.c = pyo.Constraint(range(n_cons), rule=lambda m, i: m.v[0] >= -100) + nl_info = self._FakeNLInfo( + variables=[m.v[i] for i in range(n_vars)], + constraints=[m.c[i] for i in range(n_cons)], + ) + + res = Results() + res_out, sol_data = parse_sol_file(stream, nl_info, res) + + # Check counts populated + self.assertEqual(len(sol_data.duals), n_cons) + self.assertEqual(len(sol_data.primals), n_vars) + # Exit code 0..99 -> optimal + convergenceCriteriaSatisfied + self.assertEqual(res_out.solution_status.name, "optimal") + self.assertEqual( + res_out.termination_condition.name, "convergenceCriteriaSatisfied" + ) + + # Values preserved + self.assertAlmostEqual(sol_data.duals[0], 1.5) + self.assertAlmostEqual(sol_data.duals[1], -2.25) + self.assertEqual(sol_data.primals, [10.0, 20.0, 30.0]) + + def test_parse_sol_file_missing_options_raises(self): + # No line contains the substring "Options" + bad_text = "Solver message preamble\nNo header here\n" + stream = io.StringIO(bad_text) + + nl_info = self._FakeNLInfo(variables=[], constraints=[]) + + with self.assertRaises(PyomoException): + parse_sol_file(stream, nl_info, Results()) - def test_custom_behavior(self): - pass + def test_parse_sol_file_malformed_options_raises(self): + # Contains "Options" but the required integer line is missing/blank + bad_text = "Preamble\nOptions\n\n" + stream = io.StringIO(bad_text) - def test_infeasible1(self): - pass + nl_info = self._FakeNLInfo(variables=[], constraints=[]) - def test_infeasible2(self): - pass + with self.assertRaises(ValueError): + parse_sol_file(stream, nl_info, Results())