Issue385 timeout (lbl-srg#386)

* Fix timeout at low level and start process as daemon The daemon flag is an extra safety: in case the main process exists for whatever reason, the daemonic subprocess will also be terminated. * Fix timeout in base class * Run autopep8 * Fix issues with error logging * Dummy commit (empty line) to trigger CI * Set daemon with a flag for compatibility with Python 2 * Added error message if log file is not found * Refactored process termination * Refactor timeout mechanism * Run autopep8 * Restore error log * Add test for timeout with Dymola * pep8 * Added function that sleeps * Add tests and release notes * Fix Python version requirement Co-authored-by: Michael Wetter <[email protected]>
marcusfuchs · Nov 18, 2020 · 7f35d83 · 7f35d83
1 parent 797f8cd
commit 7f35d83
Show file tree

Hide file tree

Showing 13 changed files with 148 additions and 47 deletions.
diff --git a/Makefile b/Makefile
@@ -43,7 +43,6 @@ doctest:
 	@rm -f plot.pdf plot.png roomTemperatures.png dymola.log MyModel.mat dslog.txt package.order \
 	   run_simulate.mos run_translate.mos simulator.log translator.log
 
-
 dist:	clean doctest unittest doc
 	@# Make sure README.rst are consistent
 	cmp -s README.rst buildingspy/README.rst
@@ -55,7 +54,6 @@ dist:	clean doctest unittest doc
 	@echo "To post to server, run postBuildingsPyToWeb.sh"
 	@echo "To upload to PyPi, run 'twine upload dist/*'"
 
-
 upload-test:
 	@# Make sure README.rst are consistent
 	cmp -s README.rst buildingspy/README.rst

diff --git a/buildingspy/CHANGES.txt b/buildingspy/CHANGES.txt
@@ -4,6 +4,10 @@ BuildingsPy Changelog
 Version 2.2.0, xxx, 2020 -- Release 2.2
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - xxx
+- Corrected timeout handling in buildingspy.simulate.base_simulator.py
+  (https://github.com/lbl-srg/BuildingsPy/issues/385)
+- Corrected class name lookup mechanism in buildingspy.development.refactor.move_class()
+  (https://github.com/lbl-srg/BuildingsPy/issues/382)
 - For unit tests, added optional comment that is printed if a model is excluded from
   the tests (https://github.com/lbl-srg/BuildingsPy/issues/389)
 - Corrected generation of package.order for constant arrays (https://github.com/lbl-srg/BuildingsPy/issues/387)

diff --git a/buildingspy/development/jmodelica_run.template b/buildingspy/development/jmodelica_run.template
@@ -16,21 +16,24 @@ def process_with_timeout(target, timeout):
     manager = multiprocessing.Manager()
     return_dict = manager.dict()
     p = multiprocessing.Process(target=target, args=(0, return_dict))
+    p.daemon = True
     start = time.time()
     p.start()
     if timeout > 0:
         p.join(timeout)
     else:
         p.join()
 
-    cpu_time = time.time()-start
+    cpu_time = time.time() - start
 
-    if p.exitcode != 0:
-        if cpu_time >= timeout:
-            msg = "Process timeout"
-        else:
-            msg = "Process terminated by signal {}".format(-p.exitcode)
-        raise RuntimeError(msg)
+    error_msg = None
+    if p.is_alive():
+        error_msg = "Process timeout"
+        p.terminate()
+    elif p.exitcode != 0:
+        error_msg = "Process terminated by signal {}".format(-p.exitcode)
+    if error_msg is not None:
+        raise RuntimeError(error_msg)
 
     ret = copy.copy(return_dict[0])
     ret.update({'cpu_time': cpu_time})

diff --git a/buildingspy/development/optimica_run.template b/buildingspy/development/optimica_run.template
@@ -9,21 +9,24 @@ def process_with_timeout(target, timeout):
     manager = multiprocessing.Manager()
     return_dict = manager.dict()
     p = multiprocessing.Process(target=target, args=(0, return_dict))
+    p.daemon = True
     start = time.time()
     p.start()
     if timeout > 0:
         p.join(timeout)
     else:
         p.join()
 
-    cpu_time = time.time()-start
+    cpu_time = time.time() - start
 
-    if p.exitcode != 0:
-        if cpu_time >= timeout:
-            msg = "Process timeout"
-        else:
-            msg = "Process terminated by signal {}".format(-p.exitcode)
-        raise RuntimeError(msg)
+    error_msg = None
+    if p.is_alive():
+        error_msg = "Process timeout"
+        p.terminate()
+    elif p.exitcode != 0:
+        error_msg = "Process terminated by signal {}".format(-p.exitcode)
+    if error_msg is not None:
+        raise RuntimeError(error_msg)
 
     ret = copy.copy(return_dict[0])
     ret.update({'cpu_time': cpu_time})

diff --git a/buildingspy/simulate/Dymola.py b/buildingspy/simulate/Dymola.py
@@ -395,13 +395,19 @@ def _check_simulation_errors(self, worDir):
         import os
         from buildingspy.io.outputfile import get_errors_and_warnings
         path_to_logfile = os.path.join(worDir, 'simulator.log')
-        ret = get_errors_and_warnings(path_to_logfile, 'dymola')
-        if not ret["errors"]:
-            pass
+        # `simulator.log` may not exist in case of process timeout.
+        if os.path.exists(path_to_logfile):
+            ret = get_errors_and_warnings(path_to_logfile, 'dymola')
+            if not ret["errors"]:
+                pass
+            else:
+                for li in ret["errors"]:
+                    self._reporter.writeError(li)
+                raise IOError
         else:
-            for li in ret["errors"]:
-                self._reporter.writeError(li)
-            raise IOError
+            em = f"Log file {path_to_logfile} does not exist."
+            self._reporter.writeError(em)
+            raise IOError(em)
 
 # Classes that are inherited. These are listed here
 # so that they appear in the documentation.

diff --git a/buildingspy/simulate/Optimica.py b/buildingspy/simulate/Optimica.py
@@ -224,7 +224,7 @@ def _translate_and_simulate(self, simulate):
                     't1') is not None else 'mod.get_default_experiment_stop_time()',
                 result_file_name=f"{self._simulator_.get('resultFile')}.mat",
                 simulate=simulate,
-                time_out=-1,  # timeout is handled by BuildingsPy directly and not by the generated script
+                time_out=self._simulator_.get('timeout'),
                 filter=self._result_filter,
                 generate_html_diagnostics=self._generate_html_diagnostics,
                 debug_solver=self._debug_solver,

diff --git a/buildingspy/simulate/base_simulator.py b/buildingspy/simulate/base_simulator.py
@@ -273,7 +273,7 @@ def _deleteTemporaryDirectory(self, worDir):
 
         # For Dymola, walk one level up, since we appended the name of the current directory
         # to the name of the working directory
-        if self._simulator_ is 'dymola':
+        if self._MODELICA_EXE == 'dymola':
             dirNam = os.path.split(worDir)[0]
         else:
             dirNam = worDir
@@ -393,40 +393,56 @@ def _runSimulation(self, cmd, timeout, directory, env=None):
                                    shell=False,
                                    cwd=directory,
                                    env=osEnv)
-
+            timeout_exceeded = False
+            terminatedProcess = False
             killedProcess = False
+            # Tailored implementation of a timeout mechanism as it is not available
+            # through `wait` or `communicate` methods in Python 2.
             if timeout > 0:
-                while pro.poll() is None:
+                while not timeout_exceeded and pro.poll() is None:
                     time.sleep(0.01)
                     elapsedTime = (datetime.datetime.now() - self._simulationStartTime).seconds
-
                     if elapsedTime > timeout:
-                        # First, terminate the process. Then, if it is still
-                        # running, kill the process
+                        timeout_exceeded = True
+            else:
+                pro.wait()
 
-                        if self._showProgressBar and not killedProcess:
-                            killedProcess = True
-                            # This output needed because of the progress bar
-                            sys.stdout.write("\n")
-                            self._reporter.writeError("Terminating simulation in " +
-                                                      directory + ".")
-                            pro.terminate()
-                        else:
+            if timeout_exceeded:
+                # For Dymola only: manage process termination.
+                # (For Optimica and JModelica this is managed at the lower level
+                # in `*_run.template`.)
+                if self._MODELICA_EXE == 'dymola':
+                    # On unixlike systems, give the process a chance to close gracefully
+                    # using `terminate` (on Windows `terminate` and `kill` are aliases).
+                    # Then, if it is still running after `terminate_timeout`, kill the process.
+                    terminate_timeout = 5
+                    if self._showProgressBar:
+                        # This output needed because of the progress bar
+                        sys.stdout.write("\n")
+                    self._reporter.writeError("Terminating simulation in " +
+                                              directory + ".")
+                    pro.terminate()
+                    terminate_start_time = datetime.datetime.now()
+                    while not terminatedProcess and not killedProcess:
+                        time.sleep(0.1)
+                        elapsedTime = (datetime.datetime.now() - terminate_start_time).seconds
+                        if pro.poll() is not None:
+                            terminatedProcess = True
+                        if elapsedTime > terminate_timeout:
                             self._reporter.writeError("Killing simulation in " +
                                                       directory + ".")
                             pro.kill()
-                    else:
-                        if self._showProgressBar:
-                            fractionComplete = float(elapsedTime) / float(timeout)
-                            self._printProgressBar(fractionComplete)
-
+                            killedProcess = True
             else:
-                pro.wait()
+                if self._showProgressBar:
+                    fractionComplete = float(elapsedTime) / float(timeout)
+                    self._printProgressBar(fractionComplete)
+
             # This output is needed because of the progress bar
-            if self._showProgressBar and not killedProcess:
+            if self._showProgressBar and not terminatedProcess:
                 sys.stdout.write("\n")
 
-            if not killedProcess:
+            if (not terminatedProcess) and (not killedProcess):
                 std_out = pro.stdout.read()
                 if len(std_out) > 0:
                     self._reporter.writeOutput(
@@ -444,7 +460,7 @@ def _runSimulation(self, cmd, timeout, directory, env=None):
                             f"*** Standard error stream from simulation:\n{std_err}")
             else:
                 self._reporter.writeError(
-                    f"Killed process as it computed longer than {str(timeout)} seconds.")
+                    f"Process timeout: terminated process as it computed longer than {str(timeout)} seconds.")
 
             pro.stdout.close()
             pro.stderr.close()

diff --git a/buildingspy/tests/MyModelicaLibrary/MyModelTimeOut.mo b/buildingspy/tests/MyModelicaLibrary/MyModelTimeOut.mo
@@ -0,0 +1,16 @@
+within MyModelicaLibrary;
+model MyModelTimeOut
+  parameter Integer sec = 5 "Time for sleep in seconds";
+  Real r "Return value of mySleep";
+
+  function mySleep
+    input Integer sec "Sleep time in seconds";
+    output Integer r "Return value";
+    external "C" r = MySleep(sec)
+      annotation (
+       Include="#include <MySleep.c>",
+       IncludeDirectory="modelica://MyModelicaLibrary/Resources/C-Sources");
+  end mySleep;
+equation
+  r = mySleep(sec=sec);
+end MyModelTimeOut;
diff --git a/buildingspy/tests/MyModelicaLibrary/Resources/C-Sources/MySleep.c b/buildingspy/tests/MyModelicaLibrary/Resources/C-Sources/MySleep.c
@@ -0,0 +1,15 @@
+#ifdef _WIN32
+#include <Windows.h>
+#else
+#include <unistd.h>
+#endif
+
+int MySleep(int sec)
+{
+#ifdef _WIN32
+  Sleep(sec);
+  return 0;
+#else
+  return sleep(sec);
+#endif
+}
diff --git a/buildingspy/tests/MyModelicaLibrary/package.order b/buildingspy/tests/MyModelicaLibrary/package.order
@@ -1,4 +1,5 @@
 MyModel
+MyModelTimeOut
 MyStep
 Reset
 one

diff --git a/buildingspy/tests/test_simulate_Dymola.py b/buildingspy/tests/test_simulate_Dymola.py
@@ -178,6 +178,25 @@ def test_setBooleanParameterValues(self):
         # Delete output files
         s.deleteOutputFiles()
 
+    def test_timeout(self, timeout=3):
+        model = 'MyModelicaLibrary.MyModelTimeOut'
+        s = Simulator(
+            model,
+            packagePath=self._packagePath
+        )
+        s._deleteTemporaryDirectory = False
+        outDir = os.path.abspath(s.getOutputDirectory())
+        s.setTimeOut(timeout)
+        s.simulate()
+        with open(os.path.join(outDir, s._reporter._logFil)) as fh:
+            log = fh.read()
+        self.assertTrue('Terminating simulation' in log and 'Process timeout' in log)
+        s.setTimeOut(-1)
+        s.simulate()
+        with open(os.path.join(outDir, 'dslog.txt')) as fh:
+            log = fh.read()
+        self.assertTrue('Integration terminated successfully' in log)
+
 
 if __name__ == '__main__':
     unittest.main()
diff --git a/buildingspy/tests/test_simulate_Optimica.py b/buildingspy/tests/test_simulate_Optimica.py
@@ -271,6 +271,26 @@ def test_generateSolverDiagnostics(self):
         # Delete output files
         s.deleteOutputFiles()
 
+    def test_timeout(self, timeout=3):
+        model = 'MyModelicaLibrary.MyModelTimeOut'
+        json_log_file = '{}_buildingspy.json'.format(model.replace('.', '_'))
+        s = Simulator(
+            model,
+            packagePath=self._packagePath
+        )
+        s._deleteTemporaryDirectory = False
+        outDir = os.path.abspath(s.getOutputDirectory())
+        s.setTimeOut(timeout)
+        s.simulate()
+        with open(os.path.join(outDir, json_log_file)) as fh:
+            log = fh.read()
+        self.assertTrue('RuntimeError: Process timeout' in log)
+        s.setTimeOut(-1)
+        s.simulate()
+        with open(os.path.join(outDir, json_log_file)) as fh:
+            log = fh.read()
+        self.assertFalse('"success": false' in log)
+
 
 if __name__ == '__main__':
     unittest.main()
diff --git a/setup.py b/setup.py
@@ -31,7 +31,7 @@
     license="3-clause BSD",
     keywords="modelica dymola openmodelica mat",
     url="http://simulationresearch.lbl.gov/modelica/",
-    python_requires='!=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*, !=3.4.*, !=3.5.*',
+    python_requires='>=2.7, !=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*, !=3.4.*, !=3.5.*',
     install_requires=[
         'gitpython>=2.1',
         'jinja2>=2.10',