Open
Description
Summary
While attempting to fix a completely different problem, it is clear that there is the logger buffer is not being flushed/cast correctly. Anything that would be printed to stdout while under a logger should get past to a LogStream and then "streamed" correctly; however, it is not.
Steps to reproduce the issue
This is the test I added to contrib.solver that revealed the problem. It can be run locally to confirm that the behavior is not as intended.
@unittest.skipIf(not ipopt_available, 'ipopt is not available')
def test_real_example(self):
log_stream = io.StringIO()
logging.basicConfig(stream=log_stream, level=logging.DEBUG)
logger = logging.getLogger('contrib.solver.config.test.1')
m = pyo.ConcreteModel()
m.x = pyo.Var([1, 2], initialize=1, bounds=(0, None))
m.eq = pyo.Constraint(expr=m.x[1] * m.x[2] ** 1.5 == 3)
m.obj = pyo.Objective(expr=m.x[1] ** 2 + m.x[2] ** 2)
solver = pyo.SolverFactory("ipopt_v2")
with capture_output(logger):
solver.solve(m, tee=True, timelimit=5)
for handler in logger.handlers:
handler.flush()
log_contents = log_stream.getvalue()
self.assertIn('EXIT: Optimal Solution Found.', log_contents)
Error Message
DEBUG:pyomo.core:Constructing ConcreteModel 'ConcreteModel', from data=None
DEBUG:pyomo.core:Constructing SetOf, name=[1, 2], from data=None
DEBUG:pyomo.core:Constructing Set, name={}, from data=None
DEBUG:pyomo.core:Constructing IndexedVar 'x' on [Model] from data=None
DEBUG:pyomo.core:Constructing Variable x
DEBUG:pyomo.core:Constructed component ''[Model].x'':
x : Size=2, Index={1, 2}
Key : Lower : Value : Upper : Fixed : Stale : Domain
1 : 0 : 1 : None : False : False : Reals
2 : 0 : 1 : None : False : False : Reals
DEBUG:pyomo.core:Constructing AbstractScalarConstraint 'eq' on [Model] from data=None
DEBUG:pyomo.core:Constructing constraint eq
DEBUG:pyomo.core:Constructed component ''[Model].eq'':
eq : Size=1, Index=None, Active=True
Key : Lower : Body : Upper : Active
None : 3.0 : x[1]*x[2]**1.5 : 3.0 : True
DEBUG:pyomo.core:Constructing ScalarObjective 'obj' on [Model] from data=None
DEBUG:pyomo.core:Constructing objective obj
DEBUG:pyomo.core:Constructed component ''[Model].obj'':
obj : Size=1, Index=None, Active=True
Key : Active : Sense : Expression
None : True : minimize : x[1]**2 + x[2]**2
ERROR:pyomo.common.tee:Output stream (<Logger __main__ (DEBUG)>) closed before all output was written to it. The following was left in the output buffer:
'Ipopt 3.13.2: max_cpu_time=5.0\n\n\n******************************************************************************\nThis program contains Ipopt, a library for large-scale nonlinear optimization.\n Ipopt is released as open source code under the Eclipse Public License (EPL).\n For more information visit http://projects.coin-or.org/Ipopt\n\nThis version of Ipopt was compiled from source code available at\n https://github.com/IDAES/Ipopt as part of the Institute for the Design of\n Advanced Energy Systems Process Systems Engineering Framework (IDAES PSE\n Framework) Copyright (c) 2018-2019. See https://github.com/IDAES/idaes-pse.\n\nThis version of Ipopt was compiled using HSL, a collection of Fortran codes\n for large-scale scientific computation. All technical papers, sales and\n publicity material resulting from use of the HSL codes within IPOPT must\n contain the following acknowledgement:\n HSL, a collection of Fortran codes for large-scale scientific\n computation. See http://www.hsl.rl.ac.uk.\n******************************************************************************\n\nThis is Ipopt version 3.13.2, running with linear solver ma27.\n\nNumber of nonzeros in equality constraint Jacobian...: 2\nNumber of nonzeros in inequality constraint Jacobian.: 0\nNumber of nonzeros in Lagrangian Hessian.............: 3\n\nTotal number of variables............................: 2\n variables with only lower bounds: 2\n variables with lower and upper bounds: 0\n variables with only upper bounds: 0\nTotal number of equality constraints.................: 1\nTotal number of inequality constraints...............: 0\n inequality constraints with only lower bounds: 0\n inequality constraints with lower and upper bounds: 0\n inequality constraints with only upper bounds: 0\n\niter objective inf_pr inf_du lg(mu) ||d|| lg(rg) alpha_du alpha_pr ls\n 0 2.0000000e+00 2.00e+00 2.31e-01 -1.0 0.00e+00 - 0.00e+00 0.00e+00 0\n 1 6.2678087e+00 1.27e+00 3.92e+00 -1.0 9.70e-01 - 5.29e-01 1.00e+00h 1\n 2 4.8590703e+00 1.10e-01 5.52e-01 -1.0 2.57e-01 - 1.00e+00 1.00e+00f 1\n 3 4.7218167e+00 1.10e-03 1.14e-02 -1.7 3.06e-02 - 1.00e+00 1.00e+00h 1\n 4 4.7204377e+00 1.01e-07 1.11e-06 -3.8 3.20e-04 - 1.00e+00 1.00e+00h 1\n 5 4.7204376e+00 4.34e-11 3.96e-10 -5.7 5.75e-06 - 1.00e+00 1.00e+00h 1\n 6 4.7204376e+00 6.22e-15 7.88e-14 -8.6 6.70e-08 - 1.00e+00 1.00e+00h 1\n\nNumber of Iterations....: 6\n\n (scaled) (unscaled)\nObjective...............: 4.7204375564745025e+00 4.7204375564745025e+00\nDual infeasibility......: 7.8814701770843877e-14 7.8814701770843877e-14\nConstraint violation....: 6.2172489379008766e-15 6.2172489379008766e-15\nComplementarity.........: 2.5059934717596744e-09 2.5059934717596744e-09\nOverall NLP error.......: 2.5059934717596744e-09 2.5059934717596744e-09\n\n\nNumber of objective function evaluations = 7\nNumber of objective gradient evaluations = 7\nNumber of equality constraint evaluations = 7\nNumber of inequality constraint evaluations = 0\nNumber of equality constraint Jacobian evaluations = 7\nNumber of inequality constraint Jacobian evaluations = 0\nNumber of Lagrangian Hessian evaluations = 6\nTotal CPU secs in IPOPT (w/o function evaluations) = 0.001\nTotal CPU secs in NLP function evaluations = 0.000\n\nEXIT: Optimal Solution Found.\n'Information on your system
Pyomo version: 6.9.0.dev0
Python version: 3.11
Operating system: MacOS (but confirmed on Linux/Win, too)
How Pyomo was installed (PyPI, conda, source): source
Solver (if applicable): ipopt
Additional information
We are delaying this fix until after the 6.9.0 release because it's been there for who knows how long and hasn't yet been reported.