Add MOLEXTRACT_LOG_LEVEL with debugging capabilities (#12)

molextract/__init__.py

@@ -1,4 +1,4 @@
 from .rule import Rule
 from .parser import Parser
 
-__version__ = '1.0.0'
+__version__ = '1.0.0'

molextract/debug.py

@@ -0,0 +1,69 @@
+"""
+Utility functions to debug / log what is happening within in a Rule
+"""
+import os
+import sys
+import logging
+
+LOG_NAME_TO_LEVEL = {
+    'CRITICAL': logging.CRITICAL,
+    'FATAL': logging.FATAL,
+    'ERROR': logging.ERROR,
+    'WARN': logging.WARNING,
+    'WARNING': logging.WARNING,
+    'INFO': logging.INFO,
+    'DEBUG': logging.DEBUG,
+    'NOTSET': logging.NOTSET,
+}
+
+MOLEXTRACT_LOG_LEVEL = os.getenv('MOLEXTRACT_LOG_LEVEL', 'INFO')
+ESC_CHAR = '\x1b['
+TAG_LEFT_JUST = 100
+VERB_LEFT_JUST = 12
+
+logger = logging.getLogger('molextract')
+handler = logging.StreamHandler()
+logger.addHandler(handler)
+logger.setLevel(MOLEXTRACT_LOG_LEVEL)
+
+_COLOR_CODES = {
+    'BLACK': 30,
+    'RED': 31,
+    'GREEN': 32,
+    'YELLOW': 33,
+    'BLUE': 34,
+    'MAGENTA': 35,
+    'CYAN': 36,
+    'WHITE': 37,
+    'RESET': 0
+}
+
+
+class ColorType(type):
+    def __getattr__(self, item):
+        code = _COLOR_CODES.get(item)
+        if code is None:
+            raise ValueError(f'{item} is not a valid color')
+
+        if sys.stderr.isatty():
+            return f'{ESC_CHAR}{code}m'
+
+        return ''
+
+
+class Color(metaclass=ColorType):
+    pass
+
+
+def log_start_tag(start_tag, rule_id):
+    verb = "executed".ljust(VERB_LEFT_JUST)
+    start_tag = start_tag.ljust(TAG_LEFT_JUST)
+    msg = f'{start_tag} {Color.GREEN}{verb}{Color.RESET} {rule_id}'
+    logger.debug(msg)
+
+
+def log_end_tag(end_tag, rule_id):
+    verb = "ended".ljust(VERB_LEFT_JUST)
+    end_tag = end_tag.ljust(TAG_LEFT_JUST)
+    msg = f'{end_tag} {Color.RED}{verb}{Color.RESET} {rule_id}'
+    logger.debug(msg)

molextract/rule.py

@@ -1,4 +1,6 @@
 import re
+from molextract import debug
+from molextract.debug import Color
 
 
 class Rule:
@@ -74,6 +76,13 @@ def __init__(self,
         self._check_only_beginning = check_only_beginning
         self._iterator = None
 
+    def rule_id(self):
+        """
+        Get the name of the current Rule, default behavior is the name of the
+        class. Useful for debugging / logging purposes.
+        """
+        return type(self).__name__
+
     def set_iter(self, iterator):
         """
         Set the internal iterator used to read lines from
@@ -92,7 +101,11 @@ def start_tag_matches(self, line):
         :return: whether the match was successful
         :rtype: bool
         """
-        return self._match(self._start_tag, line)
+        matches = self._match(self._start_tag, line)
+        if matches:
+            debug.log_start_tag(line, self.rule_id())
+
+        return matches
 
     def end_tag_matches(self, line):
         """
@@ -103,8 +116,11 @@ def end_tag_matches(self, line):
         :return: whether the match was successful
         :rtype: bool
         """
+        matches = self._match(self._end_tag, line)
+        if matches:
+            debug.log_end_tag(line, self.rule_id())
 
-        return self._match(self._end_tag, line)
+        return matches
 
     def _match(self, compiled_re, line):
         if self._check_only_beginning:

setup.py

@@ -1,3 +1,3 @@
 from setuptools import setup
 
-setup()
+setup()

test/debug_test.py

@@ -0,0 +1,24 @@
+from unittest import mock
+import pytest
+
+from molextract import debug
+
+
+@mock.patch('sys.stderr.isatty', return_value=True)
+def test_color(mock_isatty):
+    for color in debug._COLOR_CODES:
+        code = debug._COLOR_CODES[color]
+        string = f'{debug.ESC_CHAR}{code}m'
+        assert debug.Color.__getattr__(color) == string
+
+    with pytest.raises(ValueError, match='not a valid color'):
+        debug.Color.ORANGE
+
+
+@mock.patch('sys.stderr.isatty')
+def test_color_notty(mock_isatty):
+    mock_isatty.return_value = True
+    assert len(debug.Color.RED) > 0
+
+    mock_isatty.return_value = False
+    assert debug.Color.RED == ''

test/rule_test.py

@@ -3,6 +3,7 @@
 import pytest
 
 from molextract.rule import Rule
+from molextract import debug
 
 
 def test_start_tag_matches():
@@ -21,6 +22,24 @@ def test_start_tag_matches():
     assert rule.start_tag_matches("prefix Foo suffix")
 
 
+@mock.patch('molextract.debug.log_start_tag')
+def test_start_tag_log(mock_log_start_tag):
+    rule = Rule("Foo", "Bar", False)
+    for level in debug.LOG_NAME_TO_LEVEL:
+        with mock.patch('molextract.debug.MOLEXTRACT_LOG_LEVEL', level):
+            assert mock_log_start_tag.call_count == 0
+
+            rule.start_tag_matches("Foo")
+            assert mock_log_start_tag.call_args_list == [
+                mock.call("Foo", rule.rule_id())
+            ]
+            mock_log_start_tag.reset_mock()
+
+            rule.start_tag_matches("Baz")
+            assert mock_log_start_tag.call_count == 0
+            mock_log_start_tag.reset_mock()
+
+
 def test_end_tag_matches():
     rule = Rule("Foo", "Bar")
 
@@ -37,6 +56,24 @@ def test_end_tag_matches():
     assert rule.end_tag_matches("prefix Bar suffix")
 
 
+@mock.patch('molextract.debug.log_end_tag')
+def test_start_tag_log(mock_log_end_tag):
+    rule = Rule("Foo", "Bar", False)
+    for level in debug.LOG_NAME_TO_LEVEL:
+        with mock.patch('molextract.debug.MOLEXTRACT_LOG_LEVEL', level):
+            assert mock_log_end_tag.call_count == 0
+
+            rule.end_tag_matches("Bar")
+            assert mock_log_end_tag.call_args_list == [
+                mock.call("Bar", rule.rule_id())
+            ]
+            mock_log_end_tag.reset_mock()
+
+            rule.end_tag_matches("Baz")
+            assert mock_log_end_tag.call_count == 0
+            mock_log_end_tag.reset_mock()
+
+
 def test_skip():
     rule = Rule("Foo", "Bar")
     rule.set_iter(iter("abcd"))