From 2cb136cfb8ef1d4b3a2cb68c4cbc23547bfc395f Mon Sep 17 00:00:00 2001 From: Raphaël Barrois Date: Fri, 12 Apr 2013 00:14:33 +0200 Subject: Add logging calls (Closes #45). --- README | 28 ++++++++++++++++++++++++++++ docs/changelog.rst | 1 + factory/base.py | 18 +++++++++++++++++- factory/containers.py | 21 ++++++++++++++++----- factory/declarations.py | 35 +++++++++++++++++++++++++++++++++++ factory/utils.py | 7 +++++++ setup.py | 11 ++++++++--- 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=>) + SubFactory: Instantiating tests.test_using.TestModelFactory(__containers=(,), one=4), create=True + BaseFactory: Preparing tests.test_using.TestModelFactory(extra={'__containers': (,), '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=) + BaseFactory: Generating tests.test_using.TestModel2Factory(two=) + + 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 '' % self.__target_class.__name__ + return '' % (self.__target_class.__module__, self.__target_class.__name__) def __str__(self): return '' % ( @@ -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() -- cgit v1.2.3