Merge pull request #5438 from chrismeyersfsu/private-performance_logging

add a new type of logger, performance.api

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')
 
 
 def get_view_name(cls, suffix=None):
@@ -117,6 +118,8 @@ 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)
+
+        analytics_logger.info("api response", extra=dict(python_objects=dict(request=request, response=response)))
         return response
 
     def get_authenticate_header(self, request):

awx/main/conf.py

@@ -313,3 +313,13 @@ register(
     category=_('Logging'),
     category_slug='logging',
 )
+register(
+    'LOG_AGGREGATOR_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=None,
+)

awx/main/utils/formatters.py

@@ -2,7 +2,6 @@
 # All Rights Reserved.
 
 from logstash.formatter import LogstashFormatterVersion1
-from django.conf import settings
 from copy import copy
 import json
 import time
@@ -10,8 +9,11 @@ import time
 
 class LogstashFormatter(LogstashFormatterVersion1):
     def __init__(self, **kwargs):
+        settings_module = kwargs.pop('settings_module', None)
         ret = super(LogstashFormatter, self).__init__(**kwargs)
-        self.host_id = settings.CLUSTER_HOST_ID
+        if settings_module:
+            self.host_id = settings_module.CLUSTER_HOST_ID
+            self.tower_uuid = settings_module.LOG_AGGREGATOR_TOWER_UUID
         return ret
 
     def reformat_data_for_log(self, raw_data, kind=None):
@@ -56,6 +58,21 @@ class LogstashFormatter(LogstashFormatterVersion1):
                     adict[name] = subdict
             return adict
 
+        def convert_to_type(t, val):
+            if t is float:
+                val = val[:-1] if val.endswith('s') else val
+                try:
+                    return float(val)
+                except ValueError:
+                    return val
+            elif t is int:
+                try:
+                    return int(val)
+                except ValueError:
+                    return val
+            elif t is str:
+                return val
+
         if kind == 'job_events':
             data.update(data.get('event_data', {}))
             for fd in data:
@@ -81,12 +98,32 @@ class LogstashFormatter(LogstashFormatterVersion1):
             else:
                 data_for_log['facts'] = data
             data_for_log['module_name'] = module_name
+        elif kind == 'performance':
+            request = raw_data['python_objects']['request']
+            response = raw_data['python_objects']['response']
+
+            headers = [
+                (float, 'X-API-Time'),  # may end with an 's' "0.33s"
+                (int, 'X-API-Query-Count'),
+                (float, 'X-API-Query-Time'), # may also end with an 's'
+                (str, 'X-API-Node'),
+            ]
+            data_for_log['x_api'] = {k: convert_to_type(t, response[k]) for (t, k) in headers}
+
+            data_for_log['request'] = {
+                'method': request.method,
+                'path': request.path,
+                'path_info': request.path_info,
+                'query_string': request.META['QUERY_STRING'],
+                'data': request.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
 
@@ -104,9 +141,13 @@ class LogstashFormatter(LogstashFormatterVersion1):
             # Extra Fields
             'level': record.levelname,
             'logger_name': record.name,
-            'cluster_host_id': self.host_id
         }
 
+        if getattr(self, 'tower_uuid', None):
+            message['tower_uuid'] = self.tower_uuid
+        if getattr(self, 'host_id', None):
+            message['cluster_host_id'] = self.host_id
+
         # Add extra fields
         message.update(self.get_extra_fields(record))
 

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):
         """
@@ -189,7 +189,7 @@ def configure_external_logger(settings_module, async_flag=True, is_startup=True)
     instance = None
     if is_enabled:
         instance = BaseHTTPSHandler.from_django_settings(settings_module, async=async_flag)
-        instance.setFormatter(LogstashFormatter())
+        instance.setFormatter(LogstashFormatter(settings_module=settings_module))
     awx_logger_instance = instance
     if is_enabled and 'awx' not in settings_module.LOG_AGGREGATOR_LOGGERS:
         awx_logger_instance = None