Add debug/info logging to conditions, models numberoverzero#55

bloop/conditions.py

@@ -1,6 +1,7 @@
 # http://docs.aws.amazon.com/amazondynamodb/latest/developerguide/ \
 #   Expressions.SpecifyingConditions.html#ConditionExpressionReference.Syntax
 import collections
+import logging
 
 from .exceptions import InvalidCondition
 from .signals import (
@@ -25,6 +26,7 @@
     ">=": ">=",
 }
 comparisons = list(comparison_aliases.keys())
+logger = logging.getLogger("bloop.conditions")
 
 
 # CONDITION TRACKING ============================================================================== CONDITION TRACKING
@@ -241,6 +243,7 @@ def pop_refs(self, *refs):
                 self.counts[name] -= 1
             # Last reference
             else:
+                logger.debug("popping last usage of {}".format(ref))
                 self.counts[name] -= 1
                 if ref.type == "value":
                     del self.attr_values[name]
@@ -683,6 +686,7 @@ def render(self, renderer):
         if self.operation in ("==", "!="):
             renderer.refs.pop_refs(value_ref)
             function = "attribute_not_exists" if self.operation == "==" else "attribute_exists"
+            logger.debug("rendering \"{}\" as {}".format(self.operation, function))
             return "({}({}))".format(function, column_ref.name)
 
         # #n0 <= None
@@ -797,7 +801,6 @@ def render(self, renderer):
 
 
 def check_support(column, operation):
-    # TODO parametrize tests for (all condition types) X (all backing types)
     typedef = column.typedef
     for segment in path_of(column):
         typedef = typedef[segment]

bloop/models.py

@@ -1,4 +1,5 @@
 import collections.abc
+import logging
 
 import declare
 
@@ -9,6 +10,7 @@
 
 
 __all__ = ["BaseModel", "Column", "GlobalSecondaryIndex", "LocalSecondaryIndex"]
+logger = logging.getLogger("bloop.models")
 
 
 def loaded_columns(obj):
@@ -90,6 +92,7 @@ def __new__(mcs, name, bases, attrs):
             # hash function has priority over the default.
             # If there aren't any bases with explicit hash functions,
             # just use object.__hash__
+            logger.info("searching for nearest __hash__ impl in {}.__mro__".format(name))
             for base in bases:
                 hash_fn = getattr(base, "__hash__")
                 if hash_fn:

tests/unit/test_conditions.py

@@ -1,3 +1,4 @@
+import logging
 import operator
 
 import pytest
@@ -514,7 +515,7 @@ def test_render_missing_object(engine):
     ("key", "KeyConditionExpression"),
     ("condition", "ConditionExpression"),
 ])
-def test_render_condition_only(kwarg_name, expression_key, engine):
+def test_render_condition_only(kwarg_name, expression_key, engine, caplog):
     """Only renders the given condition"""
     condition = (User.email == "@") & (User.name.is_(None))
     rendered = render(engine, **{kwarg_name: condition})
@@ -524,6 +525,11 @@ def test_render_condition_only(kwarg_name, expression_key, engine):
         expression_key: "((#n0 = :v1) AND (attribute_not_exists(#n2)))"
     }
 
+    assert caplog.record_tuples == [
+        ("bloop.conditions", logging.DEBUG, "popping last usage of Reference(name=':v3', type='value', value=None)"),
+        ("bloop.conditions", logging.DEBUG, "rendering \"==\" as attribute_not_exists"),
+    ]
+
 
 def test_render_projection_only(engine):
     columns = [User.id, User.email, User.id, User.age]

tests/unit/test_models.py

@@ -1,4 +1,5 @@
 import datetime
+import logging
 import operator
 
 import pytest
@@ -378,7 +379,7 @@ class Model(BaseModel):
     assert Model.__hash__ is hash_fn
 
 
-def test_parent_hash():
+def test_parent_hash(caplog):
     """Parent __hash__ function is used, not object __hash__"""
     class OtherBase:
         # Explicit __eq__ prevents OtherBase from having a __hash__
@@ -389,9 +390,13 @@ class BaseWithHash:
         def __hash__(self):
             return id(self)
 
-    class Model(OtherBase, BaseWithHash, BaseModel):
+    class MyModel(OtherBase, BaseWithHash, BaseModel):
         id = Column(Integer, hash_key=True)
-    assert Model.__hash__ is BaseWithHash.__hash__
+    assert MyModel.__hash__ is BaseWithHash.__hash__
+
+    assert caplog.record_tuples == [
+        ("bloop.models", logging.INFO, "searching for nearest __hash__ impl in MyModel.__mro__"),
+    ]
 
 
 # END BASE MODEL ======================================================================================= END BASE MODEL