Logging module follows python cookbook (#325)

* Improved logging

* black

* Respects logging level of Logger

* use tqdm.auto

* Uses tqdm.write context manager

* log + reformat

* fix test

* Better handling of children loggers

* Fix a test

archetypal/__init__.py

@@ -33,3 +33,4 @@
 from .idfclass import IDF
 from .eplus_interface.version import EnergyPlusVersion
 from .umi_template import UmiTemplateLibrary
+from .utils import config

archetypal/cli.py

@@ -216,10 +216,9 @@ def reduce(ctx, idf, output, weather, cores, all_zones, as_version):
     )
     log(
         f"executing {len(file_paths)} file(s):\n{file_list}",
-        verbose=True,
     )
     weather, *_ = set_filepaths([weather])
-    log(f"using the '{weather.basename()}' weather file\n", verbose=True)
+    log(f"using the '{weather.basename()}' weather file\n")
 
     # Call UmiTemplateLibrary constructor with list of IDFs
     template = UmiTemplateLibrary.from_idf_files(
@@ -236,7 +235,6 @@ def reduce(ctx, idf, output, weather, cores, all_zones, as_version):
     template.save(path_or_buf=final_path)
     log(
         f"Successfully created template file at {final_path.abspath()}",
-        verbose=True,
     )
 
 
@@ -301,7 +299,6 @@ def transition(idf, to_version, cores, yes):
     file_paths, file_list = idf
     log(
         f"executing {len(file_paths)} file(s):\n{file_list}",
-        verbose=True,
     )
     if not yes:
         overwrite = click.confirm("Would you like to overwrite the file(s)?")

archetypal/eplus_interface/basement.py

@@ -8,7 +8,8 @@
 
 from packaging.version import Version
 from path import Path
-from tqdm import tqdm
+from tqdm.auto import tqdm
+from tqdm.contrib.logging import logging_redirect_tqdm
 
 from archetypal.utils import log
 
@@ -90,50 +91,53 @@ def run(self):
         self.msg_callback(f"Weather File: {self.epw}")
 
         # Run Slab Program
-        with tqdm(
-            unit_scale=True,
-            miniters=1,
-            desc=f"RunBasement #{self.idf.position}-{self.idf.name}",
-            position=self.idf.position,
-        ) as progress:
-
-            self.p = subprocess.Popen(
-                self.cmd,
-                stdout=subprocess.PIPE,
-                stderr=subprocess.PIPE,
-                shell=True,  # can use shell
-                cwd=self.run_dir,
-            )
-            start_time = time.time()
-            self.msg_callback("Begin Basement Temperature Calculation processing . . .")
-
-            for line in self.p.stdout:
-                self.msg_callback(line.decode("utf-8").strip("\n"))
-                progress.update()
-
-            # We explicitly close stdout
-            self.p.stdout.close()
-
-            # Wait for process to complete
-            self.p.wait()
-
-            # Communicate callbacks
-            if self.cancelled:
-                self.msg_callback("RunSlab cancelled")
-                # self.cancelled_callback(self.std_out, self.std_err)
-            else:
-                if self.p.returncode == 0:
-                    self.msg_callback(
-                        "RunSlab completed in {:,.2f} seconds".format(
-                            time.time() - start_time
-                        )
-                    )
-                    self.success_callback()
-                    for line in self.p.stderr:
-                        self.msg_callback(line.decode("utf-8"))
+        with logging_redirect_tqdm():
+            with tqdm(
+                unit_scale=True,
+                miniters=1,
+                desc=f"RunBasement #{self.idf.position}-{self.idf.name}",
+                position=self.idf.position,
+            ) as progress:
+
+                self.p = subprocess.Popen(
+                    self.cmd,
+                    stdout=subprocess.PIPE,
+                    stderr=subprocess.PIPE,
+                    shell=True,  # can use shell
+                    cwd=self.run_dir,
+                )
+                start_time = time.time()
+                self.msg_callback(
+                    "Begin Basement Temperature Calculation processing . . ."
+                )
+
+                for line in self.p.stdout:
+                    self.msg_callback(line.decode("utf-8").strip("\n"))
+                    progress.update()
+
+                # We explicitly close stdout
+                self.p.stdout.close()
+
+                # Wait for process to complete
+                self.p.wait()
+
+                # Communicate callbacks
+                if self.cancelled:
+                    self.msg_callback("RunSlab cancelled")
+                    # self.cancelled_callback(self.std_out, self.std_err)
                 else:
-                    self.msg_callback("RunSlab failed")
-                    self.failure_callback()
+                    if self.p.returncode == 0:
+                        self.msg_callback(
+                            "RunSlab completed in {:,.2f} seconds".format(
+                                time.time() - start_time
+                            )
+                        )
+                        self.success_callback()
+                        for line in self.p.stderr:
+                            self.msg_callback(line.decode("utf-8"))
+                    else:
+                        self.msg_callback("RunSlab failed")
+                        self.failure_callback()
 
     def msg_callback(self, *args, **kwargs):
         """Pass message to logger."""

archetypal/eplus_interface/energy_plus.py

@@ -7,7 +7,8 @@
 import eppy
 from eppy.runner.run_functions import paths_from_version
 from path import Path
-from tqdm import tqdm
+from tqdm.auto import tqdm
+from tqdm.contrib.logging import logging_redirect_tqdm
 
 from archetypal.eplus_interface.exceptions import (
     EnergyPlusProcessError,
@@ -177,7 +178,7 @@ def run(self):
 
         # build a list of command line arguments
         try:
-            self.cmd = EnergyPlusExe(
+            eplus_exe = EnergyPlusExe(
                 idfname=self.idfname,
                 epw=self.epw,
                 output_directory=self.run_dir,
@@ -193,60 +194,64 @@ def run(self):
                 output_sufix=self.idf.output_suffix,
                 version=False,
                 expandobjects=self.idf.expandobjects,
-            ).cmd()
+            )
+            self.cmd = eplus_exe.cmd()
         except EnergyPlusVersionError as e:
             self.exception = e
             self.p.kill()  # kill process to be sure
             return
+        with logging_redirect_tqdm(loggers=[lg.getLogger(self.idf.name)]):
+            # Start process with tqdm bar
+            with tqdm(
+                unit_scale=False,
+                total=self.idf.energyplus_its if self.idf.energyplus_its > 0 else None,
+                miniters=1,
+                desc=f"{eplus_exe.eplus_exe_path} #{self.idf.position}-{self.idf.name}"
+                if self.idf.position
+                else f"{eplus_exe.eplus_exe_path} {self.idf.name}",
+                position=self.idf.position,
+            ) as progress:
+                self.p = subprocess.Popen(
+                    self.cmd,
+                    shell=False,
+                    stdout=subprocess.PIPE,
+                    stderr=subprocess.PIPE,
+                )
+                start_time = time.time()
+                self.msg_callback("Simulation started")
+                self.idf._energyplus_its = 0  # reset counter
+                for line in self.p.stdout:
+                    self.msg_callback(line.decode("utf-8").strip("\n"))
+                    self.idf._energyplus_its += 1
+                    progress.update()
 
-        # Start process with tqdm bar
-        with tqdm(
-            unit_scale=True,
-            total=self.idf.energyplus_its if self.idf.energyplus_its > 0 else None,
-            miniters=1,
-            desc=f"EnergyPlus #{self.idf.position}-{self.idf.name}"
-            if self.idf.position
-            else f"EnergyPlus {self.idf.name}",
-            position=self.idf.position,
-        ) as progress:
-            self.p = subprocess.Popen(
-                self.cmd,
-                shell=False,
-                stdout=subprocess.PIPE,
-                stderr=subprocess.PIPE,
-            )
-            start_time = time.time()
-            self.msg_callback("Simulation started")
-            self.idf._energyplus_its = 0  # reset counter
-            for line in self.p.stdout:
-                self.msg_callback(line.decode("utf-8").strip("\n"))
-                self.idf._energyplus_its += 1
-                progress.update()
-
-            # We explicitly close stdout
-            self.p.stdout.close()
+                # We explicitly close stdout
+                self.p.stdout.close()
 
-            # Wait for process to complete
-            self.p.wait()
+                # Wait for process to complete
+                self.p.wait()
 
-            # Communicate callbacks
-            if self.cancelled:
-                self.msg_callback("Simulation cancelled")
-                self.cancelled_callback(self.std_out, self.std_err)
-            else:
-                if self.p.returncode == 0:
-                    self.msg_callback(
-                        "EnergyPlus Completed in {:,.2f} seconds".format(
-                            time.time() - start_time
-                        )
-                    )
-                    self.success_callback()
+                # Communicate callbacks
+                if self.cancelled:
+                    self.msg_callback("Simulation cancelled")
+                    self.cancelled_callback(self.std_out, self.std_err)
                 else:
-                    self.msg_callback("Simulation failed")
-                    self.failure_callback()
+                    if self.p.returncode == 0:
+                        self.msg_callback(
+                            "EnergyPlus Completed in {:,.2f} seconds".format(
+                                time.time() - start_time
+                            )
+                        )
+                        self.success_callback()
+                    else:
+                        self.msg_callback("Simulation failed")
+                        self.failure_callback()
 
     def msg_callback(self, *args, **kwargs):
-        log(*args, name=self.idf.name, **kwargs)
+        msg, *_ = args
+        for m in msg.split("\r"):
+            if m:
+                log(m, name=self.idf.name, **kwargs)
 
     def success_callback(self):
         save_dir = self.idf.simulation_dir

archetypal/eplus_interface/expand_objects.py

@@ -1,5 +1,4 @@
 """ExpandObjects module"""
-
 import logging as lg
 import shutil
 import subprocess
@@ -8,14 +7,12 @@
 from subprocess import CalledProcessError
 from threading import Thread
 
-from eppy.runner.run_functions import paths_from_version
 from packaging.version import Version
 from path import Path
-from tqdm import tqdm
+from tqdm.auto import tqdm
+from tqdm.contrib.logging import logging_redirect_tqdm
 
 from archetypal.eplus_interface.energy_plus import EnergyPlusProgram
-from archetypal.eplus_interface.exceptions import EnergyPlusVersionError
-from archetypal.eplus_interface.version import EnergyPlusVersion
 from archetypal.utils import log
 
 
@@ -65,46 +62,47 @@ def run(self):
             self.run_dir = Path(tmp).expand()
 
             # Run ExpandObjects Program
-            self.cmd = ExpandObjectsExe(self.idf).cmd
-            with tqdm(
-                unit_scale=True,
-                miniters=1,
-                desc=f"ExpandObjects #{self.idf.position}-{self.idf.name}",
-                position=self.idf.position,
-            ) as progress:
-
-                self.p = subprocess.Popen(
-                    self.cmd,
-                    stdout=subprocess.PIPE,
-                    stderr=subprocess.PIPE,
-                    shell=True,  # can use shell
-                    cwd=self.run_dir.abspath(),
-                )
-                start_time = time.time()
-                # self.msg_callback("ExpandObjects started")
-                for line in self.p.stdout:
-                    self.msg_callback(line.decode("utf-8"))
-                    progress.update()
-
-                # We explicitly close stdout
-                self.p.stdout.close()
-
-                # Wait for process to complete
-                self.p.wait()
-
-                # Communicate callbacks
-                if self.cancelled:
-                    self.msg_callback("ExpandObjects cancelled")
-                    # self.cancelled_callback(self.std_out, self.std_err)
-                else:
-                    if self.p.returncode == 0:
-                        self.msg_callback(
-                            f"ExpandObjects completed in "
-                            f"{time.time() - start_time:,.2f} seconds"
-                        )
-                        self.success_callback()
+            with logging_redirect_tqdm():
+                self.cmd = ExpandObjectsExe(self.idf).cmd
+                with tqdm(
+                    unit_scale=True,
+                    miniters=1,
+                    desc=f"{expand_object_exe} #{self.idf.position}-{self.idf.name}",
+                    position=self.idf.position,
+                ) as progress:
+
+                    self.p = subprocess.Popen(
+                        self.cmd,
+                        stdout=subprocess.PIPE,
+                        stderr=subprocess.PIPE,
+                        shell=True,  # can use shell
+                        cwd=self.run_dir.abspath(),
+                    )
+                    start_time = time.time()
+                    # self.msg_callback("ExpandObjects started")
+                    for line in self.p.stdout:
+                        self.msg_callback(line.decode("utf-8").strip("\n"))
+                        progress.update()
+
+                    # We explicitly close stdout
+                    self.p.stdout.close()
+
+                    # Wait for process to complete
+                    self.p.wait()
+
+                    # Communicate callbacks
+                    if self.cancelled:
+                        self.msg_callback("ExpandObjects cancelled")
+                        # self.cancelled_callback(self.std_out, self.std_err)
                     else:
-                        self.failure_callback()
+                        if self.p.returncode == 0:
+                            self.msg_callback(
+                                f"ExpandObjects completed in "
+                                f"{time.time() - start_time:,.2f} seconds"
+                            )
+                            self.success_callback()
+                        else:
+                            self.failure_callback()
         except Exception as e:
             self.exception = e
             if self.p is not None: