Add verbose debug logging to API block checking

CHANGELOG.md

@@ -19,6 +19,12 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 
 ### Security
 
+## [2.39.2] - 2021-02-38
+
+### Added
+
+-  Add verbose debug logging to API block checking [#1274](https://github.com/open-apparel-registry/open-apparel-registry/pull/1274)
+
 ## [2.39.1] - 2021-02-02
 
 ### Added

src/django/api/middleware.py

@@ -1,5 +1,6 @@
 import sys
 import datetime
+import logging
 
 from django.utils import timezone
 from django.conf import settings
@@ -11,6 +12,8 @@
 from api.models import RequestLog
 from api.limits import get_api_block
 
+logger = logging.getLogger(__name__)
+
 
 def _report_error_to_rollbar(request, auth):
     ROLLBAR = getattr(settings, 'ROLLBAR', {})
@@ -51,17 +54,44 @@ def __call__(self, request):
 
 
 def has_active_block(request):
+    def debug_log(msg):
+        if request.path != '/health-check/':
+            logger.debug(msg)
+    debug_log('has_active_block handling request {0}'.format(
+        request.__dict__))
     try:
         if request.user and request.user.is_authenticated:
+            debug_log('has_active_block user {0} authenticated'.format(
+                request.user.id))
             auth = get_authorization_header(request)
             if auth and auth.split()[0].lower() == 'token'.encode():
+                debug_log('has_active_block saw token auth')
                 contributor = request.user.contributor
+                debug_log(
+                    'has_active_block fetched contributor {0}'.format(
+                        contributor.id))
                 apiBlock = get_api_block(contributor)
+                if apiBlock is not None:
+                    debug_log(
+                        'has_active_block fetched block {0}'.format(
+                            apiBlock.__dict__))
+                else:
+                    debug_log(
+                        'has_active_block no block found for contributor {0}'
+                        .format(contributor.id))
+
                 at_datetime = datetime.datetime.now(tz=timezone.utc)
+                debug_log(
+                    'has_active_block at_datetime is {0}'.format(
+                        at_datetime))
                 return (apiBlock is not None and
                         apiBlock.until > at_datetime and apiBlock.active)
+        debug_log('has_active_block did not see an authenticated user')
     except ObjectDoesNotExist:
+        debug_log('has_active_block caught ObjectDoesNotExist exception')
+        debug_log('has_active_block returning False from the except block')
         return False
+    debug_log('has_active_block returning False')
     return False
 
 

src/django/oar/settings.py

@@ -253,6 +253,11 @@
             'handlers': ['console'],
             'level': os.getenv('DJANGO_LOG_LEVEL', 'INFO'),
         },
+        'api.middleware': {
+            'handlers': ['console'],
+            'level': 'DEBUG',
+            'propagate': False
+        }
     },
 }