Add logging

conformers.py

@@ -4,6 +4,7 @@
 
 import argparse
 import json
+import logging
 import sys
 from pathlib import Path
 from shutil import copytree
@@ -12,6 +13,9 @@
 from opt import cleanup_after_opt
 
 
+logger = logging.getLogger(__name__)
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -199,3 +203,4 @@
 
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

docs.py

@@ -4,9 +4,17 @@
 
 import argparse
 import json
+import logging
 import sys
 import webbrowser
 
+
+logger = logging.getLogger(__name__)
+
+
+xtb_docs_url = "https://xtb-docs.readthedocs.io/en/latest/commandline.html"
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -30,11 +38,13 @@
         # Otherwise molecule disappears
         avo_input = json.loads(sys.stdin.read())
 
-        webbrowser.open("https://xtb-docs.readthedocs.io/en/latest/commandline.html")
+        logger.debug(f"Opening the xtb docs website at {xtb_docs_url}")
+        webbrowser.open(xtb_docs_url)
         result = {
             "message": "The xtb documentation should have opened in your browser.",
             "moleculeFormat": "cjson",
             "cjson": avo_input["cjson"],
         }
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

energy.py

@@ -4,13 +4,15 @@
 
 import argparse
 import json
+import logging
 import sys
-from pathlib import Path
-from shutil import rmtree
 
 from support import py_xtb
 
 
+logger = logging.getLogger(__name__)
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -41,6 +43,7 @@
         geom = py_xtb.Geometry.from_xyz(avo_input["xyz"].split("\n"))
 
         # Run calculation; returns energy as float in hartree
+        logger.debug("avo_xtb is requesting a single point energy calculation")
         energy_hartree = py_xtb.calc.energy(
             geom,
             charge=avo_input["charge"],
@@ -69,3 +72,4 @@
         result["cjson"]["properties"]["totalEnergy"] = str(round(energies["eV"], 7))
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

freq.py

@@ -4,11 +4,15 @@
 
 import argparse
 import json
+import logging
 import sys
 
 from support import py_xtb
 
 
+logger = logging.getLogger(__name__)
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -39,6 +43,7 @@
         geom = py_xtb.Geometry.from_xyz(avo_input["xyz"].split("\n"))
 
         # Run calculation; returns set of frequency data
+        logger.debug("avo_xtb is requesting a frequency calculation")
         freqs = py_xtb.calc.frequencies(
             geom,
             charge=avo_input["charge"],
@@ -68,3 +73,4 @@
 
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

install.py

@@ -6,6 +6,7 @@
 
 import argparse
 import json
+import logging
 import os
 import platform
 import sys
@@ -17,6 +18,9 @@
 from support import py_xtb
 
 
+logger = logging.getLogger(__name__)
+
+
 # For now just hard code the URLs of xtb and crest
 if platform.system() == "Windows":
     xtb_url = "https://github.com/grimme-lab/xtb/releases/download/v6.7.1/xtb-6.7.1pre-Windows-x86_64.zip"
@@ -211,3 +215,4 @@ def link_crest_bin(crest_folder):
 
         # Pass result back to Avogadro to display to user
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

ohess.py

@@ -4,12 +4,16 @@
 
 import argparse
 import json
+import logging
 import sys
 
 from support import py_xtb
 from opt import cleanup_after_opt
 
 
+logger = logging.getLogger(__name__)
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -40,6 +44,7 @@
         geom = py_xtb.Geometry.from_xyz(avo_input["xyz"].split("\n"))
 
         # Run calculation; returns path to Gaussian file containing frequencies
+        logger.debug("avo_xtb is requesting an opt+freq calculation")
         opt_geom, freqs, calc = py_xtb.calc.opt_freq(
             geom,
             charge=avo_input["charge"],
@@ -87,3 +92,4 @@
 
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

opt.py

@@ -4,11 +4,15 @@
 
 import argparse
 import json
+import logging
 import sys
 
 from support import py_xtb
 
 
+logger = logging.getLogger(__name__)
+
+
 def cleanup_after_opt(cjson: dict) -> dict:
     """Makes sure that any data that is no longer meaningful after a geometry change is
     removed from a CJSON structure."""
@@ -51,6 +55,7 @@ def cleanup_after_opt(cjson: dict) -> dict:
         geom = py_xtb.Geometry.from_xyz(avo_input["xyz"].split("\n"))
 
         # Run calculation; returns optimized geometry as well as Calculation object
+        logger.debug("avo_xtb is requesting a geometry optimization")
         opt_geom, calc = py_xtb.calc.optimize(
             geom,
             charge=avo_input["charge"],
@@ -88,3 +93,4 @@ def cleanup_after_opt(cjson: dict) -> dict:
 
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

orbitals.py

@@ -4,11 +4,15 @@
 
 import argparse
 import json
+import logging
 import sys
 
 from support import py_xtb
 
 
+logger = logging.getLogger(__name__)
+
+
 if __name__ == "__main__":
     parser = argparse.ArgumentParser()
     parser.add_argument("--debug", action="store_true")
@@ -39,6 +43,7 @@
         geom = py_xtb.Geometry.from_xyz(avo_input["xyz"].split("\n"))
 
         # Run calculation; returns Molden output file as string
+        logger.debug("avo_xtb is requesting a molecular orbitals calculation")
         molden_string = py_xtb.calc.orbitals(
             geom,
             charge=avo_input["charge"],
@@ -71,3 +76,4 @@
 
         # Pass back to Avogadro
         print(json.dumps(result))
+        logger.debug(f"The following dictionary was passed back to Avogadro: {result}")

py-xtb/src/py_xtb/__init__.py

@@ -1,4 +1,17 @@
-from .conf import config, config_file, CALC_DIR, TEMP_DIR, BIN_DIR, XTB_BIN, CREST_BIN
+import logging
+
+from .conf import config, config_file
+from .conf import PLUGIN_DIR, CALC_DIR, TEMP_DIR, BIN_DIR, XTB_BIN, CREST_BIN
 from .geometry import Atom, Geometry
 from .calc import Calculation
 from . import calc, conf, convert
+
+
+logger = logging.getLogger(__name__)
+logging.basicConfig(
+    filename="/home/matt/log.log",
+    filemode="w",
+    format="%(name)s:%(lineno)s: %(message)s",
+    encoding="utf-8",
+    level=logging.DEBUG,
+)

py-xtb/src/py_xtb/calc.py

@@ -15,6 +15,7 @@
 Both are designed to be run on `Geometry` objects.
 """
 
+import logging
 import os
 import subprocess
 from pathlib import Path
@@ -25,6 +26,9 @@
 from .parse import parse_energy, parse_g98_frequencies
 
 
+logger = logging.getLogger(__name__)
+
+
 class Calculation:
 
     def __init__(
@@ -63,11 +67,15 @@ def __init__(
         self.input_geometry = input_geometry
         if calc_dir:
             self.calc_dir = Path(calc_dir)
+        logger.info(f"New Calculation created for runtype {self.runtype} with {self.program.stem}")
 
     def run(self):
         """Run calculation with xtb or crest, storing the output, the saved output file,
         and the parsed energy, as well as the `subprocess` object."""
 
+        logger.debug(f"Calculation of runtype {self.runtype} has been asked to run")
+        logger.debug(f"The calculation will be run in the following directory: {self.calc_dir}")
+
         # Make sure directory nominated for calculation exists and is empty
         if self.calc_dir.exists():
             for x in self.calc_dir.iterdir():
@@ -80,12 +88,14 @@ def run(self):
 
         # Save geometry to file
         geom_file = self.calc_dir / "input.xyz"
+        logger.debug(f"Saving input geometry to {geom_file}")
         self.input_geometry.write_xyz(geom_file)
         # We are using proper paths for pretty much everything so it shouldn't be
         # necessary to change the working dir
         # But we do anyway to be absolutely that xtb runs correctly and puts all the
         # output here
         os.chdir(self.calc_dir)
+        logger.debug(f"Working directory changed to {Path.cwd()}")
         self.output_file = geom_file.with_name("output.out")
 
         if self.command:
@@ -116,15 +126,19 @@ def run(self):
                     continue
                 else:
                     command.extend([flag, str(value)])
+        logger.debug(f"Calculation will be run with the command: {' '.join(command)}")
 
         # Run xtb or crest from command line
+        logger.debug("Running calculation in new subprocess...")
         subproc = subprocess.run(command, capture_output=True, encoding="utf-8")
+        logger.debug("...calculation complete.")
 
         # Store output
         self.output = subproc.stdout
         # Also save it to file
         with open(self.output_file, "w", encoding="utf-8") as f:
             f.write(self.output)
+            logger.debug(f"Calculation output saved to {self.output_file}")
 
         # Store the subprocess.CompletedProcess object too
         self.subproc = subproc
@@ -140,22 +154,29 @@ def process_xtb(self):
         # First do generic operations that apply to many calculation types
         # Extract energy from output (if not found, returns None)
         self.energy = parse_energy(self.output)
+        logger.debug(f"Final energy parsed from output file: {self.energy}")
         # If there's an output geometry, read it
         if self.output_file.with_name("xtbopt.xyz").exists():
+            logger.debug(f"Output geometry found at {self.output_file.with_name('xtbopt.xyz')}")
             self.output_geometry = Geometry.from_file(self.output_file.with_name("xtbopt.xyz"))
+            logger.debug("Read output geometry")
         else:
             # Assume geom was the same at end of calc as at beginning
+            logger.debug("No output geometry found - final geometry assumed to be same as initial")
             self.output_geometry = self.input_geometry
         # Orbital info
         # If Molden output was requested, read the file
         if self.options.get("molden", False):
+            logger.debug("Molden output was requested, so checking for file")
             with open(self.output_file.with_name("molden.input"), encoding="utf-8") as f:
                 molden_string = f.read()
             self.output_molden = molden_string
+            logger.debug("Molden output was found and read")
 
         # Now do more specific operations based on calculation type
         match self.runtype:
             case "hess" | "ohess":
+                logger.debug("Frequencies were requested, so checking for file")
                 # Read the Gaussian output file with frequencies
                 with open(self.output_file.with_name("g98.out"), encoding="utf-8") as f:
                     g98_string = f.read()
@@ -167,19 +188,24 @@ def process_crest(self):
         match self.runtype:
             case "v1" | "v2" | "v2i" | "v3" | "v4" | None:
                 # Conformer search
+                logger.debug("A conformer search was requested, so checking for files")
                 # Get energy and geom of lowest conformer
                 best = Geometry.from_file(self.output_file.with_name("crest_best.xyz"))
+                logger.debug(f"Geometry of lowest energy conformer read from {self.output_file.with_name('crest_best.xyz')}")
                 self.output_geometry = best
                 self.energy = float(best._comment)
+                logger.debug(f"Energy of lowest energy conformer: {self.energy}")
                 # Get set of conformers
                 conformer_geoms = Geometry.from_file(
                     self.output_file.with_name("crest_conformers.xyz"),
                     multi=True,
                 )
+                logger.debug(f"Geometries of conformers read from {self.output_file.with_name('crest_conformers.xyz')}")
                 self.conformers = [
                     {"geometry": geom, "energy": float(geom._comment)}
                     for geom in conformer_geoms
                 ]
+                logger.debug(f"Found {len(self.conformers)} conformers in the ensemble")
             case _:
                 pass