From 44f8034cfe00c06a424688c359674ea6ad9798ed Mon Sep 17 00:00:00 2001 From: Jaime RGP Date: Mon, 27 Apr 2020 15:27:36 +0200 Subject: [PATCH 1/5] Add custom logging config and mimic support for verbose flags --- pymbar/__init__.py | 4 +++ pymbar/mbar.py | 68 ++++++++++++++++++++++---------------- pymbar/other_estimators.py | 35 ++++++++++++-------- pymbar/pmf.py | 31 ++++++++++------- pymbar/timeseries.py | 23 ++++++++----- pymbar/utils.py | 67 ++++++++++++++++++++++++++++++++++++- 6 files changed, 165 insertions(+), 63 deletions(-) diff --git a/pymbar/__init__.py b/pymbar/__init__.py index 56de3338..32463934 100644 --- a/pymbar/__init__.py +++ b/pymbar/__init__.py @@ -28,6 +28,10 @@ __maintainer__ = "Levi N. Naden, Michael R. Shirts and John D. Chodera" __email__ = "levi.naden@choderalab.org,michael.shirts@colorado.edu,john.chodera@choderalab.org" +from pymbar.utils import configure_logging + +configure_logging() + from pymbar import timeseries, testsystems, confidenceintervals from pymbar.mbar import MBAR from pymbar.other_estimators import bar, bar_zero, exp, exp_gauss diff --git a/pymbar/mbar.py b/pymbar/mbar.py index 5048d6ad..5927218c 100644 --- a/pymbar/mbar.py +++ b/pymbar/mbar.py @@ -49,6 +49,7 @@ DataError, logsumexp, check_w_normalized, + log_level, ) logger = logging.getLogger(__name__) @@ -217,7 +218,8 @@ def __init__( K, N = np.shape(u_kn) if verbose: - logger.info("K (total states) = {:d}, total samples = {:d}".format(K, N)) + with log_level(__name__, logging.INFO): + logger.info("K (total states) = {:d}, total samples = {:d}".format(K, N)) if np.sum(self.N_k) != N: raise ParameterError( @@ -286,8 +288,9 @@ def __init__( # Print number of samples from each state. if self.verbose: - logger.info("N_k = ") - logger.info(self.N_k) + with log_level(__name__, logging.INFO): + logger.info("N_k = ") + logger.info(self.N_k) # Determine list of k indices for which N_k != 0 self.states_with_samples = np.where(self.N_k != 0)[0] @@ -296,7 +299,8 @@ def __init__( # Number of states with samples. self.K_nonzero = self.states_with_samples.size if verbose: - logger.info("There are {:d} states with samples.".format(self.K_nonzero)) + with log_level(__name__, logging.INFO): + logger.info("There are {:d} states with samples.".format(self.K_nonzero)) # Initialize estimate of relative dimensionless free energy of each state to zero. # Note that f_k[0] will be constrained to be zero throughout. @@ -307,7 +311,8 @@ def __init__( # specified, start with that. if initial_f_k is not None: if self.verbose: - logger.info("Initializing f_k with provided initial guess.") + with log_level(__name__, logging.INFO): + logger.info("Initializing f_k with provided initial guess.") # Cast to np array. initial_f_k = np.array(initial_f_k, dtype=np.float64) # Check shape @@ -318,7 +323,8 @@ def __init__( # Initialize f_k with provided guess. self.f_k = initial_f_k if self.verbose: - logger.info(self.f_k) + with log_level(__name__, logging.INFO): + logger.info(self.f_k) # Shift all free energies such that f_0 = 0. self.f_k[:] = self.f_k[:] - self.f_k[0] else: @@ -326,11 +332,12 @@ def __init__( self._initializeFreeEnergies(verbose, method=initialize) if self.verbose: - logger.info( - "Initial dimensionless free energies with method {:s}".format(initialize) - ) - logger.info("f_k = ") - logger.info(self.f_k) + with log_level(__name__, logging.INFO): + logger.info( + "Initial dimensionless free energies with method {:s}".format(initialize) + ) + logger.info("f_k = ") + logger.info(self.f_k) if solver_protocol is None: solver_protocol = ({"method": None},) @@ -349,12 +356,14 @@ def __init__( # Print final dimensionless free energies. if self.verbose: - logger.info("Final dimensionless free energies") - logger.info("f_k = ") - logger.info(self.f_k) + with log_level(__name__, logging.INFO): + logger.info("Final dimensionless free energies") + logger.info("f_k = ") + logger.info(self.f_k) if self.verbose: - logger.info("MBAR initialization complete.") + with log_level(__name__, logging.INFO): + logger.info("MBAR initialization complete.") @property def W_nk(self): @@ -441,14 +450,15 @@ def compute_effective_sample_number(self, verbose=False): w = np.exp(self.Log_W_nk[:, k]) N_eff[k] = 1 / np.sum(w ** 2) if verbose: - logger.info( - "Effective number of sample in state {:d} is {:10.3f}".format(k, N_eff[k]) - ) - logger.info( - "Efficiency for state {:d} is {:6f}/{:d} = {:10.4f}".format( - k, N_eff[k], len(w), N_eff[k] / len(w) + with log_level(__name__, logging.INFO): + logger.info( + "Effective number of sample in state {:d} is {:10.3f}".format(k, N_eff[k]) + ) + logger.info( + "Efficiency for state {:d} is {:6f}/{:d} = {:10.4f}".format( + k, N_eff[k], len(w), N_eff[k] / len(w) + ) ) - ) return N_eff @@ -1360,7 +1370,8 @@ def compute_entropy_and_enthalpy( """ if verbose: - logger.info("Computing average energy and entropy by MBAR.") + with log_level(__name__, logging.INFO): + logger.info("Computing average energy and entropy by MBAR.") dims = len(np.shape(u_kn)) if dims == 3: @@ -1640,19 +1651,20 @@ def _initializeFreeEnergies(self, verbose=False, method="zeros"): * mean-reduced-potential: the mean reduced potential is used """ - if method == "zeros": # Use zeros for initial free energies. if verbose: - logger.info("Initializing free energies to zero.") + with log_level(__name__, logging.INFO): + logger.info("Initializing free energies to zero.") self.f_k[:] = 0.0 elif method == "mean-reduced-potential": # Compute initial guess at free energies from the mean reduced # potential from each state if verbose: - logger.info( - "Initializing free energies with mean reduced potential for each state." - ) + with log_level(__name__, logging.INFO): + logger.info( + "Initializing free energies with mean reduced potential for each state." + ) means = np.zeros([self.K], float) for k in self.states_with_samples: means[k] = self.u_kn[k, 0 : self.N_k[k]].mean() diff --git a/pymbar/other_estimators.py b/pymbar/other_estimators.py index ac878356..07e60f8d 100644 --- a/pymbar/other_estimators.py +++ b/pymbar/other_estimators.py @@ -48,7 +48,7 @@ # ============================================================================================= import logging import numpy as np -from pymbar.utils import ParameterError, ConvergenceError, BoundsError, logsumexp +from pymbar.utils import ParameterError, ConvergenceError, BoundsError, logsumexp, log_level logger = logging.getLogger(__name__) @@ -277,7 +277,8 @@ def bar( # if they have the same sign, they do not bracket. Widen the bracket until they have opposite signs. # There may be a better way to do this, and the above bracket should rarely fail. if verbose: - logger.info("Initial brackets did not actually bracket, widening them") + with log_level(__name__, logging.INFO): + logger.info("Initial brackets did not actually bracket, widening them") FAve = (UpperB + LowerB) / 2 UpperB = UpperB - max(abs(UpperB - FAve), 0.1) LowerB = LowerB + max(abs(LowerB - FAve), 0.1) @@ -304,7 +305,8 @@ def bar( if FNew == 0: # Convergence is achieved. if verbose: - logger.info("Convergence achieved.") + with log_level(__name__, logging.INFO): + logger.info("Convergence achieved.") relative_change = 10 ** (-15) break @@ -322,18 +324,21 @@ def bar( if DeltaF == 0.0: # The free energy difference appears to be zero -- return. if verbose: - logger.info("The free energy difference appears to be zero.") + with log_level(__name__, logging.INFO): + logger.info("The free energy difference appears to be zero.") break if iterated_solution: relative_change = abs((DeltaF - DeltaF_old) / DeltaF) if verbose: - logger.info("relative_change = {:12.3f}".format(relative_change)) + with log_level(__name__, logging.INFO): + logger.info("relative_change = {:12.3f}".format(relative_change)) if (iteration > 0) and (relative_change < relative_tolerance): # Convergence is achieved. if verbose: - logger.info("Convergence achieved.") + with log_level(__name__, logging.INFO): + logger.info("Convergence achieved.") break if method == "false-position" or method == "bisection": @@ -350,17 +355,19 @@ def bar( raise BoundsError(message) if verbose: - logger.info("iteration {:5d}: DeltaF = {:16.3f}".format(iteration, DeltaF)) + with log_level(__name__, logging.INFO): + logger.info("iteration {:5d}: DeltaF = {:16.3f}".format(iteration, DeltaF)) # Report convergence, or warn user if not achieved. if iterated_solution: if iteration < maximum_iterations: if verbose: - logger.info( - "Converged to tolerance of {:e} in {:d} iterations ({:d} function evaluations)".format( - relative_change, iteration, nfunc + with log_level(__name__, logging.INFO): + logger.info( + "Converged to tolerance of {:e} in {:d} iterations ({:d} function evaluations)".format( + relative_change, iteration, nfunc + ) ) - ) else: message = "WARNING: Did not converge to within specified tolerance. max_delta = {:f}, TOLERANCE = {:f}, MAX_ITS = {:d}".format( relative_change, relative_tolerance, maximum_iterations @@ -519,14 +526,16 @@ def bar( raise ParameterError(message) if verbose: - logger.info("DeltaF = {:8.3f} +- {:8.3f}".format(DeltaF, dDeltaF)) + with log_level(__name__, logging.INFO): + logger.info("DeltaF = {:8.3f} +- {:8.3f}".format(DeltaF, dDeltaF)) result_vals["Delta_f"] = DeltaF result_vals["dDelta_f"] = dDeltaF return result_vals else: if verbose: - logger.info("DeltaF = {:8.3f}".format(DeltaF)) + with log_level(__name__, logging.INFO): + logger.info("DeltaF = {:8.3f}".format(DeltaF)) result_vals["Delta_f"] = DeltaF return result_vals diff --git a/pymbar/pmf.py b/pymbar/pmf.py index 05214a09..e8fa71a1 100644 --- a/pymbar/pmf.py +++ b/pymbar/pmf.py @@ -26,7 +26,7 @@ import numpy as np import pymbar -from pymbar.utils import kln_to_kn, ParameterError, DataError, logsumexp +from pymbar.utils import kln_to_kn, ParameterError, DataError, logsumexp, log_level from pymbar import timeseries # bunch of imports needed for doing newton optimization of B-splines @@ -229,7 +229,8 @@ def __init__(self, u_kn, N_k, verbose=False, mbar_options=None, timings=True, ** # self._seed = None if self.verbose: - logger.info("PMF initialized") + with log_level(__name__, logging.INFO): + logger.info("PMF initialized") # TODO: see above about not storing np.random # @property @@ -1830,11 +1831,12 @@ def prob(x): csamples[:, n // sample_every] = results["c"] logposteriors[n // sample_every] = results["logposterior"] if n % print_every == 0 and verbose: - logger.info( - "MC Step {:d} of {:d}".format(n, niterations), - str(results["logposterior"]), - str(bspline.c), - ) + with log_level(__name__, logging.INFO): + logger.info( + "MC Step {:d} of {:d}".format(n, niterations), + str(results["logposterior"]), + str(bspline.c), + ) # We now have a distribution of samples of parameters sampled according # to the posterior. @@ -1844,7 +1846,8 @@ def prob(x): g_mc = None if verbose: - logger.info("Done MC sampling") + with log_level(__name__, logging.INFO): + logger.info("Done MC sampling") if decorrelate: t_mc, g_mc, Neff = timeseries.detect_equilibration(logposteriors) @@ -1854,12 +1857,14 @@ def prob(x): equil_logp = logposteriors[t_mc:] g_mc = timeseries.statistical_inefficiency(equil_logp) if verbose: - logger.info("Statistical inefficiency of log posterior is {:.3g}".format(g_mc)) + with log_level(__name__, logging.INFO): + logger.info("Statistical inefficiency of log posterior is {:.3g}".format(g_mc)) g_c = np.zeros(len(c)) for nc in range(len(c)): g_c[nc] = timeseries.statistical_inefficiency(csamples[nc, t_mc:]) if verbose: - logger.info("Time series for spline parameters are: {:s}".format(str(g_c))) + with log_level(__name__, logging.INFO): + logger.info("Time series for spline parameters are: {:s}".format(str(g_c))) maxgc = np.max(g_c) meangc = np.mean(g_c) guse = g_mc # doesn't affect the distribution that much @@ -1867,14 +1872,16 @@ def prob(x): logposteriors = equil_logp[indices] csamples = (csamples[:, t_mc:])[:, indices] if verbose: - logger.info("samples after decorrelation: {:d}".format(np.shape(csamples)[1])) + with log_level(__name__, logging.INFO): + logger.info("samples after decorrelation: {:d}".format(np.shape(csamples)[1])) self.mc_data["samples"] = csamples self.mc_data["logposteriors"] = logposteriors self.mc_data["mc_parameters"] = mc_parameters self.mc_data["acceptance_ratio"] = self.mc_data["naccept"] / niterations if verbose: - logger.info("Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"])) + with log_level(__name__, logging.INFO): + logger.info("Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"])) self.mc_data["nequil"] = t_mc # the start of the "equilibrated" data set self.mc_data["g_logposterior"] = g_mc # statistical efficiency of the log posterior self.mc_data["g_parameters"] = g_c # statistical efficiency of the parametere diff --git a/pymbar/timeseries.py b/pymbar/timeseries.py index fd336634..bded91ec 100644 --- a/pymbar/timeseries.py +++ b/pymbar/timeseries.py @@ -58,7 +58,7 @@ import logging import math import numpy as np -from pymbar.utils import ParameterError +from pymbar.utils import ParameterError, log_level # ============================================================================================= # Issue warning on import. @@ -734,16 +734,19 @@ def subsample_correlated_data(A_t, g=None, fast=False, conservative=False, verbo # Compute the statistical inefficiency for the timeseries. if not g: if verbose: - logger.info("Computing statistical inefficiency...") + with log_level(__name__, logging.INFO): + logger.info("Computing statistical inefficiency...") g = statistical_inefficiency(A_t, A_t, fast=fast) if verbose: - logger.info("g = {:f}".format(g)) + with log_level(__name__, logging.INFO): + logger.info("g = {:f}".format(g)) if conservative: # Round g up to determine the stride we can use to pick out regularly-spaced uncorrelated samples. stride = int(math.ceil(g)) if verbose: - logger.info("conservative subsampling: using stride of {:d}".format(stride)) + with log_level(__name__, logging.INFO): + logger.info("conservative subsampling: using stride of {:d}".format(stride)) # Assemble list of indices of uncorrelated snapshots. indices = range(0, T, stride) @@ -758,17 +761,19 @@ def subsample_correlated_data(A_t, g=None, fast=False, conservative=False, verbo indices.append(t) n += 1 if verbose: - logger.info("standard subsampling: using average stride of {:f}".format(g)) + with log_level(__name__, logging.INFO): + logger.info("standard subsampling: using average stride of {:f}".format(g)) # Number of samples in subsampled timeseries. N = len(indices) if verbose: - logger.info( - "The resulting subsampled set has {:d} samples (original timeseries had {:d}).".format( - N, T + with log_level(__name__, logging.INFO): + logger.info( + "The resulting subsampled set has {:d} samples (original timeseries had {:d}).".format( + N, T + ) ) - ) # Return the list of indices of uncorrelated snapshots. return indices diff --git a/pymbar/utils.py b/pymbar/utils.py index 26222d8f..09143d4a 100644 --- a/pymbar/utils.py +++ b/pymbar/utils.py @@ -24,7 +24,10 @@ ############################################################################## from itertools import zip_longest +from contextlib import contextmanager import warnings +import logging + import numpy as np import numexpr @@ -388,9 +391,71 @@ def check_w_normalized(W, N_k, tolerance=1.0e-4): return +# ============================================================================================ +# Logging utilities +# ============================================================================================ + +# Custom formatter +class PerLevelFormatter(logging.Formatter): + """ + Adapted from https://stackoverflow.com/a/14859558 + """ + + FORMATS = { + logging.ERROR: "ERROR! %(message)s", + logging.WARNING: "WARNING: %(message)s", + logging.INFO: "%(message)s", + logging.DEBUG: "Debug: %(module)s: %(lineno)d: %(message)s", + } + + def __init__(self, fmt="%(levelno)d: %(message)s", datefmt=None, style="%", **kwargs): + super().__init__(fmt=fmt, datefmt=datefmt, style=style, **kwargs) + + def format(self, record, *args, **kwargs): + + # Save the original format configured by the user + # when the logger formatter was instantiated + format_orig = self._style._fmt + self._style._fmt = self.FORMATS.get(record.levelno, self._style._fmt) + # Call the original formatter class to do the grunt work + result = super().format(record, *args, **kwargs) + # Restore the original format configured by the user + self._style._fmt = format_orig + + return result + + +def configure_logging(level=logging.WARNING): + """ + Basic configuration for the project, with a custom formatter + """ + logger = logging.getLogger(__name__.split(".", 1)[0]) + logger.setLevel(level) + + handler = logging.StreamHandler() + formatter = PerLevelFormatter() + handler.setFormatter(formatter) + + logger.addHandler(handler) + + +@contextmanager +def log_level(name, level=logging.INFO): + """ + Context manager to change the logging level for a block. + """ + logger = logging.getLogger(name) + current_level = logger.getEffectiveLevel() + logger.setLevel(level) + try: + yield + finally: + logger.setLevel(current_level) + + # ============================================================================================ # Exception classes -# ============================================================================================= +# ============================================================================================ class ParameterError(Exception): From 8085892ec181c81751a0ed20ad3918c9db08af4f Mon Sep 17 00:00:00 2001 From: Jaime RGP Date: Mon, 27 Apr 2020 16:18:52 +0200 Subject: [PATCH 2/5] Satisfy linter --- pymbar/utils.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pymbar/utils.py b/pymbar/utils.py index 09143d4a..b4b0ad10 100644 --- a/pymbar/utils.py +++ b/pymbar/utils.py @@ -411,14 +411,14 @@ class PerLevelFormatter(logging.Formatter): def __init__(self, fmt="%(levelno)d: %(message)s", datefmt=None, style="%", **kwargs): super().__init__(fmt=fmt, datefmt=datefmt, style=style, **kwargs) - def format(self, record, *args, **kwargs): + def format(self, record): # Save the original format configured by the user # when the logger formatter was instantiated format_orig = self._style._fmt self._style._fmt = self.FORMATS.get(record.levelno, self._style._fmt) # Call the original formatter class to do the grunt work - result = super().format(record, *args, **kwargs) + result = super().format(record) # Restore the original format configured by the user self._style._fmt = format_orig From e56fc1f35f0ab55e164c39a64619580af86b74aa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jaime=20Rodr=C3=ADguez-Guerra?= Date: Tue, 28 Apr 2020 10:33:37 +0200 Subject: [PATCH 3/5] Readapt logging machinery to use a new keyword force_emit that overrides levels for that message --- pymbar/__init__.py | 4 +- pymbar/logging_utils.py | 146 +++++++++++++++++++++++++++++++++++++ pymbar/mbar.py | 90 +++++++++-------------- pymbar/other_estimators.py | 55 ++++++-------- pymbar/pmf.py | 40 ++++------ pymbar/timeseries.py | 35 ++++----- pymbar/utils.py | 64 ---------------- 7 files changed, 235 insertions(+), 199 deletions(-) create mode 100644 pymbar/logging_utils.py diff --git a/pymbar/__init__.py b/pymbar/__init__.py index 32463934..94287079 100644 --- a/pymbar/__init__.py +++ b/pymbar/__init__.py @@ -28,9 +28,9 @@ __maintainer__ = "Levi N. Naden, Michael R. Shirts and John D. Chodera" __email__ = "levi.naden@choderalab.org,michael.shirts@colorado.edu,john.chodera@choderalab.org" -from pymbar.utils import configure_logging +from pymbar.logging_utils import setup_logging -configure_logging() +setup_logging() from pymbar import timeseries, testsystems, confidenceintervals from pymbar.mbar import MBAR diff --git a/pymbar/logging_utils.py b/pymbar/logging_utils.py new file mode 100644 index 00000000..3e634e71 --- /dev/null +++ b/pymbar/logging_utils.py @@ -0,0 +1,146 @@ +""" +Utilities for our custom logging features +""" +from contextlib import contextmanager +import logging + + +class ForceEmitLogger(logging.Logger): + def log(self, level, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if not isinstance(level, int): + if logging.raiseExceptions: + raise TypeError("level must be an integer") + else: + return + if self.isEnabledFor(level): + self._log(level, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(level): + self._log(level, msg, args, **kwargs) + + def debug(self, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if self.isEnabledFor(logging.DEBUG): + self._log(logging.DEBUG, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(logging.DEBUG): + self._log(logging.DEBUG, msg, args, **kwargs) + + def info(self, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if self.isEnabledFor(logging.INFO): + self._log(logging.INFO, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(logging.INFO): + self._log(logging.INFO, msg, args, **kwargs) + + def warning(self, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if self.isEnabledFor(logging.WARNING): + self._log(logging.WARNING, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(logging.INFO): + self._log(logging.INFO, msg, args, **kwargs) + + def error(self, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if self.isEnabledFor(logging.ERROR): + self._log(logging.ERROR, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(logging.ERROR): + self._log(logging.ERROR, msg, args, **kwargs) + + def critical(self, msg, *args, **kwargs): + """ + Do what ``logging.Logger`` does, but offer to override all + level thresholds if ``force_emit=True`` is passed to the + ``.log()`` call. + """ + if self.isEnabledFor(logging.CRITICAL): + self._log(logging.CRITICAL, msg, args, **kwargs) + elif kwargs.pop("force_emit", None): + with self.temporary_level(logging.CRITICAL): + self._log(logging.CRITICAL, msg, args, **kwargs) + + @contextmanager + def temporary_level(self, level=logging.INFO): + """ + Context manager to change the logging level for a block. + """ + logger_level = self.getEffectiveLevel() + handler_levels = [h.level for h in self.handlers] + self.setLevel(level) + try: + yield + finally: + self.setLevel(logger_level) + for handler, handler_level in zip(self.handlers, handler_levels): + handler.level = handler_level + + +class PerLevelFormatter(logging.Formatter): + """ + Adapted from https://stackoverflow.com/a/14859558 + """ + + FORMATS = { + logging.ERROR: "ERROR! %(message)s", + logging.WARNING: "WARNING: %(message)s", + logging.INFO: "%(message)s", + logging.DEBUG: "Debug: %(message)s", + } + + def __init__(self, fmt="%(levelno)d: %(message)s", datefmt=None, style="%", **kwargs): + super().__init__(fmt=fmt, datefmt=datefmt, style=style, **kwargs) + + def format(self, record): + + # Save the original format configured by the user + # when the logger formatter was instantiated + format_orig = self._style._fmt + self._style._fmt = self.FORMATS.get(record.levelno, self._style._fmt) + # Call the original formatter class to do the grunt work + result = super().format(record) + # Restore the original format configured by the user + self._style._fmt = format_orig + + return result + + +def setup_logging(level=logging.WARNING): + """ + Basic configuration for the project, with a custom formatter + """ + logging.setLoggerClass(ForceEmitLogger) + logger = logging.getLogger(__name__.split(".", 1)[0]) + handler = logging.StreamHandler() + formatter = PerLevelFormatter() + handler.setFormatter(formatter) + logger.addHandler(handler) + configure_logging_level(level) + + +def configure_logging_level(level): + logger = logging.getLogger(__name__.split(".", 1)[0]) + logger.setLevel(level) diff --git a/pymbar/mbar.py b/pymbar/mbar.py index 5927218c..1ca0e863 100644 --- a/pymbar/mbar.py +++ b/pymbar/mbar.py @@ -49,7 +49,6 @@ DataError, logsumexp, check_w_normalized, - log_level, ) logger = logging.getLogger(__name__) @@ -217,9 +216,9 @@ def __init__( K, N = np.shape(u_kn) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("K (total states) = {:d}, total samples = {:d}".format(K, N)) + logger.info( + "K (total states) = {:d}, total samples = {:d}".format(K, N), force_emit=verbose + ) if np.sum(self.N_k) != N: raise ParameterError( @@ -287,10 +286,8 @@ def __init__( logger.warning(dedent(msg[1:])) # Print number of samples from each state. - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info("N_k = ") - logger.info(self.N_k) + logger.info("N_k = ", force_emit=verbose) + logger.info(self.N_k, force_emit=verbose) # Determine list of k indices for which N_k != 0 self.states_with_samples = np.where(self.N_k != 0)[0] @@ -298,9 +295,9 @@ def __init__( # Number of states with samples. self.K_nonzero = self.states_with_samples.size - if verbose: - with log_level(__name__, logging.INFO): - logger.info("There are {:d} states with samples.".format(self.K_nonzero)) + logger.info( + "There are {:d} states with samples.".format(self.K_nonzero), force_emit=verbose + ) # Initialize estimate of relative dimensionless free energy of each state to zero. # Note that f_k[0] will be constrained to be zero throughout. @@ -310,9 +307,7 @@ def __init__( # If an initial guess of the relative dimensionless free energies is # specified, start with that. if initial_f_k is not None: - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info("Initializing f_k with provided initial guess.") + logger.info("Initializing f_k with provided initial guess.", force_emit=verbose) # Cast to np array. initial_f_k = np.array(initial_f_k, dtype=np.float64) # Check shape @@ -322,22 +317,19 @@ def __init__( ) # Initialize f_k with provided guess. self.f_k = initial_f_k - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info(self.f_k) + logger.info(self.f_k, force_emit=verbose) # Shift all free energies such that f_0 = 0. self.f_k[:] = self.f_k[:] - self.f_k[0] else: # Initialize estimate of relative dimensionless free energies. self._initializeFreeEnergies(verbose, method=initialize) - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info( - "Initial dimensionless free energies with method {:s}".format(initialize) - ) - logger.info("f_k = ") - logger.info(self.f_k) + logger.info( + "Initial dimensionless free energies with method {:s}".format(initialize), + force_emit=verbose, + ) + logger.info("f_k = ", force_emit=verbose) + logger.info(self.f_k, force_emit=verbose) if solver_protocol is None: solver_protocol = ({"method": None},) @@ -355,15 +347,10 @@ def __init__( self.Log_W_nk = mbar_solvers.mbar_log_W_nk(self.u_kn, self.N_k, self.f_k) # Print final dimensionless free energies. - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info("Final dimensionless free energies") - logger.info("f_k = ") - logger.info(self.f_k) - - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info("MBAR initialization complete.") + logger.info("Final dimensionless free energies", force_emit=verbose) + logger.info("f_k = ", force_emit=verbose) + logger.info(self.f_k, force_emit=verbose) + logger.info("MBAR initialization complete.", force_emit=verbose) @property def W_nk(self): @@ -449,16 +436,16 @@ def compute_effective_sample_number(self, verbose=False): for k in range(self.K): w = np.exp(self.Log_W_nk[:, k]) N_eff[k] = 1 / np.sum(w ** 2) - if verbose: - with log_level(__name__, logging.INFO): - logger.info( - "Effective number of sample in state {:d} is {:10.3f}".format(k, N_eff[k]) - ) - logger.info( - "Efficiency for state {:d} is {:6f}/{:d} = {:10.4f}".format( - k, N_eff[k], len(w), N_eff[k] / len(w) - ) - ) + logger.info( + "Effective number of sample in state {:d} is {:10.3f}".format(k, N_eff[k]), + force_emit=verbose, + ) + logger.info( + "Efficiency for state {:d} is {:6f}/{:d} = {:10.4f}".format( + k, N_eff[k], len(w), N_eff[k] / len(w) + ), + force_emit=verbose, + ) return N_eff @@ -1369,9 +1356,7 @@ def compute_entropy_and_enthalpy( >>> results = mbar.compute_entropy_and_enthalpy() """ - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Computing average energy and entropy by MBAR.") + logger.info("Computing average energy and entropy by MBAR.", force_emit=verbose) dims = len(np.shape(u_kn)) if dims == 3: @@ -1653,18 +1638,15 @@ def _initializeFreeEnergies(self, verbose=False, method="zeros"): """ if method == "zeros": # Use zeros for initial free energies. - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Initializing free energies to zero.") + logger.info("Initializing free energies to zero.", force_emit=verbose) self.f_k[:] = 0.0 elif method == "mean-reduced-potential": # Compute initial guess at free energies from the mean reduced # potential from each state - if verbose: - with log_level(__name__, logging.INFO): - logger.info( - "Initializing free energies with mean reduced potential for each state." - ) + logger.info( + "Initializing free energies with mean reduced potential for each state.", + force_emit=verbose, + ) means = np.zeros([self.K], float) for k in self.states_with_samples: means[k] = self.u_kn[k, 0 : self.N_k[k]].mean() diff --git a/pymbar/other_estimators.py b/pymbar/other_estimators.py index 07e60f8d..d912b773 100644 --- a/pymbar/other_estimators.py +++ b/pymbar/other_estimators.py @@ -48,7 +48,7 @@ # ============================================================================================= import logging import numpy as np -from pymbar.utils import ParameterError, ConvergenceError, BoundsError, logsumexp, log_level +from pymbar.utils import ParameterError, ConvergenceError, BoundsError, logsumexp logger = logging.getLogger(__name__) @@ -262,7 +262,9 @@ def bar( # this data set is returning NAN -- will likely not work. Return 0, print a warning: # consider returning more information about failure logger.warning( - "BAR is likely to be inaccurate because of poor overlap. Improve the sampling, or decrease the spacing betweeen states. For now, guessing that the free energy difference is 0 with no uncertainty." + "BAR is likely to be inaccurate because of poor overlap. " + "Improve the sampling, or decrease the spacing betweeen states. " + "For now, guessing that the free energy difference is 0 with no uncertainty." ) if compute_uncertainty: result_vals["Delta_f"] = 0.0 @@ -276,9 +278,9 @@ def bar( while FUpperB * FLowerB > 0: # if they have the same sign, they do not bracket. Widen the bracket until they have opposite signs. # There may be a better way to do this, and the above bracket should rarely fail. - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Initial brackets did not actually bracket, widening them") + logger.info( + "Initial brackets did not actually bracket, widening them", force_emit=verbose + ) FAve = (UpperB + LowerB) / 2 UpperB = UpperB - max(abs(UpperB - FAve), 0.1) LowerB = LowerB + max(abs(LowerB - FAve), 0.1) @@ -304,9 +306,7 @@ def bar( if FNew == 0: # Convergence is achieved. - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Convergence achieved.") + logger.info("Convergence achieved.", force_emit=verbose) relative_change = 10 ** (-15) break @@ -323,22 +323,16 @@ def bar( # Check for convergence. if DeltaF == 0.0: # The free energy difference appears to be zero -- return. - if verbose: - with log_level(__name__, logging.INFO): - logger.info("The free energy difference appears to be zero.") + logger.info("The free energy difference appears to be zero.", force_emit=verbose) break if iterated_solution: relative_change = abs((DeltaF - DeltaF_old) / DeltaF) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("relative_change = {:12.3f}".format(relative_change)) + logger.info("relative_change = {:12.3f}".format(relative_change), force_emit=verbose) if (iteration > 0) and (relative_change < relative_tolerance): # Convergence is achieved. - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Convergence achieved.") + logger.info("Convergence achieved.", force_emit=verbose) break if method == "false-position" or method == "bisection": @@ -354,20 +348,19 @@ def bar( message = "WARNING: Cannot determine bound on free energy" raise BoundsError(message) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("iteration {:5d}: DeltaF = {:16.3f}".format(iteration, DeltaF)) + logger.info( + "iteration {:5d}: DeltaF = {:16.3f}".format(iteration, DeltaF), force_emit=verbose + ) # Report convergence, or warn user if not achieved. if iterated_solution: if iteration < maximum_iterations: - if verbose: - with log_level(__name__, logging.INFO): - logger.info( - "Converged to tolerance of {:e} in {:d} iterations ({:d} function evaluations)".format( - relative_change, iteration, nfunc - ) - ) + logger.info( + "Converged to tolerance of {:e} in {:d} iterations ({:d} function evaluations)".format( + relative_change, iteration, nfunc + ), + force_emit=verbose, + ) else: message = "WARNING: Did not converge to within specified tolerance. max_delta = {:f}, TOLERANCE = {:f}, MAX_ITS = {:d}".format( relative_change, relative_tolerance, maximum_iterations @@ -525,17 +518,13 @@ def bar( ) raise ParameterError(message) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("DeltaF = {:8.3f} +- {:8.3f}".format(DeltaF, dDeltaF)) + logger.info("DeltaF = {:8.3f} +- {:8.3f}".format(DeltaF, dDeltaF), force_emit=verbose) result_vals["Delta_f"] = DeltaF result_vals["dDelta_f"] = dDeltaF return result_vals else: - if verbose: - with log_level(__name__, logging.INFO): - logger.info("DeltaF = {:8.3f}".format(DeltaF)) + logger.info("DeltaF = {:8.3f}".format(DeltaF), force_emit=verbose) result_vals["Delta_f"] = DeltaF return result_vals diff --git a/pymbar/pmf.py b/pymbar/pmf.py index e8fa71a1..ffd436ae 100644 --- a/pymbar/pmf.py +++ b/pymbar/pmf.py @@ -26,7 +26,7 @@ import numpy as np import pymbar -from pymbar.utils import kln_to_kn, ParameterError, DataError, logsumexp, log_level +from pymbar.utils import kln_to_kn, ParameterError, DataError, logsumexp from pymbar import timeseries # bunch of imports needed for doing newton optimization of B-splines @@ -228,9 +228,7 @@ def __init__(self, u_kn, N_k, verbose=False, mbar_options=None, timings=True, ** # self._random = np.random # self._seed = None - if self.verbose: - with log_level(__name__, logging.INFO): - logger.info("PMF initialized") + logger.info("PMF initialized", force_emit=verbose) # TODO: see above about not storing np.random # @property @@ -1830,13 +1828,13 @@ def prob(x): if n % sample_every == 0: csamples[:, n // sample_every] = results["c"] logposteriors[n // sample_every] = results["logposterior"] - if n % print_every == 0 and verbose: - with log_level(__name__, logging.INFO): - logger.info( - "MC Step {:d} of {:d}".format(n, niterations), - str(results["logposterior"]), - str(bspline.c), - ) + if n % print_every == 0: + logger.info( + "MC Step {:d} of {:d}".format(n, niterations), + str(results["logposterior"]), + str(bspline.c), + force_emit=verbose, + ) # We now have a distribution of samples of parameters sampled according # to the posterior. @@ -1845,9 +1843,7 @@ def prob(x): t_mc = 0 g_mc = None - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Done MC sampling") + logger.info("Done MC sampling", force_emit=verbose) if decorrelate: t_mc, g_mc, Neff = timeseries.detect_equilibration(logposteriors) @@ -1856,32 +1852,24 @@ def prob(x): ) equil_logp = logposteriors[t_mc:] g_mc = timeseries.statistical_inefficiency(equil_logp) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Statistical inefficiency of log posterior is {:.3g}".format(g_mc)) + logger.info("Statistical inefficiency of log posterior is {:.3g}".format(g_mc), force_emit=verbose) g_c = np.zeros(len(c)) for nc in range(len(c)): g_c[nc] = timeseries.statistical_inefficiency(csamples[nc, t_mc:]) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Time series for spline parameters are: {:s}".format(str(g_c))) + logger.info("Time series for spline parameters are: {:s}".format(str(g_c)), force_emit=verbose) maxgc = np.max(g_c) meangc = np.mean(g_c) guse = g_mc # doesn't affect the distribution that much indices = timeseries.subsample_correlated_data(equil_logp, g=guse) logposteriors = equil_logp[indices] csamples = (csamples[:, t_mc:])[:, indices] - if verbose: - with log_level(__name__, logging.INFO): - logger.info("samples after decorrelation: {:d}".format(np.shape(csamples)[1])) + logger.info("samples after decorrelation: {:d}".format(np.shape(csamples)[1]), force_emit=verbose) self.mc_data["samples"] = csamples self.mc_data["logposteriors"] = logposteriors self.mc_data["mc_parameters"] = mc_parameters self.mc_data["acceptance_ratio"] = self.mc_data["naccept"] / niterations - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"])) + logger.info("Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"]), force_emit=verbose) self.mc_data["nequil"] = t_mc # the start of the "equilibrated" data set self.mc_data["g_logposterior"] = g_mc # statistical efficiency of the log posterior self.mc_data["g_parameters"] = g_c # statistical efficiency of the parametere diff --git a/pymbar/timeseries.py b/pymbar/timeseries.py index bded91ec..0d77f13b 100644 --- a/pymbar/timeseries.py +++ b/pymbar/timeseries.py @@ -58,7 +58,7 @@ import logging import math import numpy as np -from pymbar.utils import ParameterError, log_level +from pymbar.utils import ParameterError # ============================================================================================= # Issue warning on import. @@ -733,20 +733,16 @@ def subsample_correlated_data(A_t, g=None, fast=False, conservative=False, verbo # Compute the statistical inefficiency for the timeseries. if not g: - if verbose: - with log_level(__name__, logging.INFO): - logger.info("Computing statistical inefficiency...") + logger.info("Computing statistical inefficiency...", force_emit=verbose) g = statistical_inefficiency(A_t, A_t, fast=fast) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("g = {:f}".format(g)) + logger.info("g = {:f}".format(g), force_emit=verbose) if conservative: # Round g up to determine the stride we can use to pick out regularly-spaced uncorrelated samples. stride = int(math.ceil(g)) - if verbose: - with log_level(__name__, logging.INFO): - logger.info("conservative subsampling: using stride of {:d}".format(stride)) + logger.info( + "conservative subsampling: using stride of {:d}".format(stride), force_emit=verbose + ) # Assemble list of indices of uncorrelated snapshots. indices = range(0, T, stride) @@ -760,20 +756,19 @@ def subsample_correlated_data(A_t, g=None, fast=False, conservative=False, verbo if (n == 0) or (t != indices[n - 1]): indices.append(t) n += 1 - if verbose: - with log_level(__name__, logging.INFO): - logger.info("standard subsampling: using average stride of {:f}".format(g)) + logger.info( + "standard subsampling: using average stride of {:f}".format(g), force_emit=verbose + ) # Number of samples in subsampled timeseries. N = len(indices) - if verbose: - with log_level(__name__, logging.INFO): - logger.info( - "The resulting subsampled set has {:d} samples (original timeseries had {:d}).".format( - N, T - ) - ) + logger.info( + "The resulting subsampled set has {:d} samples (original timeseries had {:d}).".format( + N, T + ), + force_emit=verbose, + ) # Return the list of indices of uncorrelated snapshots. return indices diff --git a/pymbar/utils.py b/pymbar/utils.py index b4b0ad10..1f67d646 100644 --- a/pymbar/utils.py +++ b/pymbar/utils.py @@ -24,9 +24,7 @@ ############################################################################## from itertools import zip_longest -from contextlib import contextmanager import warnings -import logging import numpy as np import numexpr @@ -391,68 +389,6 @@ def check_w_normalized(W, N_k, tolerance=1.0e-4): return -# ============================================================================================ -# Logging utilities -# ============================================================================================ - -# Custom formatter -class PerLevelFormatter(logging.Formatter): - """ - Adapted from https://stackoverflow.com/a/14859558 - """ - - FORMATS = { - logging.ERROR: "ERROR! %(message)s", - logging.WARNING: "WARNING: %(message)s", - logging.INFO: "%(message)s", - logging.DEBUG: "Debug: %(module)s: %(lineno)d: %(message)s", - } - - def __init__(self, fmt="%(levelno)d: %(message)s", datefmt=None, style="%", **kwargs): - super().__init__(fmt=fmt, datefmt=datefmt, style=style, **kwargs) - - def format(self, record): - - # Save the original format configured by the user - # when the logger formatter was instantiated - format_orig = self._style._fmt - self._style._fmt = self.FORMATS.get(record.levelno, self._style._fmt) - # Call the original formatter class to do the grunt work - result = super().format(record) - # Restore the original format configured by the user - self._style._fmt = format_orig - - return result - - -def configure_logging(level=logging.WARNING): - """ - Basic configuration for the project, with a custom formatter - """ - logger = logging.getLogger(__name__.split(".", 1)[0]) - logger.setLevel(level) - - handler = logging.StreamHandler() - formatter = PerLevelFormatter() - handler.setFormatter(formatter) - - logger.addHandler(handler) - - -@contextmanager -def log_level(name, level=logging.INFO): - """ - Context manager to change the logging level for a block. - """ - logger = logging.getLogger(name) - current_level = logger.getEffectiveLevel() - logger.setLevel(level) - try: - yield - finally: - logger.setLevel(current_level) - - # ============================================================================================ # Exception classes # ============================================================================================ From a04ff862fb698d1fbc79216c02d25d4db00be7fd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jaime=20Rodr=C3=ADguez-Guerra?= Date: Tue, 28 Apr 2020 10:52:23 +0200 Subject: [PATCH 4/5] Satisfy linter --- pymbar/pmf.py | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/pymbar/pmf.py b/pymbar/pmf.py index ffd436ae..b74cb6f1 100644 --- a/pymbar/pmf.py +++ b/pymbar/pmf.py @@ -1852,24 +1852,34 @@ def prob(x): ) equil_logp = logposteriors[t_mc:] g_mc = timeseries.statistical_inefficiency(equil_logp) - logger.info("Statistical inefficiency of log posterior is {:.3g}".format(g_mc), force_emit=verbose) + logger.info( + "Statistical inefficiency of log posterior is {:.3g}".format(g_mc), + force_emit=verbose, + ) g_c = np.zeros(len(c)) for nc in range(len(c)): g_c[nc] = timeseries.statistical_inefficiency(csamples[nc, t_mc:]) - logger.info("Time series for spline parameters are: {:s}".format(str(g_c)), force_emit=verbose) + logger.info( + "Time series for spline parameters are: {:s}".format(str(g_c)), force_emit=verbose + ) maxgc = np.max(g_c) meangc = np.mean(g_c) guse = g_mc # doesn't affect the distribution that much indices = timeseries.subsample_correlated_data(equil_logp, g=guse) logposteriors = equil_logp[indices] csamples = (csamples[:, t_mc:])[:, indices] - logger.info("samples after decorrelation: {:d}".format(np.shape(csamples)[1]), force_emit=verbose) + logger.info( + "samples after decorrelation: {:d}".format(np.shape(csamples)[1]), + force_emit=verbose, + ) self.mc_data["samples"] = csamples self.mc_data["logposteriors"] = logposteriors self.mc_data["mc_parameters"] = mc_parameters self.mc_data["acceptance_ratio"] = self.mc_data["naccept"] / niterations - logger.info("Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"]), force_emit=verbose) + logger.info( + "Acceptance rate: {:5.3f}".format(self.mc_data["acceptance_ratio"]), force_emit=verbose + ) self.mc_data["nequil"] = t_mc # the start of the "equilibrated" data set self.mc_data["g_logposterior"] = g_mc # statistical efficiency of the log posterior self.mc_data["g_parameters"] = g_c # statistical efficiency of the parametere From 27cad149a625ec0e17744daa06e681ab4b6af680 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jaime=20Rodr=C3=ADguez-Guerra?= Date: Tue, 21 Jul 2020 11:06:45 +0200 Subject: [PATCH 5/5] Use levelName --- pymbar/logging_utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pymbar/logging_utils.py b/pymbar/logging_utils.py index 3e634e71..04fef9b0 100644 --- a/pymbar/logging_utils.py +++ b/pymbar/logging_utils.py @@ -111,7 +111,7 @@ class PerLevelFormatter(logging.Formatter): logging.DEBUG: "Debug: %(message)s", } - def __init__(self, fmt="%(levelno)d: %(message)s", datefmt=None, style="%", **kwargs): + def __init__(self, fmt="%(levelName)d: %(message)s", datefmt=None, style="%", **kwargs): super().__init__(fmt=fmt, datefmt=datefmt, style=style, **kwargs) def format(self, record):