add a new logger, awx.analytics.performance.api

* Used to log API timing information

awx/api/generics.py

@@ -41,6 +41,7 @@ __all__ = ['APIView', 'GenericAPIView', 'ListAPIView', 'SimpleListAPIView',
            'DeleteLastUnattachLabelMixin',]
 
 logger = logging.getLogger('awx.api.generics')
+analytics_logger = logging.getLogger('awx.analytics.performance.api')
 
 
 def get_view_name(cls, suffix=None):
@@ -117,6 +118,37 @@ class APIView(views.APIView):
             q_times = [float(q['time']) for q in connection.queries[queries_before:]]
             response['X-API-Query-Count'] = len(q_times)
             response['X-API-Query-Time'] = '%0.3fs' % sum(q_times)
+
+        def copy_items_try_to_numberify(d, keys):
+            new_d = {}
+            for k in keys:
+                val = d[k]
+                if val.endswith('s'):
+                    val = val[:-1]
+                try:
+                    new_d[k] = int(val)
+                except ValueError:
+                    try:
+                        new_d[k] = float(val)
+                    except ValueError:
+                        new_d[k] = val
+
+            return new_d
+
+        log = copy_items_try_to_numberify(response, ['X-API-Time', 'X-API-Query-Count', 'X-API-Query-Time', 'X-API-Node',])
+        req = {
+            'method': request.method,
+            'path': request.path,
+            'path_info': request.path_info,
+            'query_string': request.META['QUERY_STRING'],
+
+        }
+        if request.method == "POST":
+            req['post_data'] = request.POST
+        elif request.method == "GET":
+            req['get_data'] = request.GET
+
+        analytics_logger.info("api response", extra=dict(request=req, x_api=log))
         return response
 
     def get_authenticate_header(self, request):

awx/main/conf.py

@@ -2,6 +2,7 @@
 import json
 import logging
 import os
+import uuid
 
 # Django
 from django.utils.translation import ugettext_lazy as _
@@ -313,3 +314,13 @@ register(
     category=_('Logging'),
     category_slug='logging',
 )
+register(
+    'LOG_TOWER_UUID',
+    field_class=fields.CharField,
+    allow_blank=True,
+    label=_('Cluster-wide Tower unique identifier.'),
+    help_text=_('Useful to uniquely identify Tower instances.'),
+    category=_('Logging'),
+    category_slug='logging',
+    default=uuid.uuid4(),
+)

awx/main/utils/formatters.py

@@ -81,12 +81,14 @@ class LogstashFormatter(LogstashFormatterVersion1):
             else:
                 data_for_log['facts'] = data
             data_for_log['module_name'] = module_name
+        elif kind == 'performance.api':
+            return raw_data
         return data_for_log
 
     def get_extra_fields(self, record):
         fields = super(LogstashFormatter, self).get_extra_fields(record)
         if record.name.startswith('awx.analytics'):
-            log_kind = record.name.split('.')[-1]
+            log_kind = record.name[len('awx.analytics.'):]
             fields = self.reformat_data_for_log(fields, kind=log_kind)
         return fields
 
@@ -100,6 +102,7 @@ class LogstashFormatter(LogstashFormatterVersion1):
             'message': record.getMessage(),
             'host': self.host,
             'type': self.message_type,
+            'tower_uuid': getattr(settings, 'LOG_TOWER_UUID', None),
 
             # Extra Fields
             'level': record.levelname,

awx/main/utils/handlers.py

@@ -116,7 +116,7 @@ class BaseHTTPSHandler(logging.Handler):
         if not logger_name.startswith('awx.analytics'):
             # Tower log emission is only turned off by enablement setting
             return False
-        return self.enabled_loggers is None or logger_name.split('.')[-1] not in self.enabled_loggers
+        return self.enabled_loggers is None or logger_name[len('awx.analytics.'):] not in self.enabled_loggers
 
     def emit(self, record):
         """