add logging (psi4#2512)

* add logger

* logging and efp

* Apply suggestions from code review

* Update build_planning.rst

.gitignore

@@ -54,6 +54,7 @@ input.py.dat
 *.molden
 *.cube
 dfh.*
+input.log
 
 *.json
 

CMakeLists.txt

@@ -41,7 +41,7 @@ message(STATUS "Building using CMake ${CMAKE_VERSION} Generator ${CMAKE_GENERATO
 #    - Python (also runtime; interpreter and headers; e.g., `conda install python`)
 #    - NumPy (also runtime; avoidable at buildtime if gau2grid pre-built; e.g., `conda install numpy`)
 #    - networkx >=2.4 (runtime only; e.g., `conda install networkx`)
-#    - pint (runtime only; e.g., `conda install pint -c conda-forge`)
+#    - pint >=0.10 (runtime only; e.g., `conda install pint -c conda-forge`)
 #    - pydantic >=1.0 (runtime only; e.g., `conda install pydantic -c conda-forge`)
 #    - msgpack-python (runtime only; e.g., `conda install msgpack-python`)
 #    - Eigen (for Libint2; e.g., `conda install eigen`)

doc/sphinxman/source/build_faq.rst

@@ -130,6 +130,7 @@ Running |PSIfour|
 #. :ref:`faq:psi4version`
 #. :ref:`faq:psi4PBS`
 #. :ref:`faq:psi4fileretention`
+#. :ref:`faq:logging`
 
 Runtime Errors and Debugging
 ----------------------------

doc/sphinxman/source/build_planning.rst

@@ -1856,3 +1856,28 @@ to your dev AddOn dynamic lib and update automatically when you rebuild
 the AddOn lib. Naturally, you may need to delete ``core.so`` and remake
 as needed.
 
+
+.. _`faq:logging`:
+
+How to use logging in Psi4
+--------------------------
+
+A log file is generated alongside the output file and has extension
+``.log``. Selected key information is sent to it. The log file contents
+are provisional and haphazard, so don't start relying upon them. It is
+tentatively envisioned that log files will have much of the same results as output
+files but more as structured data than narrative, nicely formatted data.
+In some cases where external calls are involved, the most detailed
+information may only be collectable in the log file. It is
+worthwhile to check the log file if expected results are missing from
+the usual output file. If the log file is empty, the logging level may
+be set too low.
+
+To change the logging level to DEBUG from the command-line::
+
+  >>> psi4 --logging 10
+
+To change the logging level to DEBUG in PsiAPI::
+
+  >>> psi4.set_output_file(<filebase>, loglevel=10)
+

doc/sphinxman/source/external.rst

@@ -495,6 +495,10 @@ Command-line arguments to |PSIfour| can be accessed through :option:`psi4 --help
    :envvar:`PSIDATADIR` and specifies the path to the Psi data
    library (ends in ``share/psi4``). Expert mode.
 
+.. option:: --loglevel <int>
+
+   Sets logging level: WARN=30, INFO=20, DEBUG=10.
+
 .. option:: -m, --messy
 
    Leave temporary files after the run is completed.

psi4/__init__.py

@@ -52,7 +52,7 @@
 # Init core
 from . import core
 
-from psi4.core import set_output_file, get_num_threads, set_num_threads
+from psi4.core import get_num_threads, set_num_threads
 core.initialize()
 
 if "PSI_SCRATCH" in os.environ.keys():
@@ -83,7 +83,7 @@
 from .metadata import __version__, version_formatter
 
 # A few extraneous functions
-from .extras import get_input_directory, addons, test
+from .extras import get_input_directory, addons, test, set_output_file
 from psi4.core import get_variable  # kill off in 1.4
 from psi4.core import variable, set_variable
 
@@ -97,3 +97,7 @@
     sys.path.insert(1, "@cppe_PYMOD@")
 if "@ENABLE_libefp@".upper() in ["1", "ON", "YES", "TRUE", "Y"]:  # pylibefp
     sys.path.insert(1, "@pylibefp_PYMOD@")
+
+# Create a custom logger
+import logging
+logger = logging.getLogger(__name__)

psi4/driver/__init__.py

@@ -30,6 +30,14 @@
 
 from . import dependency_check
 
+# printing and logging formatting niceties
+import pprint
+from functools import partial
+import numpy as np
+pp = pprint.PrettyPrinter(width=120, compact=True, indent=1)
+nppp = partial(np.array_str, max_line_width=120, precision=8, suppress_small=True)
+nppp10 = partial(np.array_str, max_line_width=120, precision=10, suppress_small=True)
+
 from qcelemental import constants
 from psi4.driver import psifiles as psif
 

psi4/driver/driver.py

@@ -36,6 +36,7 @@
 import re
 import shutil
 import sys
+import logging
 from typing import Union
 
 import numpy as np
@@ -47,13 +48,16 @@
 from psi4.driver import driver_findif
 from psi4.driver import p4util
 from psi4.driver import qcdb
+from psi4.driver import pp, nppp, nppp10
 from psi4.driver import qmmm
 from psi4.driver.procrouting import *
 from psi4.driver.p4util.exceptions import *
 from psi4.driver.mdi_engine import mdi_run
 
 # never import wrappers or aliases into this file
 
+logger = logging.getLogger(__name__)
+
 
 def _find_derivative_type(ptype, method_name, user_dertype):
     r"""
@@ -601,7 +605,10 @@ def energy(name, **kwargs):
             core.print_out(f" \n Copying restart file <{item}> to <{targetfile}> for internal processing\n")
             shutil.copy(item, targetfile)
 
+    logger.info(f"Compute energy(): method={lowername}, basis={core.get_global_option('BASIS').lower()}, molecule={molecule.name()}, nre={'w/EFP' if hasattr(molecule, 'EFP') else molecule.nuclear_repulsion_energy()}")
+    logger.debug("w/EFP" if hasattr(molecule, "EFP") else pp.pformat(molecule.to_dict()))
     wfn = procedures['energy'][lowername](lowername, molecule=molecule, **kwargs)
+    logger.info(f"Return energy(): {core.variable('CURRENT ENERGY')}")
 
     for postcallback in hooks['energy']['post']:
         postcallback(lowername, wfn=wfn, **kwargs)
@@ -747,7 +754,11 @@ def gradient(name, **kwargs):
         core.print_out("""gradient() will perform analytic gradient computation.\n""")
 
         # Perform the gradient calculation
+        logger.info(f"Compute gradient(): method={lowername}, basis={core.get_global_option('BASIS').lower()}, molecule={molecule.name()}, nre={'w/EFP' if hasattr(molecule, 'EFP') else molecule.nuclear_repulsion_energy()}")
+        logger.debug("w/EFP" if hasattr(molecule, "EFP") else pp.pformat(molecule.to_dict()))
         wfn = procedures['gradient'][lowername](lowername, molecule=molecule, **kwargs)
+        logger.info(f"Return gradient(): {core.variable('CURRENT ENERGY')}")
+        logger.info(nppp(wfn.gradient().np))
 
     else:
         core.print_out("""gradient() will perform gradient computation by finite difference of analytic energies.\n""")
@@ -917,7 +928,10 @@ def properties(*args, **kwargs):
 
     kwargs['properties'] = p4util.drop_duplicates(props)
     optstash = driver_util._set_convergence_criterion('properties', lowername, 6, 10, 6, 10, 8)
+    logger.info(f"Compute properties(): method={lowername}, basis={core.get_global_option('BASIS').lower()}, molecule={molecule.name()}, nre={'w/EFP' if hasattr(molecule, 'EFP') else molecule.nuclear_repulsion_energy()}")
+    logger.debug("w/EFP" if hasattr(molecule, "EFP") else pp.pformat(molecule.to_dict()))
     wfn = procedures['properties'][lowername](lowername, **kwargs)
+    logger.info(f"Return properties(): {core.variable('CURRENT ENERGY')}")
 
     optstash.restore()
 
@@ -1577,7 +1591,12 @@ def hessian(name, **kwargs):
         core.print_out("""hessian() will perform analytic frequency computation.\n""")
 
         # We have the desired method. Do it.
+        logger.info(f"Compute hessian(): method={lowername}, basis={core.get_global_option('BASIS').lower()}, molecule={molecule.name()}, nre={'w/EFP' if hasattr(molecule, 'EFP') else molecule.nuclear_repulsion_energy()}")
+        logger.debug("w/EFP" if hasattr(molecule, "EFP") else pp.pformat(molecule.to_dict()))
         wfn = procedures['hessian'][lowername](lowername, molecule=molecule, **kwargs)
+        logger.info(f"Return hessian(): {wfn.energy()}")
+        logger.info(nppp(wfn.hessian().np))
+
         wfn.set_gradient(G0)
         optstash.restore()
         optstash_conv.restore()

psi4/extras.py

@@ -31,6 +31,7 @@
 import itertools
 import os
 from typing import List, Union
+from pathlib import Path
 
 from qcelemental.util import which, which_import
 
@@ -224,3 +225,53 @@ def test(extent: str = "full", extras: List = None) -> int:
     retcode = pytest.main(command)
     return retcode
 
+
+def set_output_file(ofile: str, append: bool = False, *, loglevel: int = 20, execute: bool = True) -> Path:
+    """Set the name for output and logging files.
+
+    Parameters
+    ----------
+    ofile
+        Name of ASCII output file including extension. The logging file is set from this string with a ``.log`` extension.
+    append
+        Do append to the output and logging files rather than (the default) truncating them?
+    loglevel
+        The criticality level at which to log. 30 for WARN (Python default), 20 for INFO, 10 for DEBUG
+    execute
+        Do set ``ofile`` via :py:func:`psi4.core.set_output_file` and add the logger, rather than just returning ``ofile`` path.
+
+    Returns
+    -------
+    Path
+        ``Path(ofile)``
+
+    Notes
+    -----
+    This :py:func:`psi4.set_output_file` command calls :py:func:`psi4.core.set_output_file` and should be used in
+    preference to it as this additionally sets up logging.
+
+    """
+    out = Path(ofile)
+    log = out.with_suffix(".log")
+
+    # Get the custom logger
+    import logging
+    from psi4 import logger
+    logger.setLevel(loglevel)
+
+    # Create formatters
+    # * detailed:  example: 2019-11-20:01:13:46,811 DEBUG    [psi4.driver.task_base:156]
+    f_format_detailed = logging.Formatter("%(asctime)s,%(msecs)d %(levelname)-8s [%(name)s:%(lineno)d] %(message)s", datefmt="%Y-%m-%d:%H:%M:%S")
+    # * light:     example: 2019-11-20:10:45:21 FINDIFREC CLASS INIT DATA
+    f_format_light = logging.Formatter("%(asctime)s %(message)s", datefmt="%Y-%m-%d:%H:%M:%S")
+
+    # Create handlers, add formatters to handlers, and add handlers to logger (StreamHandler() also available)
+    filemode = "a" if append else "w"
+    f_handler = logging.FileHandler(log, filemode)
+    f_handler.setLevel(logging.DEBUG)
+    f_handler.setFormatter(f_format_detailed)
+
+    if execute:
+        core.set_output_file(str(out), append)
+        logger.addHandler(f_handler)
+    return out

psi4/run_psi4.py

@@ -45,7 +45,7 @@
 Redirect output elsewhere.
 Default: when input filename is 'input.dat', 'output.dat'.
 Otherwise, output filename defaults to input filename with
-any '.in' or 'dat' extension replaced by '.out'""")
+'.out' extension""")
 parser.add_argument("-a", "--append", action='store_true',
                     help="Appends results to output file. Default: Truncate first")
 parser.add_argument("-V", "--version", action='store_true',
@@ -79,6 +79,8 @@
                     help="Runs pytest tests. If `pytest-xdist` installed, parallel with `--nthread`.")
 parser.add_argument("--mdi", default=None,
                     help="Sets MDI configuration options")
+parser.add_argument("--loglevel", default=20,
+                    help="Sets logging level: WARN=30, INFO=20, DEBUG=10.")
 
 # For plugins
 parser.add_argument("--plugin-name", help="""\
@@ -140,21 +142,18 @@
 if (args["output"] is None) and (args["qcschema"] is False):
     if args["input"] == "input.dat":
         args["output"] = "output.dat"
-    elif args["input"].endswith(".in"):
-        args["output"] = args["input"][:-2] + "out"
-    elif args["input"].endswith(".dat"):
-        args["output"] = args["input"][:-3] + "out"
     else:
-        args["output"] = args["input"] + ".dat"
+        pinput = Path(args["input"])
+        presuffix = pinput.suffix if pinput.suffix in [".out", ".log"] else ""
+        args["output"] = str(pinput.with_suffix(presuffix + ".out"))
 
 # Plugin compile line
 if args['plugin_compile']:
     share_cmake_dir = os.path.sep.join([cmake_install_prefix, 'share', 'cmake', 'psi4'])
 
     plugincachealongside = os.path.isfile(share_cmake_dir + os.path.sep + 'psi4PluginCache.cmake')
     if plugincachealongside:
-        print("""cmake -C {}/psi4PluginCache.cmake -DCMAKE_PREFIX_PATH={} .""".format(
-            share_cmake_dir, cmake_install_prefix))
+        print(f"""cmake -C {share_cmake_dir}/psi4PluginCache.cmake -DCMAKE_PREFIX_PATH={cmake_install_prefix} .""")
         sys.exit()
     else:
         print("""Install "psi4-dev" via `conda install psi4-dev -c psi4[/label/dev]`, then reissue command.""")
@@ -224,7 +223,7 @@ def custom_formatwarning(msg, *args, **kwargs):
 if args["append"] is None:
     args["append"] = False
 if (args["output"] != "stdout") and (args["qcschema"] is False):
-    psi4.core.set_output_file(args["output"], args["append"])
+    psi4.set_output_file(args["output"], args["append"], loglevel=int(args["loglevel"]))
 
 # Set a few options
 psi4.core.set_num_threads(int(args["nthread"]), quiet=True)