Add logging calls (Closes #45).

7 files changed, 112 insertions, 9 deletions

diff --git a/README b/README
index 06f3393..8586e1d 100644
--- a/README
+++ b/README
@@ -184,6 +184,34 @@ The associated object's strategy will be used:
     True
 
 
+Debugging factory_boy
+"""""""""""""""""""""
+
+Debugging factory_boy can be rather complex due to the long chains of calls.
+Detailed logging is available through the ``factory`` logger:
+
+.. code-block:: python
+
+    import logging
+    logger = logging.getLogger('factory')
+    logger.addHandler(logging.StreamHandler())
+    logger.setLevel(logging.DEBUG)
+
+This will yield messages similar to those (artificial indentation):
+
+.. code-block:: ini
+
+    BaseFactory: Preparing tests.test_using.TestModel2Factory(extra={})
+      LazyStub: Computing values for tests.test_using.TestModel2Factory(two=<OrderedDeclarationWrapper for <factory.declarations.SubFactory object at 0x1e15610>>)
+        SubFactory: Instantiating tests.test_using.TestModelFactory(__containers=(<LazyStub for tests.test_using.TestModel2Factory>,), one=4), create=True
+        BaseFactory: Preparing tests.test_using.TestModelFactory(extra={'__containers': (<LazyStub for tests.test_using.TestModel2Factory>,), 'one': 4})
+          LazyStub: Computing values for tests.test_using.TestModelFactory(one=4)
+          LazyStub: Computed values, got tests.test_using.TestModelFactory(one=4)
+        BaseFactory: Generating tests.test_using.TestModelFactory(one=4)
+      LazyStub: Computed values, got tests.test_using.TestModel2Factory(two=<tests.test_using.TestModel object at 0x1e15410>)
+    BaseFactory: Generating tests.test_using.TestModel2Factory(two=<tests.test_using.TestModel object at 0x1e15410>)
+
+
 ORM Support
 """""""""""
 
diff --git a/docs/changelog.rst b/docs/changelog.rst
index 5d6c4bf..a08330f 100644
--- a/docs/changelog.rst
+++ b/docs/changelog.rst
@@ -15,6 +15,7 @@ ChangeLog
       to their own modules (:mod:`factory.django` and :mod:`factory.mogo`)
     - Add the :meth:`~factory.Factory.reset_sequence` classmethod to :class:`~factory.Factory`
       to ease resetting the sequence counter for a given factory.
+    - Add debug messages to ``factory`` logger.
 
 *Bugfix*
 
diff --git a/factory/base.py b/factory/base.py
index ff5404f..60aa218 100644
--- a/factory/base.py
+++ b/factory/base.py
@@ -20,7 +20,12 @@
 # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
 # THE SOFTWARE.
 
+import logging
+
 from . import containers
+from . import utils
+
+logger = logging.getLogger('factory.generate')
 
 # Strategies
 BUILD_STRATEGY = 'build'
@@ -300,7 +305,13 @@ class BaseFactory(object):
         force_sequence = None
         if extra:
             force_sequence = extra.pop('__sequence', None)
-        return containers.AttributeBuilder(cls, extra).build(
+        log_ctx = '%s.%s' % (cls.__module__, cls.__name__)
+        logger.debug('BaseFactory: Preparing %s.%s(extra=%r)',
+            cls.__module__,
+            cls.__name__,
+            extra,
+        )
+        return containers.AttributeBuilder(cls, extra, log_ctx=log_ctx).build(
             create=create,
             force_sequence=force_sequence,
         )
@@ -338,6 +349,11 @@ class BaseFactory(object):
         # Extract *args from **kwargs
         args = tuple(kwargs.pop(key) for key in cls.FACTORY_ARG_PARAMETERS)
 
+        logger.debug('BaseFactory: Generating %s.%s(%s)',
+            cls.__module__,
+            cls.__name__,
+            utils.log_pprint(args, kwargs),
+        )
         if create:
             return cls._create(target_class, *args, **kwargs)
         else:
diff --git a/factory/containers.py b/factory/containers.py
index b3b003e..4975036 100644
--- a/factory/containers.py
+++ b/factory/containers.py
@@ -20,6 +20,9 @@
 # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
 # THE SOFTWARE.
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 from . import declarations
 from . import utils
@@ -49,17 +52,18 @@ class LazyStub(object):
 
     __initialized = False
 
-    def __init__(self, attrs, containers=(), target_class=object):
+    def __init__(self, attrs, containers=(), target_class=object, log_ctx=None):
         self.__attrs = attrs
         self.__values = {}
         self.__pending = []
         self.__containers = containers
         self.__target_class = target_class
+        self.__log_ctx = log_ctx or '%s.%s' % (target_class.__module__, target_class.__name__)
         self.factory_parent = containers[0] if containers else None
         self.__initialized = True
 
     def __repr__(self):
-        return '<LazyStub for %s>' % self.__target_class.__name__
+        return '<LazyStub for %s.%s>' % (self.__target_class.__module__, self.__target_class.__name__)
 
     def __str__(self):
         return '<LazyStub for %s with %s>' % (
@@ -72,8 +76,14 @@ class LazyStub(object):
             dict: map of attribute name => computed value
         """
         res = {}
+        logger.debug("LazyStub: Computing values for %s(%s)",
+            self.__log_ctx, utils.log_pprint(kwargs=self.__attrs),
+        )
         for attr in self.__attrs:
             res[attr] = getattr(self, attr)
+        logger.debug("LazyStub: Computed values, got %s(%s)",
+            self.__log_ctx, utils.log_pprint(kwargs=res),
+        )
         return res
 
     def __getattr__(self, name):
@@ -219,8 +229,8 @@ class AttributeBuilder(object):
             overridden default values for the related SubFactory.
     """
 
-    def __init__(self, factory, extra=None, *args, **kwargs):
-        super(AttributeBuilder, self).__init__(*args, **kwargs)
+    def __init__(self, factory, extra=None, log_ctx=None, **kwargs):
+        super(AttributeBuilder, self).__init__(**kwargs)
 
         if not extra:
             extra = {}
@@ -228,6 +238,7 @@ class AttributeBuilder(object):
         self.factory = factory
         self._containers = extra.pop('__containers', ())
         self._attrs = factory.declarations(extra)
+        self._log_ctx = log_ctx
 
         attrs_with_subfields = [
             k for k, v in self._attrs.items()
@@ -266,7 +277,7 @@ class AttributeBuilder(object):
             wrapped_attrs[k] = v
 
         stub = LazyStub(wrapped_attrs, containers=self._containers,
-            target_class=self.factory)
+            target_class=self.factory, log_ctx=self._log_ctx)
         return stub.__fill__()
 
 
diff --git a/factory/declarations.py b/factory/declarations.py
index abd384e..dbade97 100644
--- a/factory/declarations.py
+++ b/factory/declarations.py
@@ -23,11 +23,15 @@
 
 import itertools
 import warnings
+import logging
 
 from . import compat
 from . import utils
 
 
+logger = logging.getLogger('factory.generate')
+
+
 class OrderedDeclaration(object):
     """A factory declaration.
 
@@ -67,6 +71,7 @@ class LazyAttribute(OrderedDeclaration):
         self.function = function
 
     def evaluate(self, sequence, obj, create, extra=None, containers=()):
+        logger.debug("LazyAttribute: Evaluating %r on %r", self.function, obj)
         return self.function(obj)
 
 
@@ -131,6 +136,8 @@ class SelfAttribute(OrderedDeclaration):
             target = containers[self.depth - 2]
         else:
             target = obj
+
+        logger.debug("SelfAttribute: Picking attribute %r on %r", self.attribute_name, target)
         return deepgetattr(target, self.attribute_name, self.default)
 
     def __repr__(self):
@@ -161,6 +168,7 @@ class Iterator(OrderedDeclaration):
             self.iterator = iter(iterator)
 
     def evaluate(self, sequence, obj, create, extra=None, containers=()):
+        logger.debug("Iterator: Fetching next value from %r", self.iterator)
         value = next(self.iterator)
         if self.getter is None:
             return value
@@ -184,6 +192,7 @@ class Sequence(OrderedDeclaration):
         self.type = type
 
     def evaluate(self, sequence, obj, create, extra=None, containers=()):
+        logger.debug("Sequence: Computing next value of %r for seq=%d", self.function, sequence)
         return self.function(self.type(sequence))
 
 
@@ -197,6 +206,8 @@ class LazyAttributeSequence(Sequence):
             of counter for the 'function' attribute.
     """
     def evaluate(self, sequence, obj, create, extra=None, containers=()):
+        logger.debug("LazyAttributeSequence: Computing next value of %r for seq=%d, obj=%r",
+                self.function, sequence, obj)
         return self.function(obj, self.type(sequence))
 
 
@@ -364,6 +375,11 @@ class SubFactory(ParameteredAttribute):
                 override the wrapped factory's defaults
         """
         subfactory = self.get_factory()
+        logger.debug("SubFactory: Instantiating %s.%s(%s), create=%r",
+            subfactory.__module__, subfactory.__name__,
+            utils.log_pprint(kwargs=params),
+            create,
+        )
         return subfactory.simple_generate(create, **params)
 
 
@@ -375,6 +391,7 @@ class Dict(SubFactory):
 
     def generate(self, sequence, obj, create, params):
         dict_factory = self.get_factory()
+        logger.debug("Dict: Building dict(%s)", utils.log_pprint(kwargs=params))
         return dict_factory.simple_generate(create,
             __sequence=sequence,
             **params)
@@ -389,6 +406,9 @@ class List(SubFactory):
 
     def generate(self, sequence, obj, create, params):
         list_factory = self.get_factory()
+        logger.debug('List: Building list(%s)',
+            utils.log_pprint(args=[v for _i, v in sorted(params.items())]),
+        )
         return list_factory.simple_generate(create,
             __sequence=sequence,
             **params)
@@ -435,6 +455,11 @@ class PostGeneration(PostGenerationDeclaration):
         self.function = function
 
     def call(self, obj, create, extracted=None, **kwargs):
+        logger.debug('PostGeneration: Calling %s.%s(%s)',
+            self.function.__module__,
+            self.function.__name__,
+            utils.log_pprint((obj, create, extracted), kwargs),
+        )
         return self.function(obj, create, extracted, **kwargs)
 
 
@@ -474,6 +499,11 @@ class RelatedFactory(PostGenerationDeclaration):
             passed_kwargs[self.name] = obj
 
         factory = self.get_factory()
+        logger.debug('RelatedFactory: Generating %s.%s(%s)',
+            factory.__module__,
+            factory.__name__,
+            utils.log_pprint((create,), passed_kwargs),
+        )
         factory.simple_generate(create, **passed_kwargs)
 
 
@@ -509,4 +539,9 @@ class PostGenerationMethodCall(PostGenerationDeclaration):
         passed_kwargs = dict(self.method_kwargs)
         passed_kwargs.update(kwargs)
         method = getattr(obj, self.method_name)
+        logger.debug('PostGenerationMethodCall: Calling %r.%s(%s)',
+            obj,
+            self.method_name,
+            utils.log_pprint(passed_args, passed_kwargs),
+        )
         method(*passed_args, **passed_kwargs)
diff --git a/factory/utils.py b/factory/utils.py
index fb8cfef..e1b265f 100644
--- a/factory/utils.py
+++ b/factory/utils.py
@@ -94,3 +94,10 @@ def import_object(module_name, attribute_name):
     module = __import__(module_name, {}, {}, [attribute_name], 0)
     return getattr(module, attribute_name)
 
+
+def log_pprint(args=(), kwargs=None):
+    kwargs = kwargs or {}
+    return ', '.join(
+        [str(arg) for arg in args] +
+        ['%s=%r' % item for item in kwargs.items()]
+    )
diff --git a/setup.py b/setup.py
index 050e43b..42519ce 100755
--- a/setup.py
+++ b/setup.py
@@ -46,10 +46,15 @@ class test(cmd.Command):
         except ImportError:
             import unittest
 
-        if self.verbose:
-            verbosity=1
+        import logging
+        logger = logging.getLogger('factory')
+        logger.addHandler(logging.StreamHandler())
+
+        verbosity = self.verbose
+        if verbosity >= 2:
+            logger.setLevel(logging.DEBUG)
         else:
-            verbosity=0
+            logger.setLevel(logging.INFO)
 
         loader = unittest.TestLoader()
         suite = unittest.TestSuite()