Changes in behavior for DISPATCHES flowsheet between Pyomo 6.5 and 6.6

[lbianchi-lbl]

Summary

Symptoms

• After updating to Pyomo 6.6.1, we noticed that one of the flowsheets in DISPATCHES solved to a different solution than expected, causing the corresponding test to fail
• The same identical flowsheet solved to its reference solution (i.e. the test passes) when IDAES 2.0.0 and Pyomo 6.5.0 are used
• This persisted when the DISPATCHES and IDAES versions were kept fixed, and the Pyomo version was the only thing being changed:
  • Using Pyomo 6.5.0, the flowsheet solves as expected and the test passes (corresponding to Outcome A described below)
  • Using Pyomo 6.6.1, the flowsheet takes a much longer time to solve (test runtime is 15-20 minutes instead of 1-2 minutes) to a solution different than the one expected, causing the test to fail (corresponding to Outcome D described below)

Investigation

• The following steps were performed under the hypothesis that the change in behavior was due solely to a change in Pyomo at some point between 6.5.0 and 6.6.1, which is possibly incorrect or incomplete
• Other confounding factors that we're aware of include the presence of UnboundLocalError in FBBT _prop_bnds_leaf_to_root_GeneralExpression() #2846 early in the timeline, which causes the test to fail immediately. This required applying the patch in Fix typo in FBBT (GeneralExpression) #2848 to every commit starting from 687f4a2 so that the flowsheet could be tested to completion
• Some commits (e.g. 5bf835d) contain spurious errors that were immediately fixed in neighboring commits. We considered this type of errors not relevant for the purpose of investigating this issue and therefore are not explicitly mentioned in the list below
• The "probe" used was pytest -v -x --pyargs dispatches -k test_charge_usc_powerplant (exact details described below)

Results

• 6.5.0 to 8c3094e: the test passes (outcome A)
• e9580de to 36b5799: the test fails, but for a different reason (numeric value being slightly outside the tolerance threshold) (outcome B)
  • Note: commit range is approximate because of bugfix commits
• 8da7fc9 to 62dbb8f: the test fails with a RuntimeError raised by SymbolMap.addSymbol() (outcome C)
• b8fc92b to 6.6.1: the test fails because of the different solution (assert False == True) (outcome D)

Steps to reproduce the issue

Step 1: prepare the environment

conda create -n test-dispatches-205 python=3.8 && conda activate test-dispatches-205
pip install "git+https://github.com/gmlc-dispatches/dispatches@03b936a7c0999c2e91f542094557c708532ba7e6"
pip show idaes-pse pyomo  # should show idaes-pse 2.0.0, pyomo 6.5.0 following gmlc-dispatches/dispatches#203
git clone https://github.com/Pyomo/pyomo && cd pyomo

Step 2: generate list of commit SHAs to be tested in oldest-first order

git log 189ce74af^..6.6.1 --format=%H --reverse --ancestry-path

Step 3: run for every Pyomo commit to be tested (git bisect-style)

• {} is expanded to the full SHA of the commit (the command is run serially through xargs to serve as a poor impression of git bisect run)
• The git show f492dd8 -- pyomo/contrib/fbbt/fbbt.py | git apply - is needed between 687f4a2 and edf4ccc, but practically running it outside that range doesn't seem to make a difference (the git apply command will fail without apparent side effects)

bash -c 'git checkout {} ; git show f492dd8 -- pyomo/contrib/fbbt/fbbt.py | git apply - ; pip uninstall --yes pyomo ; pip install . ; pytest -v -x --pyargs dispatches -k test_charge_usc_powerplant > ../logs/{}.log ; git reset --hard {}'

Error Message

Outcome A

============================= test session starts ==============================
platform linux -- Python 3.8.16, pytest-7.3.2, pluggy-1.0.0 -- /opt/conda/envs/test-dispatches-205/bin/python
cachedir: .pytest_cache
rootdir: /home/ludo/lbl/dispatches/bugs/dispatches-205/pyomo
configfile: setup.cfg
plugins: dispatches-data-packages-23.3.19, anyio-3.7.0
collecting ... collected 105 items / 101 deselected / 1 skipped / 4 selected

case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function PASSED [ 25%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_initialize PASSED [ 50%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_costing PASSED [ 75%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model PASSED [100%]

=============================== warnings summary ===============================
../../../../../../../opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25
  /opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25: DeprecationWarning: Please use `get_index_dtype` from the `scipy.sparse` namespace, the `scipy.sparse.sputils` namespace is deprecated.
    from scipy.sparse.sputils import get_index_dtype

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
===== 4 passed, 1 skipped, 101 deselected, 1 warning in 132.45s (0:02:12) ======

Outcome B

============================= test session starts ==============================
platform linux -- Python 3.8.16, pytest-7.3.2, pluggy-1.0.0 -- /opt/conda/envs/test-dispatches-205/bin/python
cachedir: .pytest_cache
rootdir: /home/ludo/lbl/dispatches/bugs/dispatches-205/pyomo
configfile: setup.cfg
plugins: dispatches-data-packages-23.3.19, anyio-3.7.0
collecting ... collected 105 items / 101 deselected / 1 skipped / 4 selected

case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function PASSED [ 25%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_initialize PASSED [ 50%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_costing PASSED [ 75%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model FAILED [100%]

=================================== FAILURES ===================================
____________________________ test_usc_charge_model _____________________________

model = <pyomo.core.base.PyomoModel.ConcreteModel object at 0x7f9bd4217b30>

    @pytest.mark.integration
    def test_usc_charge_model(model):
        # Add missing functions to complete the charge model (add bounds
        # and disjunctions)
        charge_usc.unfix_disjuncts_post_initialization(model)
        charge_usc.add_bounds(model, power_max=power_max)
        charge_usc.add_bounds_costing(model, power_max=power_max)
    
        # Add design optimization problem
        charge_usc.model_analysis(model, heat_duty=heat_duty)
    
        opt = SolverFactory('gdpopt')
        _prop_bnds_root_to_leaf_map[ExternalFunctionExpression] = lambda x, y, z: None
    
        result = opt.solve(
            model,
            tee=False,
            algorithm='RIC',
            mip_solver='cbc',
            nlp_solver='ipopt',
            init_algorithm='no_init',
            subproblem_presolve=False
        )
    
        assert result.solver.termination_condition == TerminationCondition.optimal
        assert value(model.fs.charge.hp_source_disjunct.indicator_var) == True
        assert value(model.fs.charge.solar_salt_disjunct.indicator_var) == True
>       assert value(
            model.fs.charge.solar_salt_disjunct.hxc.area) == pytest.approx(
                1838.2,
                abs=1e-1)
E       assert 1839.3559228993597 == 1838.2 ± 1.0e-01
E         comparison failed
E         Obtained: 1839.3559228993597
E         Expected: 1838.2 ± 1.0e-01

/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py:140: AssertionError
----------------------------- Captured stdout call -----------------------------
******************** Disjuncts Unfixed *************************


=============================== warnings summary ===============================
../../../../../../../opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25
  /opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25: DeprecationWarning: Please use `get_index_dtype` from the `scipy.sparse` namespace, the `scipy.sparse.sputils` namespace is deprecated.
    from scipy.sparse.sputils import get_index_dtype

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model
!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
= 1 failed, 3 passed, 1 skipped, 101 deselected, 1 warning in 128.40s (0:02:08) =

Outcome C

============================= test session starts ==============================
platform linux -- Python 3.8.16, pytest-7.3.2, pluggy-1.0.0 -- /opt/conda/envs/test-dispatches-205/bin/python
cachedir: .pytest_cache
rootdir: /home/ludo/lbl/dispatches/bugs/dispatches-205/pyomo
configfile: setup.cfg
plugins: dispatches-data-packages-23.3.19, anyio-3.7.0
collecting ... collected 105 items / 101 deselected / 1 skipped / 4 selected

case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function FAILED [ 25%]

=================================== FAILURES ===================================
______________________________ test_main_function ______________________________

    @pytest.mark.integration
    def test_main_function():
    
        # Build ultra-supercritical plant base model
        m_usc = usc.build_plant_model()
    
        # Initialize ultra-supercritical plant base model
        usc.initialize(m_usc)
    
        # Build charge model
        m = charge_usc.main(m_usc, solver=solver, optarg=optarg)
    
        # Solve design optimization problem
        charge_usc.model_analysis(m, heat_duty=heat_duty)
    
        # Solve model using GDPopt
>       results = charge_usc.run_gdp(m)

/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py:88: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/charge_design_ultra_supercritical_power_plant.py:2589: in run_gdp
    results = opt.solve(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/gdpopt/GDPopt.py:141: in solve
    return SolverFactory(_supported_algorithms[algorithm][0]).solve(model, **kwds)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/gdpopt/ric.py:60: in solve
    return super().solve(model, **kwds)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/gdpopt/algorithm_base_class.py:130: in solve
    self._solve_gdp(model, config)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/gdpopt/ric.py:85: in _solve_gdp
    mip_feasible = solve_MILP_discrete_problem(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/gdpopt/solve_discrete_problem.py:89: in solve_MILP_discrete_problem
    results = SolverFactory(config.mip_solver).solve(m, **mip_args)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/opt/base/solvers.py:597: in solve
    self._presolve(*args, **kwds)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/solvers/plugins/solvers/CBCplugin.py:263: in _presolve
    super(CBCSHELL, self)._presolve(*args, **kwds)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/opt/solver/shellcmd.py:224: in _presolve
    OptSolver._presolve(self, *args, **kwds)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/opt/base/solvers.py:706: in _presolve
    ) = self._convert_problem(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/opt/base/solvers.py:757: in _convert_problem
    return convert_problem(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/opt/base/convert.py:99: in convert_problem
    problem_files, symbol_map = converter.apply(*tmp, **tmpkw)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/solvers/plugins/converter/model.py:78: in apply
    (problem_filename, symbol_map_id) = instance.write(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/core/base/block.py:2086: in write
    (filename, smap) = problem_writer(self, filename, solver_capability, io_options)
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/repn/plugins/cpxlp.py:164: in __call__
    symbol_map = self._print_model_LP(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/repn/plugins/cpxlp.py:485: in _print_model_LP
    variable_label_pairs = list(
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/repn/plugins/cpxlp.py:486: in <genexpr>
    (vardata, create_symbol_func(symbol_map, vardata, labeler))
/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/core/expr/symbol_map.py:117: in createSymbol
    self.addSymbol(obj, symbol)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pyomo.core.expr.symbol_map.SymbolMap object at 0x7fdcbb0123a0>
obj = <pyomo.core.base.var._GeneralVarData object at 0x7fdca7841190>
symb = 'x18'

    def addSymbol(self, obj, symb):
        """
        Add a symbol for a given object
    
        This method assumes that objects and symbol names will not conflict.
        """
        nSymbols = len(self.byObject) + 1
        self.byObject[id(obj)] = symb
        self.bySymbol[symb] = obj
        if nSymbols != len(self.bySymbol):
            raise RuntimeError(
                "SymbolMap.addSymbol(): duplicate symbol.  "
                "SymbolMap likely in an inconsistent state"
            )
        if len(self.byObject) != len(self.bySymbol):
>           raise RuntimeError(
                "SymbolMap.addSymbol(): duplicate object.  "
                "SymbolMap likely in an inconsistent state"
            )
E           RuntimeError: SymbolMap.addSymbol(): duplicate object.  SymbolMap likely in an inconsistent state

/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/core/expr/symbol_map.py:78: RuntimeError
----------------------------- Captured stdout call -----------------------------
2023-06-14 03:29:03 [INFO] idaes.init.fs.boiler.control_volume: Initialization Complete
2023-06-14 03:29:03 [INFO] idaes.init.fs.boiler: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.turbine_splitter[1]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.turbine_splitter[2]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.reheater[1].control_volume: Initialization Complete
2023-06-14 03:29:03 [INFO] idaes.init.fs.reheater[1]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.turbine_splitter[3]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.turbine_splitter[4]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.reheater[2].control_volume: Initialization Complete
2023-06-14 03:29:03 [INFO] idaes.init.fs.reheater[2]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:03 [INFO] idaes.init.fs.turbine_splitter[5]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.turbine_splitter[6]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.turbine_splitter[7]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.turbine_splitter[8]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.turbine_splitter[9]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.turbine_splitter[10]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.condenser_mix: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.condenser.control_volume: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.condenser: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh_mixer[1]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[1].hot_side: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[1].cold_side: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[1]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh_mixer[2]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[2].hot_side: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[2].cold_side: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[2]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh_mixer[3]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[3].hot_side: Initialization Complete
2023-06-14 03:29:04 [INFO] idaes.init.fs.fwh[3].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[3]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh_mixer[4]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[4].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[4].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[4]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[5].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[5].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[5]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.deaerator: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh_mixer[6]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[6].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[6].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[6]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh_mixer[7]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[7].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[7].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[7]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh_mixer[8]: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[8].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[8].cold_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[8]: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[9].hot_side: Initialization Complete
2023-06-14 03:29:05 [INFO] idaes.init.fs.fwh[9].cold_side: Initialization Complete
2023-06-14 03:29:06 [INFO] idaes.init.fs.fwh[9]: Initialization Completed, optimal - Optimal Solution Found
Model Initialization =  optimal
*******************  USC Model Initialized   ********************
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.vhp_source_disjunct.ess_vhp_split: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.hp_source_disjunct.ess_hp_split: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.connector.control_volume: Initialization Complete
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.connector: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.solar_salt_disjunct.hxc.hot_side: Initialization Complete
2023-06-14 03:29:07 [INFO] idaes.init.dispatches.properties.solarsalt_properties: fs.charge.solar_salt_disjunct.hxc.cold_side.properties_in Initialisation Step 1 Complete.
2023-06-14 03:29:07 [INFO] idaes.init.dispatches.properties.solarsalt_properties: Initialization Step 1 Complete.
2023-06-14 03:29:07 [INFO] idaes.init.dispatches.properties.solarsalt_properties: fs.charge.solar_salt_disjunct.hxc.cold_side.properties_out Initialisation Step 1 Complete.
2023-06-14 03:29:07 [INFO] idaes.init.dispatches.properties.solarsalt_properties: Initialization Step 1 Complete.
2023-06-14 03:29:07 [INFO] idaes.init.dispatches.properties.solarsalt_properties: State Released.
2023-06-14 03:29:07 [INFO] idaes.init.fs.charge.solar_salt_disjunct.hxc.cold_side: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.solarsalt_properties: State Released.
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.solar_salt_disjunct.hxc: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.hitec_salt_disjunct.hxc.hot_side: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: fs.charge.hitec_salt_disjunct.hxc.cold_side.properties_in Initialisation Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: Initialization Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: fs.charge.hitec_salt_disjunct.hxc.cold_side.properties_out Initialisation Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: Initialization Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: State Released.
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.hitec_salt_disjunct.hxc.cold_side: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.hitecsalt_properties: State Released.
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.hitec_salt_disjunct.hxc: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.thermal_oil_disjunct.hxc.hot_side: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: fs.charge.thermal_oil_disjunct.hxc.cold_side.properties_in Initialisation Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: Initialization Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: fs.charge.thermal_oil_disjunct.hxc.cold_side.properties_out Initialisation Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: Initialization Step 1 Complete.
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: State Released.
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.thermal_oil_disjunct.hxc.cold_side: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.dispatches.properties.thermaloil_properties: State Released.
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.thermal_oil_disjunct.hxc: Initialization Completed, optimal - Optimal Solution Found
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.cooler.control_volume: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.cooler: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.hx_pump.control_volume: Initialization Complete
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.hx_pump: Initialization Complete: optimal - Optimal Solution Found
2023-06-14 03:29:08 [INFO] idaes.init.fs.charge.recycle_mixer: Initialization Complete: optimal - Optimal Solution Found
Charge model initialization solver termination =  optimal
***************   Charge Model Initialized   ********************
Charge model initialization solver termination =  optimal
******************** Costing Initialized *************************


******************** Disjuncts Unfixed *************************


Starting GDPopt version 22.5.13 using RIC algorithm
iterlim: None
time_limit: None
tee: true
logger: <Logger pyomo.contrib.gdpopt (INFO)>
mip_solver: cbc
mip_solver_args:
nlp_solver: ipopt
nlp_solver_args:
  options: {max_iter: 150}
  tee: false
minlp_solver: baron
minlp_solver_args:
local_minlp_solver: bonmin
local_minlp_solver_args:
small_dual_tolerance: 1.0e-08
bound_tolerance: 1.0e-06
integer_tolerance: 1.0e-05
constraint_tolerance: 1.0e-06
variable_tolerance: 1.0e-08
subproblem_initialization_method: <function restore_vars_to_original_values at 0x7fdcaeff0ee0>
call_before_subproblem_solve: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
call_after_subproblem_solve: <function print_model at 0x7fdc8ff61ee0>
call_after_subproblem_feasible: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
force_subproblem_nlp: false
subproblem_presolve: false
tighten_nlp_var_bounds: false
round_discrete_vars: true
max_fbbt_iterations: 3
init_strategy: None
init_algorithm: no_init
custom_init_disjuncts: []
max_slack: 1000.0
OA_penalty_factor: 1000.0
set_cover_iterlim: 8
discrete_problem_transformation: gdp.bigm
call_before_discrete_problem_solve: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
call_after_discrete_problem_solve: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
call_before_master_solve: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
call_after_master_solve: !!python/name:pyomo.contrib.gdpopt.util._DoNothing ''
mip_presolve: true
calc_disjunctive_bounds: false
obbt_disjunctive_bounds: false

If you use this software, you may cite the following:
            - Implementation:
            Chen, Q; Johnson, ES; Bernal, DE; Valentin, R; Kale, S;
            Bates, J; Siirola, JD; Grossmann, IE.
            Pyomo.GDP: an ecosystem for logic based modeling and optimization
            development.
            Optimization and Engineering, 2021.
Original model has 687 constraints (196 nonlinear) and 2 disjunctions, with 680 variables, of which 5 are binary, 0 are integer, and 675 are continuous.
---Starting GDPopt initialization---
Finished discrete problem initialization in 2.11s and 0 iterations 

=============================================================================================
Iteration | Subproblem Type | Lower Bound | Upper Bound |   Gap    | Time(s)


Solved in 1 iterations and 4.84810 seconds
Optimal objective value inf
Relative optimality gap nan%
No feasible solutions found.
=============================== warnings summary ===============================
../../../../../../../opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25
  /opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25: DeprecationWarning: Please use `get_index_dtype` from the `scipy.sparse` namespace, the `scipy.sparse.sputils` namespace is deprecated.
    from scipy.sparse.sputils import get_index_dtype

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function
!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
=========== 1 failed, 1 skipped, 101 deselected, 1 warning in 22.88s ===========

Outcome D

============================= test session starts ==============================
platform linux -- Python 3.8.16, pytest-7.3.2, pluggy-1.0.0 -- /opt/conda/envs/test-dispatches-205/bin/python
cachedir: .pytest_cache
rootdir: /home/ludo/lbl/dispatches/bugs/dispatches-205/pyomo
configfile: setup.cfg
plugins: dispatches-data-packages-23.3.19, anyio-3.7.0
collecting ... collected 105 items / 101 deselected / 1 skipped / 4 selected

case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function PASSED [ 25%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_initialize PASSED [ 50%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_costing PASSED [ 75%]
case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model FAILED [100%]

=================================== FAILURES ===================================
____________________________ test_usc_charge_model _____________________________

model = <pyomo.core.base.PyomoModel.ConcreteModel object at 0x7f58b2aa1270>

    @pytest.mark.integration
    def test_usc_charge_model(model):
        # Add missing functions to complete the charge model (add bounds
        # and disjunctions)
        charge_usc.unfix_disjuncts_post_initialization(model)
        charge_usc.add_bounds(model, power_max=power_max)
        charge_usc.add_bounds_costing(model, power_max=power_max)
    
        # Add design optimization problem
        charge_usc.model_analysis(model, heat_duty=heat_duty)
    
        opt = SolverFactory('gdpopt')
        _prop_bnds_root_to_leaf_map[ExternalFunctionExpression] = lambda x, y, z: None
    
        result = opt.solve(
            model,
            tee=False,
            algorithm='RIC',
            mip_solver='cbc',
            nlp_solver='ipopt',
            init_algorithm='no_init',
            subproblem_presolve=False
        )
    
        assert result.solver.termination_condition == TerminationCondition.optimal
        assert value(model.fs.charge.hp_source_disjunct.indicator_var) == True
>       assert value(model.fs.charge.solar_salt_disjunct.indicator_var) == True
E       assert False == True
E        +  where False = value(<pyomo.gdp.disjunct.AutoLinkedBooleanVar object at 0x7f58d0ce1b80>)
E        +    where <pyomo.gdp.disjunct.AutoLinkedBooleanVar object at 0x7f58d0ce1b80> = <pyomo.gdp.disjunct.ScalarDisjunct object at 0x7f58c4ec7950>.indicator_var
E        +      where <pyomo.gdp.disjunct.ScalarDisjunct object at 0x7f58c4ec7950> = <pyomo.core.base.block.ScalarBlock object at 0x7f58e8ac4270>.solar_salt_disjunct
E        +        where <pyomo.core.base.block.ScalarBlock object at 0x7f58e8ac4270> = <idaes.core.base.process_block._ScalarFlowsheetBlock object at 0x7f58ec7d2630>.charge
E        +          where <idaes.core.base.process_block._ScalarFlowsheetBlock object at 0x7f58ec7d2630> = <pyomo.core.base.PyomoModel.ConcreteModel object at 0x7f58b2aa1270>.fs

/opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py:139: AssertionError
----------------------------- Captured stdout call -----------------------------
******************** Disjuncts Unfixed *************************


=============================== warnings summary ===============================
../../../../../../../opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25
  /opt/conda/envs/test-dispatches-205/lib/python3.8/site-packages/pyomo/contrib/pynumero/sparse/block_matrix.py:25: DeprecationWarning: Please use `get_index_dtype` from the `scipy.sparse` namespace, the `scipy.sparse.sputils` namespace is deprecated.
    from scipy.sparse.sputils import get_index_dtype

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model
!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
= 1 failed, 3 passed, 1 skipped, 101 deselected, 1 warning in 994.07s (0:16:34) =

Information on your system

Pyomo version:
Python version: 3.8
Operating system: Ubuntu 20.04.5 (but also appears on windows-2019 runners in CI)
How Pyomo was installed (PyPI, conda, source): source (see above)
Solver (if applicable): GDPopt

Additional information

"CC-ing" folks who have actual knowledge of the flowsheet, and/or have been made aware of this issue:

• @nareshsusarla
• @esrawli
• @andrewlee94
• @blnicho

Client packages

• idaes-pse: 2.0.0 (PyPI)
• dispatches: gmlc-dispatches/dispatches@03b936a7c0999c2e91f542094557c708532ba7e6

Test file

https://github.com/gmlc-dispatches/dispatches/blob/03b936a7c0999c2e91f542094557c708532ba7e6/dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py

[andrewlee94]

@lbianchi-lbl Something that might help is to check the state of the model after initialization to see if there is any difference before calling the GDP solver; this might help determine if it is something to do with the GDP solver or the model itself.

[jsiirola]

I am having problems reproducing these test failures, using:

pyomo 1a93fa4  (6.6.1)
idaes-pse 601319d
dispatches 03b936a
---------------------------------------------------
IDAES Extensions Build Versions
===================================================
Solvers:  v3.3.0 20230331-2117 el7-x86_64
Library:  v3.3.0 20230331-2155 el7-x86_64
===================================================

running

pytest -v -x --pyargs dispatches -k test_charge_usc_powerplant

gives

============================================================================ test session starts ============================================================================
platform linux -- Python 3.7.16, pytest-7.2.2, pluggy-1.0.0 -- [...]/python/3.7.16/bin/python
cachedir: .pytest_cache
PyQt5 5.15.2 -- Qt runtime 5.15.2 -- Qt compiled 5.15.2
rootdir: [...]/idaes/dispatches, configfile: pytest.ini
plugins: reportlog-0.1.2, reporting-0.1.0, nbmake-1.4.1, xdist-3.2.1, forked-1.6.0, anyio-3.6.2, arraydiff-0.5.0, doctestplus-0.12.1, remotedata-0.4.0, qt-4.2.0, xvfb-2.0.0, cov-4.0.0, openfiles-0.5.0
collected 110 items / 106 deselected / 4 skipped / 4 selected                                                                                                               

dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_main_function PASSED                                  [ 25%]
dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_initialize PASSED                                     [ 50%]
dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_costing PASSED                                        [ 75%]
dispatches/case_studies/fossil_case/ultra_supercritical_plant/storage/tests/test_charge_usc_powerplant.py::test_usc_charge_model PASSED                               [100%]

========================================================= 4 passed, 4 skipped, 106 deselected in 301.18s (0:05:01) ==========================================================

[anamileva]

Summary

I am observing what may the same issue.

Symptoms

• I am observing several tests fail because they solve to a different objective function value after bumping Pyomo from v6.5.0 to v6.6.0.
• The behavior appears to be non-deterministic: the objective function values for the failing tests change between test runs.

Investigation

• I have confirmed that this issue is observed when the only change is the Pyomo version, with everything else kept fixed.

System Information

• I have observed this behavior with Python 3.9 and 3.10 on MacOS Ventura 13.4, Windows 11, and Ubuntu 22.04.3 LTS.
• The tests were solved with Cbc v2.10.7 on Linux and MacOS, and Cbc v2.10.10 on Windows

Steps to Reproduce

GridPath with Pyomo v6.5.0 (tests pass)

• Create and activate Python a virtual environment
• Clone and install GridPath with Pyomo 6.5.0 (please install with the -e flag)

git clone https://github.com/blue-marble/gridpath.git
cd gridpath
git checkout da2288f
pip install -e .

• Run one of the tests of interest, it should pass.
  python ./tests/test_examples.py TestExamples.test_example_2periods_new_build

GridPath with Pyomo v6.6.0 (some tests fail due to changes in the objective function value)

• Create and activate a Python virtual environment
• Clone and install GridPath with Pyomo 6.6.0 (please install with the -e flag)

git clone https://github.com/blue-marble/gridpath.git
cd gridpath
git checkout 40cf4b7
pip install -e .

• Run the same test, it should fail (since the behavior appears to be non-deterministic, you may need to run the test a few times to observe the failure).
  python ./tests/test_examples.py TestExamples.test_example_2periods_new_build

[jsiirola]

@anamileva, I cannot reproduce your case. Running your first example under RHEL7 / Python 3.9, I get:

% python ./tests/test_examples.py TestExamples.test_example_2periods_new_build
E
======================================================================
ERROR: setUpClass (__main__.TestExamples)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "[...]/gridpath/./tests/test_examples.py", line 185, in setUpClass
    create_database.main(["--database", DB_PATH])
  File "[...]/gridpath/db/create_database.py", line 488, in main
    create_database_schema(conn=conn, parsed_arguments=parsed_args)
  File "[...]/gridpath/db/create_database.py", line 96, in create_database_schema
    conn.executescript(schema)
sqlite3.OperationalError: near "WITH": syntax error

----------------------------------------------------------------------
Ran 0 tests in 12.326s

I am going to close this issue, as the originally reported problem was resolved downstream in DISPATCHES (and we should have closed this at the same time).

@anamileva, please feel free to open a new issue for your observed behavior and we can continue to work through things there. When you do, please:

• check against the current Pyomo release (6.6.2)
• please provide a minimal reproducible example.
  • if a minimal reproducible example is not possible, can you run your examples with keepfiles=True and symbolic_solver_labels=True and report both the "working" and "non-working" LP files? There were two big changes between 6.5.x and 6.6.x: the infrastructure for generating expressions (in particular, we now preserve "0*x" in the generated expressions) and a complete rework of the LP writer (which may result in LP files with different row / column orderings). The LP files might provide hints as to what changed.

[anamileva]

@jsiirola, thank you. Indeed I should have mentioned I did observe what seemed like ordering differences in the LP files. I will try to fix the RHEL7 problem and/or send you an easy-to-work-with example when I open a new issue.