Solver output should be logged through the logger instead of stdout/print

[daviskirk]

For many solvers, the solver stdout is quite valuable and it would be nice to have it logged in some kind of consistent fashion.

In general it would be nice to know if there is a convention around logging.
I've seen print and logging in the code but I can't really find a pattern as to what to use when.

If there is no convention I would strongly prefer we use logging as much as possible as it is more flexible and allows the end user to determine the target of the logging output.

I'd be glad to help with some of this if this is something that would be acceptable / desirable.

[whart222]

I'd like to discuss design trade-offs before settling on a specific plan. I agree that we should have consistency, I thought that we had that in our current design. (Though it's probably poorly documented.)

There are actually two types of "output" that need to be captured:

1. Logging information generated by Pyomo while setting up, executing the solver and summarizing the optimization results, and

2. Logging information generated by the optimizer itself.

Currently, (1) should be redirected to a logger, while (2) should be redirected to a solver logfile. I could imagine the desire to combine these, but I personally find it convenient to treat them separately.

I also think it'll be difficult to pull in the solver output (2) into the Python environment without caching it, which would probably make it difficult to "tee" the output (i.e. stream it to the user). Specifically, we execute most solvers through system calls, and it's not obvious to me that we would be able to redirect the solver output into a logger object.

[daviskirk]

Thanks for the answer! Actually I think what you describe is very sensible. I see your point on the solver output.

I think I was looking at lines like this:

pyomo/pyomo/opt/base/solvers.py

Line 603 in bf342b0

print(" %6.2f seconds required for presolve" % (presolve_completion_time - initial_time))

where a print function is used. When we redirect the logs to a different source (not just console output) these lines are then missing. Is this by design or for historical reasons?

[jsiirola]

I agree that in general, Pyomo should not have any print statements. Ideally, each module should use its own logging hierarchy (even if everything relies on the default pyomo namespace logger). The print statements that exist are (slowly) being removed and replaced with logger calls.

The specific print statement you mention is historical, and I have been moving them to a standardized / centralized pyomo.util.timing logger.

Solvers are trickier. We currently process and reroute the stdout / stderr for the solver processes to various destinations (logfiles or the console) using a set of stream readers / writers in the pyutilib.subprocess library (this is how tee is implemented). We could easily send it a "stream" that emitted its data to the logger. I'm just not entirely convinced that that is a good idea (there is an overhead in using Python logging that may not be desirable).

[mrmundt]

Hello, @daviskirk . We have recently started working on an overhaul of the solver interfaces. The request in this Issue has been implemented in the future solver interfaces but will NOT be implemented in the legacy interfaces. More details on the new solver interfaces and how to access them can be found in our online documentation https://pyomo.readthedocs.io/en/stable/explanation/experimental/solvers.html or in Issue #1030.

NOTE: The new interfaces are actively under development and are NOT the default. We encourage you to try them and provide any feedback you may have on Issue #1030.