Adding logging and fixing some auto-tag junk

Author: codekoala

articles/decorators.py

@@ -0,0 +1,48 @@
+import functools
+import logging
+import time
+
+log = logging.getLogger('articles.decorators')
+
+def logtime(func):
+
+    @functools.wraps(func)
+    def wrapped(*args, **kwargs):
+        if func.__class__.__name__ == 'function':
+            executing = '%s.%s' % (func.__module__, func.__name__)
+        elif 'method' in func.__class__.__name__:
+            executing = '%s.%s.%s' % (func.__module__, func.__class__.__name__, func.__name__)
+        else:
+            executing = str(func)
+
+        log.debug('Logging execution time for %s with args: %s; kwargs: %s' % (executing, args, kwargs))
+
+        start = time.time()
+        res = func(*args, **kwargs)
+        duration = time.time() - start
+
+        log.debug('Called %s... duration: %s seconds' % (executing, duration))
+        return res
+
+    return wrapped
+
+def once_per_instance(func):
+    """Makes it so an instance method is called at most once before saving"""
+
+    @functools.wraps(func)
+    def wrapped(self, *args, **kwargs):
+        if not hasattr(self, '__run_once_methods'):
+            self.__run_once_methods = []
+
+        name = func.__name__
+        if name in self.__run_once_methods:
+            log.debug('Method %s has already been called for %s... not calling again.' % (name, self))
+            return False
+
+        res = func(self, *args, **kwargs)
+
+        self.__run_once_methods.append(name)
+        return res
+
+    return wrapped
+

articles/forms.py

@@ -1,11 +1,20 @@
+import logging
+
 from django import forms
 from django.utils.translation import ugettext_lazy as _
 from models import Article, Tag
 
+log = logging.getLogger('articles.forms')
+
 def tag(name):
     """Returns a Tag object for the given name"""
 
-    t = Tag.objects.get_or_create(slug=Tag.clean_tag(name))[0]
+    slug = Tag.clean_tag(name)
+
+    log.debug('Looking for Tag with slug "%s"...' % (slug,))
+    t, created = Tag.objects.get_or_create(slug=slug, defaults={'name': name})
+    log.debug('Found Tag %s. Name: %s Slug: %s Created: %s' % (t.pk, t.name, t.slug, created))
+
     if not t.name:
         t.name = name
         t.save()
@@ -31,7 +40,9 @@ def __init__(self, *args, **kwargs):
     def clean_tags(self):
         """Turns the string of tags into a list"""
 
-        tags = [tag(t) for t in self.cleaned_data['tags'].split()]
+        tags = [tag(t.strip()) for t in self.cleaned_data['tags'].split() if len(t.strip())]
+
+        log.debug('Tagging Article %s with: %s' % (self.cleaned_data['title'], tags))
         self.cleaned_data['tags'] = tags
         return self.cleaned_data['tags']
 

articles/listeners.py

@@ -1,12 +1,34 @@
-from django.db.models import signals
+import logging
+
+from django.db.models import signals, Q
+
+from decorators import logtime
 from models import Article, Tag
 
-def apply_new_tag(sender, instance, created, **kwargs):
-    """
-    Applies new tags to existing articles that are marked for auto-tagging
-    """
+log = logging.getLogger('articles.listeners')
+
+@logtime
+def apply_new_tag(sender, instance, created, using='default', **kwargs):
+    """Applies new tags to existing articles that are marked for auto-tagging"""
+
+    # attempt to find all articles that contain the new tag
+    # TODO: make sure this is standard enough... seems that both MySQL and
+    # PostgreSQL support it...
+    tag = r'[[:<:]]%s[[:>:]]' % instance.name
+
+    log.debug('Searching for auto-tag Articles using regex: %s' % (tag,))
+    applicable_articles = Article.objects.filter(
+        Q(auto_tag=True),
+        Q(content__iregex=tag) |
+        Q(title__iregex=tag) |
+        Q(description__iregex=tag) |
+        Q(keywords__iregex=tag)
+    )
 
-    for article in Article.objects.filter(auto_tag=True):
-        article.do_auto_tag()
+    log.debug('Found %s matches' % len(applicable_articles))
+    for article in applicable_articles:
+        log.debug('Applying Tag "%s" (%s) to Article "%s" (%s)' % (instance, instance.pk, article.title, article.pk))
+        article.tags.add(instance)
+        article.save()
 
 signals.post_save.connect(apply_new_tag, sender=Tag)

articles/models.py

@@ -15,6 +15,8 @@
 from django.template.defaultfilters import slugify, striptags
 from django.utils.translation import ugettext_lazy as _
 
+from decorators import logtime, once_per_instance
+
 WORD_LIMIT = getattr(settings, 'ARTICLES_TEASER_LIMIT', 75)
 AUTO_TAG = getattr(settings, 'ARTICLES_AUTO_TAG', True)
 DEFAULT_DB = getattr(settings, 'ARTICLES_DEFAULT_DB', 'default')
@@ -41,7 +43,7 @@
 TITLE_RE = re.compile('<title.*?>(.*?)</title>', re.I|re.M)
 TAG_RE = re.compile('[^a-z0-9\-_\+\:\.]?', re.I)
 
-log = logging.getLogger(__file__)
+log = logging.getLogger('articles.models')
 
 def get_name(user):
     """
@@ -312,29 +314,36 @@ def do_meta_description(self):
 
         return False
 
+    @logtime
+    @once_per_instance
     def do_auto_tag(self, using=DEFAULT_DB):
         """
         Performs the auto-tagging work if necessary.
 
         Returns True if an additional save is required, False otherwise.
         """
 
+        if not self.auto_tag:
+            log.debug('Article "%s" (ID: %s) is not marked for auto-tagging. Skipping.' % (self.title, self.pk))
+            return False
+
+        # don't clobber any existing tags!
+        existing_ids = [t.id for t in self.tags.all()]
+        log.debug('Article %s already has these tags: %s' % (self.pk, existing_ids))
+
+        unused = Tag.objects.all()
+        if hasattr(unused, 'using'):
+            unused = unused.using(using)
+        unused = unused.exclude(id__in=existing_ids)
+
         found = False
-        if self.auto_tag:
-            # don't clobber any existing tags!
-            existing_ids = [t.id for t in self.tags.all()]
-
-            unused = Tag.objects.all()
-            if hasattr(unused, 'using'):
-                unused = unused.using(using)
-            unused = unused.exclude(id__in=existing_ids)
-
-            for tag in unused:
-                regex = re.compile(r'\b%s\b' % tag.name, re.I)
-                if regex.search(self.content) or regex.search(self.title) or \
-                   regex.search(self.description) or regex.search(self.keywords):
-                    self.tags.add(tag)
-                    found = True
+        to_search = (self.content, self.title, self.description, self.keywords)
+        for tag in unused:
+            regex = re.compile(r'\b%s\b' % tag.name, re.I)
+            if any(regex.search(text) for text in to_search):
+                log.debug('Applying Tag "%s" (%s) to Article %s' % (tag, tag.pk, self.pk))
+                self.tags.add(tag)
+                found = True
 
         return found
 

articles/views.py

@@ -1,3 +1,5 @@
+import logging
+
 from django.conf import settings
 from django.contrib.auth.models import User
 from django.core.cache import cache
@@ -11,6 +13,8 @@
 
 ARTICLE_PAGINATION = getattr(settings, 'ARTICLE_PAGINATION', 20)
 
+log = logging.getLogger('articles.views')
+
 def display_blog_page(request, tag=None, username=None, year=None, month=None, page=1):
     """
     Handles all of the magic behind the pages that list articles in any way.