1# -*- Mode: python; tab-width: 4; indent-tabs-mode:nil; coding:utf-8 -*-
2# vim: tabstop=4 expandtab shiftwidth=4 softtabstop=4
3#
4# MDAnalysis --- https://www.mdanalysis.org
5# Copyright (c) 2006-2017 The MDAnalysis Development Team and contributors
6# (see the file AUTHORS for the full list of names)
7#
8# Released under the GNU Public Licence, v2 or any higher version
9#
10# Please cite your use of MDAnalysis in published work:
11#
12# R. J. Gowers, M. Linke, J. Barnoud, T. J. E. Reddy, M. N. Melo, S. L. Seyler,
13# D. L. Dotson, J. Domanski, S. Buchoux, I. M. Kenney, and O. Beckstein.
14# MDAnalysis: A Python package for the rapid analysis of molecular dynamics
15# simulations. In S. Benthall and S. Rostrup editors, Proceedings of the 15th
16# Python in Science Conference, pages 102-109, Austin, TX, 2016. SciPy.
17#
18# N. Michaud-Agrawal, E. J. Denning, T. B. Woolf, and O. Beckstein.
19# MDAnalysis: A Toolkit for the Analysis of Molecular Dynamics Simulations.
20# J. Comput. Chem. 32 (2011), 2319--2327, doi:10.1002/jcc.21787
21#
22
23
24"""Setting up logging --- :mod:`MDAnalysis.lib.log`
25====================================================
26
27Configure logging for MDAnalysis. Import this module if logging is
28desired in application code.
29
30Logging to a file and the console is set up by default as described
31under `logging to multiple destinations`_.
32
33The top level logger of the library is named *MDAnalysis* by
34convention; a simple logger that writes to the console and logfile can
35be created with the :func:`create` function. This only has to be done
36*once*. For convenience, the default MDAnalysis logger can be created
37with :func:`MDAnalysis.start_logging`::
38
39 import MDAnalysis
40 MDAnalysis.start_logging()
41
42Once this has been done, MDAnalysis will write messages to the logfile
43(named `MDAnalysis.log` by default but this can be changed with the
44optional argument to :func:`~MDAnalysis.start_logging`).
45
46Any code can log to the MDAnalysis logger by using ::
47
48 import logging
49 logger = logging.getLogger('MDAnalysis.MODULENAME')
50
51 # use the logger, for example at info level:
52 logger.info("Starting task ...")
53
54The important point is that the name of the logger begins with
55"MDAnalysis.".
56
57.. _logging to multiple destinations:
58   http://docs.python.org/library/logging.html?#logging-to-multiple-destinations
59
60Note
61----
62The :mod:`logging` module in the standard library contains in depth
63documentation about using logging.
64
65
66Convenience functions
67---------------------
68
69Two convenience functions at the top level make it easy to start and
70stop the default *MDAnalysis* logger.
71
72.. autofunction:: MDAnalysis.start_logging
73.. autofunction:: MDAnalysis.stop_logging
74
75
76Other functions and classes for logging purposes
77------------------------------------------------
78
79.. autogenerated, see Online Docs
80
81"""
82from __future__ import print_function, division, absolute_import
83
84import sys
85import logging
86import re
87import warnings
88
89from .. import version
90
91
92def start_logging(logfile="MDAnalysis.log", version=version.__version__):
93    """Start logging of messages to file and console.
94
95    The default logfile is named `MDAnalysis.log` and messages are
96    logged with the tag *MDAnalysis*.
97    """
98    create("MDAnalysis", logfile=logfile)
99    logging.getLogger("MDAnalysis").info(
100        "MDAnalysis %s STARTED logging to %r", version, logfile)
101
102
103def stop_logging():
104    """Stop logging to logfile and console."""
105    logger = logging.getLogger("MDAnalysis")
106    logger.info("MDAnalysis STOPPED logging")
107    clear_handlers(logger)  # this _should_ do the job...
108
109
110def create(logger_name="MDAnalysis", logfile="MDAnalysis.log"):
111    """Create a top level logger.
112
113    - The file logger logs everything (including DEBUG).
114    - The console logger only logs INFO and above.
115
116    Logging to a file and the console as described under `logging to
117    multiple destinations`_.
118
119    The top level logger of MDAnalysis is named *MDAnalysis*.  Note
120    that we are configuring this logger with console output. If a root
121    logger also does this then we will get two output lines to the
122    console.
123
124    .. _logging to multiple destinations:
125       http://docs.python.org/library/logging.html?#logging-to-multiple-destinations
126    """
127
128    logger = logging.getLogger(logger_name)
129
130    logger.setLevel(logging.DEBUG)
131
132    # handler that writes to logfile
133    logfile_handler = logging.FileHandler(logfile)
134    logfile_formatter = logging.Formatter('%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
135    logfile_handler.setFormatter(logfile_formatter)
136    logger.addHandler(logfile_handler)
137
138    # define a Handler which writes INFO messages or higher to the sys.stderr
139    console_handler = logging.StreamHandler()
140    console_handler.setLevel(logging.INFO)
141    # set a format which is simpler for console use
142    formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
143    console_handler.setFormatter(formatter)
144    logger.addHandler(console_handler)
145
146    return logger
147
148
149def clear_handlers(logger):
150    """clean out handlers in the library top level logger
151
152    (only important for reload/debug cycles...)
153
154    """
155    for h in logger.handlers:
156        logger.removeHandler(h)
157
158
159class NullHandler(logging.Handler):
160    """Silent Handler.
161
162    Useful as a default::
163
164      h = NullHandler()
165      logging.getLogger("MDAnalysis").addHandler(h)
166      del h
167
168    see the advice on logging and libraries in
169    http://docs.python.org/library/logging.html?#configuring-logging-for-a-library
170    """
171    def emit(self, record):
172        pass
173
174
175def echo(s='', replace=False, newline=True):
176    r"""Simple string output that immediately prints to the console.
177
178    The string `s` is modified according to the keyword arguments and then
179    printed to :const:`sys.stderr`, which is immediately flushed.
180
181    Parameters
182    ----------
183    s : str
184        The string to output.
185    replace : bool
186        If ``True``, the string will be printed on top of the current line. In
187        practice, ``\r`` is added at the beginning of the string.
188    newline : bool
189        If ``True``, a newline is added at the end of the string.
190
191    """
192    if replace:
193        s = '\r' + s
194    if newline:
195        end='\n'
196    else:
197        end=''
198    print(s, file=sys.stderr, end=end)
199    sys.stderr.flush()
200
201
202def _new_format(template, variables):
203    """Format a string that follows the {}-based syntax.
204    """
205    return template.format(**variables)
206
207
208def _legacy_format(template, variables):
209    """Format a string that follows the %-based syntax.
210    """
211    return template % variables
212
213
214def _guess_string_format(template):
215    """Guess if the template follow {}-based or %-based syntax.
216    """
217    match = re.search(r'%\((step|numsteps|percentage)\)', template)
218    if match is None:
219        return _new_format
220    else:
221        return _legacy_format
222
223
224class ProgressMeter(object):
225    r"""Simple progress meter
226
227    The :class:`ProgressMeter` class can be used to show running progress such
228    as frames processed or percentage done to give the user feedback on the
229    duration and progress of a task. It is structures as a class that is
230    customized on instantation (e.g., using a custom `format` string and the
231    expected total number of frames to be processed). Within a processing loop,
232    call :meth:`echo` with the current frame number to print the output to
233    stderr.
234
235    Parameters
236    ----------
237    numsteps: int
238        total number of steps
239    interval: int
240        only calculate and print progress every `interval` steps [10]
241    format: str
242        a format string with Python variable interpolation. Allowed
243        values:
244
245        * *step*: current step
246        * *numsteps*: total number of steps as supplied in *numsteps*
247        * *percentage*: percentage of total
248
249        The last call to :meth:`ProgressMeter.print` will automatically
250        issue a newline ``\n``.
251
252        If *format* is ``None`` then the default is used::
253
254            Step {step:5d}/{numsteps} [{percentage:5.1f}%]
255
256    offset: int
257        number to add to *step*; e.g. if *step* is 0-based (as in MDAnalysis)
258        then one should set *offset* = 1; for 1-based steps, choose 0. [1]
259    verbose: bool
260        If ``False``, disable all output, ``True`` print all messages as
261        specified, [``True``]
262    dynamic: bool
263        If ``True``, each line will be printed on top of the previous one.
264        This is done by prepedind the format with ``\r``. [``True``]
265    format_handling: str
266        how to handle the format string. Allowed values are:
267
268        * *new*: the format string uses {}-based formating
269        * *legacy*: the format string uses %-basedd formating
270        * *auto*: default, try to guess how the format string should be
271          handled
272
273
274    Examples
275    --------
276    The typical use case is to show progress as frames of a trajectory are
277    processed::
278
279       u = Universe(PSF, DCD)
280       pm = ProgressMeter(u.trajectory.n_frames, interval=100)
281       for ts in u.trajectory:
282           pm.echo(ts.frame)
283           ...
284
285    For a trajectory with 10000 frames this will produce output such
286    as ::
287
288       Step   100/10000 [  1.0%]
289       Step   200/10000 [  2.0%]
290       ...
291
292    The default *format* string is::
293
294        Step {step:5d}/{numsteps} [{percentage:5.1f}%]
295
296    By default, each line of the progress meter is displayed on top of the
297    previous one. To prevent this behaviour, set the `dynamic` keyword to
298    ``False``.
299
300    It is possible to embed (almost) arbitrary additional data in the
301    format string, for example a current RMSD value::
302
303        format_line = "RMSD {rmsd:5.2f} at {step:5d}/{numsteps} [{percentage:5.1f}%]"
304        pm = ProgressMeter(u.trajectory.n_frames,
305                           interval=100, format=format_line)
306        for ts in u.trajectory:
307           pm.echo(ts.frame, rmsd=current_rmsd)
308           ...
309
310    This will print something like::
311
312       RMSD   1.02 at  100/10000 [  1.0%]
313       RMSD   1.89 at  200/10000 [  2.0%]
314       ...
315
316    .. versionchanged:: 0.8
317       Keyword argument *quiet* was added.
318
319    .. versionchanged:: 0.16
320       Keyword argument *dynamic* replaces ``\r`` in the format.
321
322    .. deprecated:: 0.16
323       Keyword argument *quiet* is deprecated in favor of *verbose*.
324
325    """
326
327    def __init__(self, numsteps, format=None, interval=10, offset=1,
328                 verbose=True, dynamic=True,
329                 format_handling='auto'):
330        self.numsteps = numsteps
331        self.interval = int(interval)
332        self.offset = int(offset)
333        self.verbose = verbose
334        self.dynamic = dynamic
335        self.numouts = -1
336
337        if format is None:
338            format = "Step {step:5d}/{numsteps} [{percentage:5.1f}%]"
339            self.format_handler = _new_format
340        else:
341            if format_handling == 'auto':
342                self.format_handler = _guess_string_format(format)
343            else:
344                self.format_handler = {'new': _new_format,
345                                       'legacy': _legacy_format}[format_handling]
346        self.format = format
347        self.step = 0
348        self.percentage = 0.0
349        assert numsteps > 0, "numsteps step must be >0"
350        assert interval > 0, "interval step must be >0"
351
352    def update(self, step, **kwargs):
353        """Update the state of the ProgressMeter.
354
355        *kwargs* are additional attributes that can be references in
356        the format string.
357        """
358        self.step = step + self.offset
359        self.percentage = 100. * self.step / self.numsteps
360        for k, v in kwargs.items():
361            setattr(self, k, v)
362
363        self.numouts += 1
364
365    def echo(self, step, **kwargs):
366        """Print the state to stderr, but only every *interval* steps.
367
368        1) calls :meth:`~ProgressMeter.update`
369        2) writes step and percentage to stderr with :func:`echo`,
370           using the format string (in :attr:`ProgressMeter.format`)
371
372        The last step is always shown, even if not on an *interval*, and a
373        carriage return is replaced with a new line for a cleaner display.
374
375        *kwargs* are additional attributes that can be references in
376        the format string.
377
378        .. Note:: If *verbose* = ``False`` has been set in the
379                  constructor or if :attr:`ProgressMeter.verbose` has
380                  been set to ``False``, then no messages will be
381                  printed.
382        """
383        if not self.verbose:
384            return
385        self.update(step, **kwargs)
386        format = self.format
387        newline = not self.dynamic
388        if self.step == self.numsteps:
389            newline = True
390        elif self.numouts % self.interval == 0:
391            pass
392        else:
393            return
394        echo(self.format_handler(format, vars(self)),
395             replace=self.dynamic, newline=newline)
396