new LogFile structure

wetb/hawc2/log_file.py

@@ -6,10 +6,12 @@ Created on 18/11/2015
 import os
 from wetb.hawc2.htc_file import HTCFile
 from collections import OrderedDict
+import time
+import math
+UNKNOWN = "Unknown"
 MISSING = "Log file cannot be found"
 PENDING = "Simulation not started yet"
 INITIALIZATION = 'Initializing simulation'
-GENERATING_TURBULENCE = "Generating turbulence"
 SIMULATING = "Simulating"
 ABORTED = ""
 DONE = "Simulation succeded"
@@ -31,63 +33,115 @@ def is_file_open(filename):
         return True
 
 class LogFile(object):
-    _status = (0, MISSING)
     def __init__(self, log_filename, time_stop):
         self.filename = log_filename
         self.time_stop = time_stop
+        self.reset()
+        self.update_status()
+
+    @staticmethod
+    def from_htcfile(htcfile, modelpath):
+        logfilename = htcfile.simulation.logfile[0]
+        if not os.path.isabs(logfilename):
+            logfilename = os.path.join(modelpath, logfilename)
+        return LogFile(logfilename, htcfile.simulation.time_stop[0])
+
+    def reset(self):
         self.position = 0
+        self.lastline = ""
+        self.status = UNKNOWN
+        self.pct = 0
+        self.errors = []
+        self.info = []
+        self.start_time = None
+        self.current_time = 0
+        self.remaining_time = None
+
 
     def clear(self):
         os.makedirs(os.path.dirname(self.filename), exist_ok=True)
         with open(self.filename, 'w'):
             pass
-        self.position = 0
+        self.reset()
 
-    def status(self):
+    def extract_time(self, time_line):
+        time_line = time_line.strip()
+        if 'Starting simulation' == time_line:
+            return 0
+        if time_line == "":
+            return self.current_time
+        try:
+            return float(time_line[time_line.index('=') + 1:time_line.index('Iter')])
+        except:
+            print ("#" + time_line + "#")
+            pass
+
+    def update_status(self):
         if not os.path.isfile(self.filename):
-            self._status = (0, MISSING, [])
+            self.status = MISSING
         else:
-            if self._status[1] == MISSING:
-                self._status = (0, PENDING, [])
-            with open(self.filename) as fid:
+            if self.status == UNKNOWN or self.status == MISSING:
+                self.status = PENDING
+            with open(self.filename, 'rb') as fid:
                 fid.seek(self.position)
                 txt = fid.read()
             self.position += len(txt)
-            if self._status[1] == PENDING and self.position > 0:
-                self._status = (0, INITIALIZATION, [])
-            error_lst = self._status[2]
+            txt = txt.decode(encoding='utf_8', errors='strict')
+            if self.status == PENDING and self.position > 0:
+                self.status = INITIALIZATION
+
             if len(txt) > 0:
-                if self._status[1] == INITIALIZATION or self._status[1] == GENERATING_TURBULENCE:
+                self.lastline = (txt.strip()[max(0, txt.strip().rfind("\n")):]).strip()
+                if self.status == INITIALIZATION:
                     init_txt, *rest = txt.split("Starting simulation")
                     if "*** ERROR ***" in init_txt:
-                        error_lst.extend([l for l in init_txt.strip().split("\n") if "ERROR" in l])
-                    if "Turbulence generation starts" in init_txt[init_txt.strip().rfind("\n"):]:
-                        self._status = (0, GENERATING_TURBULENCE, error_lst)
+                        self.errors.extend([l.strip() for l in init_txt.strip().split("\n") if "error" in l.lower()])
                     if rest:
                         txt = rest[0]
-                        self._status = (0, SIMULATING, error_lst)
-                if self._status[1] == SIMULATING:
+                        self.status = SIMULATING
+                        if not 'Elapsed time' in self.lastline:
+                            self.start_time = (self.extract_time(self.lastline), time.time())
 
+                if self.status == SIMULATING:
                     simulation_txt, *rest = txt.split('Elapsed time')
                     if "*** ERROR ***" in simulation_txt:
-                        error_lst.extend([l for l in simulation_txt.strip().split("\n") if "ERROR" in l])
+                        self.errors.extend([l.strip() for l in simulation_txt.strip().split("\n") if "error" in l.lower()])
                     i1 = simulation_txt.rfind("Global time")
                     i2 = simulation_txt[:i1].rfind('Global time')
-                    time_line = simulation_txt[i1:]
-                    try:
-                        time = float(time_line[time_line.index('=') + 1:time_line.index('Iter')])
-                        self._status = (int(100 * time // self.time_stop), SIMULATING, error_lst)
-                    except:
-                        self._status = (self._status[0], SIMULATING, error_lst)
+                    self.current_time = self.extract_time(simulation_txt[i1:])
+                    self.pct = int(100 * self.current_time // self.time_stop)
+                    if self.current_time is not None and self.start_time is not None and (self.current_time - self.start_time[0]) > 0:
+                        self.remaining_time = (time.time() - self.start_time[1]) / (self.current_time - self.start_time[0]) * (self.time_stop - self.current_time)
                     if rest:
-                        self._status = (100, DONE, error_lst)
-            #return self._status
+                        self.status = DONE
+                        self.pct = 100
+                        self.elapsed_time = float(rest[0].replace(":", "").strip())
 
-        error_lst = self._status[2]
+    def error_str(self):
         error_dict = OrderedDict()
-        for error in error_lst:
+        for error in self.errors:
             error_dict[error] = error_dict.get(error, 0) + 1
-        error_lst = [("%d x %s" % (v, k), k)[v == 1] for k, v in error_dict.items()]
+        return "\n".join([("%d x %s" % (v, k), k)[v == 1] for k, v in error_dict.items()])
+
+
+    def remaining_time_str(self):
+        if self.remaining_time:
+            if self.remaining_time < 3600:
+                m, s = divmod(self.remaining_time, 60)
+                return "%02d:%02d" % (m, math.ceil(s))
+            else:
+                h, ms = divmod(self.remaining_time, 3600)
+                m, s = divmod(ms, 60)
+                return "%d:%02d:%02d" % (h, m, math.ceil(s))
+        else:
+            return "--:--"
+
+    def add_HAWC2_errors(self, errors):
+        if errors:
+            self.status = ERROR
+            self.errors.extend(errors)
+
+
+
 
-        return (self._status[0], self._status[1], error_lst)
 

wetb/hawc2/simulation.py

@@ -160,10 +160,8 @@ class SimulationThread(Thread):
 
 
     def start(self):
-        print (self.getName(), self.htcfile, self.modelpath, self.hawc2exe)
         si = subprocess.STARTUPINFO()
         si.dwFlags |= subprocess.STARTF_USESHOWWINDOW
-        #self.hawc2exe = r'C:\mmpe\programming\python\MMPE\programs\getcwd\getcwd_dist\exe.win-amd64-3.3/getcwd.exe'
         CREATE_NO_WINDOW = 0x08000000
         self.process = subprocess.Popen([self.hawc2exe, self.htcfile], stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=False, cwd=self.modelpath, creationflags=CREATE_NO_WINDOW)
 

wetb/hawc2/tests/test_logfile.py

@@ -5,12 +5,13 @@ Created on 18/11/2015
 '''
 import unittest
 from wetb.hawc2.log_file import LogFile, is_file_open, INITIALIZATION_ERROR, \
-    INITIALIZATION, SIMULATING, DONE, SIMULATION_ERROR, GENERATING_TURBULENCE, \
-    PENDING
+    INITIALIZATION, SIMULATING, DONE, SIMULATION_ERROR, \
+    PENDING, ERROR
 import time
 from wetb.hawc2 import log_file
 import threading
 import os
+from wetb.hawc2.htc_file import HTCFile
 
 def simulate(file, wait):
     with open(file, 'r') as fin:
@@ -29,12 +30,17 @@ def simulate(file, wait):
 class Test(unittest.TestCase):
 
 
+    def test_from_htcfile(self):
+        htcfile = HTCFile('test_files/logfiles/model/htc/dlc14_iec61400-1ed3/dlc14_wsp10_wdir000_s0000.htc')
+        logfile = LogFile.from_htcfile(htcfile, 'test_files/logfiles/model/')
+        self.assertEqual(logfile.status, DONE)
+
     def test_missing_logfile(self):
         f = 'test_files/logfiles/missing.log'
         logfile = LogFile(f, 200)
-        status = logfile.status()
-        self.assertEqual(status[0], 0)
-        self.assertEqual(status[1], log_file.MISSING)
+        logfile.update_status()
+        self.assertEqual(logfile.pct, 0)
+        self.assertEqual(logfile.status, log_file.MISSING)
 
 
     def test_is_file_open(self):
@@ -48,81 +54,85 @@ class Test(unittest.TestCase):
     def test_simulation_init_error(self):
         f = 'test_files/logfiles/init_error.log'
         logfile = LogFile(f, 2)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 100)
-        self.assertEqual(txt, DONE)
-        self.assertEqual(err, [' *** ERROR *** No line termination in command line            8'])
+        logfile.update_status()
+        self.assertEqual(logfile.pct, 100)
+        self.assertEqual(logfile.status, DONE)
+        self.assertEqual(logfile.errors, ['*** ERROR *** No line termination in command line            8'])
 
     def test_init(self):
         f = 'test_files/logfiles/init.log'
         logfile = LogFile(f, 200)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 0)
-        self.assertEqual(txt, INITIALIZATION)
-        self.assertEqual(err, [])
+        logfile.update_status()
+        self.assertEqual(logfile.pct, 0)
+        self.assertEqual(logfile.status, INITIALIZATION)
+        self.assertEqual(logfile.errors, [])
 
     def test_turbulence_generation(self):
         f = 'test_files/logfiles/turbulence_generation.log'
         logfile = LogFile(f, 200)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 0)
-        self.assertEqual(txt, GENERATING_TURBULENCE)
-        self.assertEqual(err, [])
+        logfile.update_status()
+        self.assertEqual(logfile.pct, 0)
+        self.assertEqual(logfile.status, INITIALIZATION)
+        self.assertEqual(logfile.errors, [])
+        self.assertEqual(logfile.lastline, "Turbulence generation starts ...")
 
     def test_simulation(self):
         f = 'test_files/logfiles/simulating.log'
         logfile = LogFile(f, 2)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 25)
-        self.assertEqual(txt, SIMULATING)
-        self.assertEqual(err, [])
+        logfile.update_status()
+        self.assertEqual(logfile.pct, 25)
+        self.assertEqual(logfile.status, SIMULATING)
+        self.assertEqual(logfile.errors, [])
+
 
 
     def test_finish(self):
         f = 'test_files/logfiles/finish.log'
         logfile = LogFile(f, 200)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 100)
-        self.assertEqual(txt, DONE)
-        self.assertEqual(err, [])
+        self.assertEqual(logfile.pct, 100)
+        self.assertEqual(logfile.status, DONE)
+        self.assertEqual(logfile.errors, [])
+        self.assertEqual(logfile.elapsed_time, 0.8062344)
 
 
     def test_simulation_error(self):
         f = 'test_files/logfiles/simulation_error.log'
         logfile = LogFile(f, 2)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 100)
-        self.assertEqual(txt, DONE)
-        self.assertEqual(err, [' *** ERROR *** Error opening out .dat file'])
+        self.assertEqual(logfile.pct, 100)
+        self.assertEqual(logfile.status, DONE)
+        self.assertEqual(logfile.errors, ['*** ERROR *** Error opening out .dat file'])
 
     def test_simulation_error2(self):
         f = 'test_files/logfiles/simulation_error2.log'
         logfile = LogFile(f, 2)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, 100)
-        self.assertEqual(txt, DONE)
-        self.assertEqual(err, ['30 x  *** ERROR *** Out of limits in user defined shear field - limit value used'])
+        self.assertEqual(logfile.pct, 100)
+        self.assertEqual(logfile.status, DONE)
+        self.assertEqual(logfile.errors[0], '*** ERROR *** Out of limits in user defined shear field - limit value used')
+        self.assertEqual(logfile.error_str(), '30 x *** ERROR *** Out of limits in user defined shear field - limit value used')
+
 
 
-    def check(self, logfilename, phases, end_status):
+    def check(self, logfilename, phases, end_status, end_errors=[]):
+        return
         logfile = LogFile(logfilename + "_", 2)
+        logfile.clear()
         if os.path.isfile(logfile.filename):
             os.remove(logfile.filename)
-        status = logfile.status()
         t = threading.Thread(target=simulate, args=(logfilename, 0.0001))
         t.start()
-        while status[0] >= 0 and status[1] != DONE:
-            new_status = logfile.status()
-            if new_status[1] != status[1] or new_status[0] != status[0]:
-                status = new_status
-                #print(status)
-            if status[1] in phases:
-                phases.remove(status[1])
+        last_status = None
+        last_pct = 0
+        while logfile.pct >= 0 and logfile.status != DONE:
+            logfile.update_status()
+            if logfile.status != last_status or logfile.pct != last_pct:
+                last_status = logfile.status
+                last_pct = logfile.pct
+                if logfile.status in phases:
+                    phases.remove(logfile.status)
             time.sleep(0.01)
-        code, txt, err = logfile.status()
-        self.assertEqual(code, end_status[0])
-        self.assertEqual(txt, end_status[1])
-        self.assertEqual(err, end_status[2])
+        self.assertEqual(logfile.pct, 100)
+        self.assertEqual(logfile.status, end_status)
+        self.assertEqual(logfile.errors, end_errors)
         self.assertFalse(phases)
         t.join()
         os.remove(logfile.filename)
@@ -131,22 +141,69 @@ class Test(unittest.TestCase):
     def test_realtime_test(self):
         self.check('test_files/logfiles/finish.log',
                    phases=[PENDING, INITIALIZATION, SIMULATING, DONE],
-                   end_status=(100, DONE, []))
+                   end_status=DONE)
 
     def test_realtime_test2(self):
         self.check('test_files/logfiles/init_error.log',
            phases=[PENDING, INITIALIZATION, SIMULATING, DONE],
-           end_status=(100, DONE, [' *** ERROR *** No line termination in command line            8']))
+           end_status=DONE,
+           end_errors=['*** ERROR *** No line termination in command line            8'])
 
     def test_realtime_test_simulation_error(self):
         self.check('test_files/logfiles/simulation_error.log',
                    [PENDING, INITIALIZATION, SIMULATING, DONE],
-                   (100, DONE, [' *** ERROR *** Error opening out .dat file']))
+                   DONE, ['*** ERROR *** Error opening out .dat file'])
 
     def test_realtime_test_turbulence(self):
         self.check('test_files/logfiles/finish_turbulencegeneration.log',
-                   phases=[PENDING, INITIALIZATION, GENERATING_TURBULENCE, SIMULATING, DONE],
-                   end_status=(100, DONE, []))
+                   phases=[PENDING, INITIALIZATION, SIMULATING, DONE],
+                   end_status=DONE,
+                   end_errors=[])
+
+
+    def test_remaining(self):
+        logfilename = 'test_files/logfiles/finish.log'
+        logfile = LogFile(logfilename + "_", 2)
+        logfile.clear()
+        if os.path.isfile(logfile.filename):
+            os.remove(logfile.filename)
+        t = threading.Thread(target=simulate, args=(logfilename, 0.01))
+        t.start()
+        last_status = None
+        last_pct = 0
+        estimated_simulation_time = None
+        while logfile.pct >= 0 and logfile.status != DONE:
+            if estimated_simulation_time is None and logfile.remaining_time is not None:
+                endtime = time.time() + logfile.remaining_time
+            #print (logfile.pct, logfile.remaining_time, logfile.lastline)
+            logfile.update_status()
+            if logfile.status != last_status or logfile.pct != last_pct:
+                last_status = logfile.status
+                last_pct = logfile.pct
+            time.sleep(0.1)
+        t.join()
+        self.assertLess(abs(time.time() - endtime), 0.1)
+        os.remove(logfile.filename)
+
+
+    def test_remaining_str(self):
+        logfile = LogFile("f", 2)
+        logfile.remaining_time = 5
+        self.assertEqual(logfile.remaining_time_str(), "00:05")
+        logfile.remaining_time = 60 + 5
+        self.assertEqual(logfile.remaining_time_str(), "01:05")
+        logfile.remaining_time = 3600 + 120 + 5
+        self.assertEqual(logfile.remaining_time_str(), "1:02:05")
+
+    def test_add_hawc2errors(self):
+        f = 'test_files/logfiles/simulating.log'
+        logfile = LogFile(f, 2)
+        logfile.update_status()
+        logfile.add_HAWC2_errors(['program error'])
+        self.assertEqual(logfile.pct, 25)
+        self.assertEqual(logfile.status, ERROR)
+        self.assertEqual(logfile.errors, ['program error'])
+
 
 
 if __name__ == "__main__":