Merge pull request #112 from marrink-lab/logging

Setup logging

.travis.yml

@@ -9,6 +9,7 @@ env:
     - SKIP_GENERATE_AUTHORS=1
     - SKIP_WRITE_GIT_CHANGELOG=1
 install:
+  - pip install --upgrade setuptools pip
   - pip install --upgrade -r requirements-tests.txt
   - pip install --upgrade .
 script:

bin/martinize2

@@ -34,13 +34,40 @@ from vermouth.dssp.dssp import (
     AnnotateMartiniSecondaryStructures,
     AnnotateResidues,
 )
+from vermouth.log_helpers import (StyleAdapter, BipolarFormatter,
+                                  CountingHandler)
 from vermouth import selectors
 from vermouth.map_input import (
     read_mapping_directory,
     generate_all_self_mappings,
     combine_mappings
 )
 
+# TODO Since vermouth's __init__.py does some logging (KDTree), this may or may
+# not work as intended. Investigation required.
+
+LOGGER = logging.getLogger('vermouth')
+
+PRETTY_FORMATTER = logging.Formatter(fmt='{levelname:>8} - {type} - {message}',
+                                     style='{')
+DETAILED_FORMATTER = logging.Formatter(fmt='{levelname:>8} - {type} - {name} - {message}',
+                                       style='{')
+
+COUNTER = CountingHandler()
+
+# Control above what level message we want to count
+COUNTER.setLevel(logging.WARNING)
+
+CONSOLE_HANDLER = logging.StreamHandler()
+FORMATTER = BipolarFormatter(DETAILED_FORMATTER,
+                             PRETTY_FORMATTER,
+                             logging.DEBUG,
+                             logger=LOGGER)
+CONSOLE_HANDLER.setFormatter(FORMATTER)
+LOGGER.addHandler(CONSOLE_HANDLER)
+LOGGER.addHandler(COUNTER)
+
+LOGGER = StyleAdapter(LOGGER)
 
 VERSION = 'martinize with vermouth {}'.format(vermouth.__version__)
 
@@ -298,9 +325,15 @@ def entry():
                                    'resulting file may contain "nan" '
                                    'coordinates making it unreadable by most '
                                    'softwares.'))
+    debug_group.add_argument('-v', dest='verbosity', action='count',
+                             help='Enable debug logging output. Can be given '
+                                  'multiple times.', default=0)
 
     args = parser.parse_args()
 
+    loglevels = {0: logging.INFO, 1: logging.DEBUG, 2: 5}
+    LOGGER.setLevel(loglevels[args.verbosity])
+
     known_force_fields = vermouth.forcefield.find_force_fields(
         Path(DATA_PATH) / 'force_fields'
     )

vermouth/__init__.py

@@ -18,6 +18,12 @@
 Provides functionality for creating MD topologies from coordinate files. Powers
 the CLI tool martinize2.
 """
+import logging
+from .log_helpers import StyleAdapter, get_logger
+logging.getLogger(__name__).addHandler(logging.NullHandler())
+
+LOGGER = StyleAdapter(get_logger(__name__))
+
 
 # Find the data directory once.
 try:
@@ -37,9 +43,12 @@
 try:
     from scipy.spatial import cKDTree as KDTree
 except ImportError:
-    print('Using redistributed KDTree')
+    LOGGER.info('Using redistributed KDTree. Some functionality might be slow.'
+                ' Install scipy for better performance.', type='performance')
     from .redistributed.kdtree import KDTree
 
+del LOGGER
+
 from .molecule import Molecule
 from .processors import *
 from .system import System

vermouth/deferred_file.py

@@ -17,11 +17,16 @@
 moved to a specified location if no errors occured.
 """
 
-
+import logging
 import os
 import sys
 import tempfile
 
+from .log_helpers import StyleAdapter
+
+LOGGER = StyleAdapter(logging.getLogger(__name__))
+
+
 # TODO: replace with pathlib.replace, and add pathlib2 to requirements for py2.7.
 # from https://stupidpythonideas.blogspot.nl/2014/07/getting-atomic-writes-right.html
 try:
@@ -96,7 +101,7 @@ def replace_with_backup(file_in, file_out, suffix='bak'):
     """
     if os.path.exists(file_out):
         file_out_bak = find_next_filename(file_out, suffix=suffix)
-        print('Backing up {} to {}'.format(file_out, file_out_bak))
+        LOGGER.info('Backing up {} to {}', file_out, file_out_bak)
         replace(file_out, file_out_bak)
     return replace(file_in, file_out)
 

vermouth/graphing/grappa.py

@@ -66,11 +66,14 @@
     (/#=A-D/C#(H#[1-3]),/) : Expand to multiple branches
 """
 
-
-import sys
 import string
+
 import networkx as nx
 
+from ..log_helpers import StyleAdapter, get_logger
+
+LOGGER = StyleAdapter(get_logger(__name__))
+
 
 DIRECTIVES = '@(),-=!'
 GROUPS = ('{}', '<>')
@@ -301,19 +304,17 @@ def process(graphstring, graphs={}):
             if token == '.' and node is not None:
                 # Adding stub (or stub branch) to active node
                 G.nodes[node]['stub'] = G.nodes[node].get('stub', 0) + 1
-                # DEBUG
-                # print("Adding stub to", node, ":", G.nodes[node]['stub'])
+                LOGGER.debug("Adding stub to {}: {}", node, G.nodes[node]['stub'],
+                             type='grappa')
             else:
                 # Token is node or nodes
                 nodes = expand_nodestring(token)
                 if node is None:
-                    # DEBUG
-                    # print('Unrooted nodes:', *nodes)
+                    LOGGER.debug('Unrooted nodes: {}', nodes, type='grappa')
                     G.add_nodes_from(nodes)
                 else:
                     G.add_edges_from((node, n) for n in nodes)
-                    # DEBUG
-                    # print("Edge:", node, "to", n)
+                    LOGGER.debug("Edge: {} to {}", node, nodes, type='grappa')
                 active = nodes[-1]
             continue
 
@@ -326,8 +327,7 @@ def process(graphstring, graphs={}):
         elif token == ')':
             # End branch(es) - switch to active parent
             active = parent.pop()
-            # DEBUG
-            # print("End of branching: active:", active[-1])
+            LOGGER.debug("End of branching: active: {}", active[-1], type='grappa')
 
         elif token == ',':
             # Switch to next branch
@@ -336,8 +336,7 @@ def process(graphstring, graphs={}):
         elif token == '@':
             # Set node as active
             active = next(tokens)
-            # DEBUG
-            # print("Setting active:", active)
+            LOGGER.debug("Setting active: {}", active, type='grappa')
 
         elif token == '-':
             # Remove node
@@ -351,8 +350,7 @@ def process(graphstring, graphs={}):
             # Include graph from graphs and relabel nodes according to tag
             # <tag:graphname@node>. include_graph relabels its nodes.
             B, at = include_graph(graphs, token[1:-1])
-            # DEBUG
-            # print("Including graph from", token, ":", *B.nodes)
+            LOGGER.debug("Including graph from {}: {}", token, B.nodes, type='grappa')
             G.add_nodes_from(B.nodes.items())
             G.add_edges_from(B.edges())
             if active is not None:
@@ -362,9 +360,8 @@ def process(graphstring, graphs={}):
 
         elif token[0] == '{':
             # Set attributes to active node
-            # DEBUG
-            # print("Setting attributes at active atom:",
-            #       parse_attribute_token(token))
+            LOGGER.debug("Setting attributes at active atom: {}",
+                         parse_attribute_token(token), type='grappa')
             G.nodes[active].update(parse_attribute_token(token))
 
     return G