Add Delay to Raising Logger Error

[dallan-keylogic]

Summary/Motivation:

I had an application where PETSc was raising an ApplicationError because of a failed solve without any solver output logged. It seems that the reason why was that the logger is on a separate thread than the script file, but the exception was shutting down execution before the output could be captured. Introducing a one-second delay before reraising the exception fixed the issue in my application. I'm not sure how to write a test for this, though.

Legal Acknowledgement

By contributing to this software project, I agree to the following terms and conditions for my contribution:

1. I agree my contributions are submitted under the license terms described in the LICENSE.txt file at the top level of this directory.
2. I represent I am authorized to make the contributions and grant the license. If my employer has rights to intellectual property that includes these contributions, I represent that I have received permission to make contributions and grant the required license on behalf of that employer.

[codecov[bot]]

Codecov Report

Base: 70.13% // Head: 70.12% // Decreases project coverage by -0.01% :warning:

Coverage data is based on head (2b3dde7) compared to base (ee82d83). Patch coverage: 100.00% of modified lines in pull request are covered.

:exclamation: Current head 2b3dde7 differs from pull request most recent head 538f758. Consider uploading reports for the commit 538f758 to get more accurate results

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #887      +/-   ##
==========================================
- Coverage   70.13%   70.12%   -0.01%     
==========================================
  Files         398      398              
  Lines       64933    64933              
  Branches    12019    12019              
==========================================
- Hits        45539    45536       -3     
- Misses      17068    17072       +4     
+ Partials     2326     2325       -1     

Impacted Files	Coverage Δ
idaes/logger.py	90.27% <100.00%> (ø)
idaes/ver.py	61.53% <0.00%> (-4.62%)	:arrow_down:

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

:umbrella: View full report at Codecov.
:loudspeaker: Do you have feedback about the report comment? Let us know in this issue.

[jsiirola]

Would it be better to just explicitly flush the log stream on exit rather than to add an arbitrary delay?

[eslickj]

@jsiirola, I thought that was already happening, but not working. Let me take another look at this.

[eslickj]

@dallan-keylogic, can you see if it works to the following to the top of the thread class log_value method (instead of sleep):

if self.stop.isSet():
   self.stream.flush()

[dallan-keylogic]

@eslickj That modification did not work.

[jsiirola]

My suspicion is that this is an issue with Windows stream buffering (as that is the only platform that we are seeing it on). Pyomo faces something similar when working through the TeeStream infrastructure. As I was digging through this, is there a particular reason that solver_log isn't implemented using:

from pyomo.common.log import LogStream

@contextmanager
def solver_log(logger, level=logging.ERROR):
    tee = logger.isEnabledFor(level)
    if not solver_capture():
        yield SolverLogInfo(tee=tee)
    else:
        with capture_output(LogStream(level, logger)) as s:
            yield SolverLogInfo(tee=tee)

@dallan-keylogic, can you try replacing solver_logger with this and see if the problem goes away?

(I think the issue is that there is already a thread in capture_output (buried in a TeeStream object) ... and there are race conditions between that thread and the thread IDAES is creating.)

[ksbeattie]

@dallan-keylogic, will try the above suggestion from @jsiirola .

[dallan-keylogic]

I merged the branches the wrong way when trying to get the new fix onto this branch. Closing this PR in favor of #1098.