From af9975c6af146f1005846847b3b2a36e0a5919c1 Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Mon, 6 Feb 2017 09:14:12 -0500 Subject: [PATCH 1/6] add a new logger, awx.analytics.performance.api * Used to log API timing information --- awx/api/generics.py | 32 ++++++++++++++++++++++++++++++++ awx/main/conf.py | 11 +++++++++++ awx/main/utils/formatters.py | 5 ++++- awx/main/utils/handlers.py | 2 +- 4 files changed, 48 insertions(+), 2 deletions(-) diff --git a/awx/api/generics.py b/awx/api/generics.py index e3bcdc221c..1582355f2e 100644 --- a/awx/api/generics.py +++ b/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): diff --git a/awx/main/conf.py b/awx/main/conf.py index 6bb4c15895..c9f9564f92 100644 --- a/awx/main/conf.py +++ b/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(), +) diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index 94f9b5c0f0..11a2ac3d5d 100644 --- a/awx/main/utils/formatters.py +++ b/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, diff --git a/awx/main/utils/handlers.py b/awx/main/utils/handlers.py index f3e555c4b5..479eafef59 100644 --- a/awx/main/utils/handlers.py +++ b/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): """ From 0dada82b4baea89add277c4e98c76cde7fc4317d Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Sat, 18 Feb 2017 09:28:38 -0500 Subject: [PATCH 2/6] more general name for performance logger --- awx/api/generics.py | 2 +- awx/main/utils/formatters.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/awx/api/generics.py b/awx/api/generics.py index 1582355f2e..90c555c8d3 100644 --- a/awx/api/generics.py +++ b/awx/api/generics.py @@ -41,7 +41,7 @@ __all__ = ['APIView', 'GenericAPIView', 'ListAPIView', 'SimpleListAPIView', 'DeleteLastUnattachLabelMixin',] logger = logging.getLogger('awx.api.generics') -analytics_logger = logging.getLogger('awx.analytics.performance.api') +analytics_logger = logging.getLogger('awx.analytics.performance') def get_view_name(cls, suffix=None): diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index 11a2ac3d5d..4bece1b74f 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -81,7 +81,7 @@ class LogstashFormatter(LogstashFormatterVersion1): else: data_for_log['facts'] = data data_for_log['module_name'] = module_name - elif kind == 'performance.api': + elif kind == 'performance': return raw_data return data_for_log From 31a79c331d38c6d930408401cc8f5b841a5fd953 Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Mon, 20 Feb 2017 14:30:17 -0500 Subject: [PATCH 3/6] move logger logic to formatter --- awx/api/generics.py | 31 +------------------------------ awx/main/utils/formatters.py | 35 ++++++++++++++++++++++++++++++++++- 2 files changed, 35 insertions(+), 31 deletions(-) diff --git a/awx/api/generics.py b/awx/api/generics.py index 90c555c8d3..a71deda2af 100644 --- a/awx/api/generics.py +++ b/awx/api/generics.py @@ -119,36 +119,7 @@ class APIView(views.APIView): 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)) + analytics_logger.info("api response", extra=dict(python_objects=dict(request=request, response=response))) return response def get_authenticate_header(self, request): diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index 4bece1b74f..da5df45726 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -56,6 +56,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: @@ -82,7 +97,25 @@ class LogstashFormatter(LogstashFormatterVersion1): data_for_log['facts'] = data data_for_log['module_name'] = module_name elif kind == 'performance': - return raw_data + 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): From 98c8ff34755a71f104c0ed112f8a9338161c9941 Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Tue, 21 Feb 2017 10:15:02 -0500 Subject: [PATCH 4/6] rename uuid field to trigger restart on update * Since we trigger a restart on update, we can also cache the tower uuid value in the formatter init. So do that. --- awx/main/conf.py | 4 ++-- awx/main/utils/formatters.py | 5 ++++- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/awx/main/conf.py b/awx/main/conf.py index c9f9564f92..6cecb9ec05 100644 --- a/awx/main/conf.py +++ b/awx/main/conf.py @@ -315,12 +315,12 @@ register( category_slug='logging', ) register( - 'LOG_TOWER_UUID', + '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=uuid.uuid4(), + default=None, ) diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index da5df45726..e6095c11d7 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -12,6 +12,7 @@ class LogstashFormatter(LogstashFormatterVersion1): def __init__(self, **kwargs): ret = super(LogstashFormatter, self).__init__(**kwargs) self.host_id = settings.CLUSTER_HOST_ID + self.tower_uuid = getattr(settings, "LOG_AGGREGATOR_TOWER_UUID", None) return ret def reformat_data_for_log(self, raw_data, kind=None): @@ -135,7 +136,6 @@ 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, @@ -143,6 +143,9 @@ class LogstashFormatter(LogstashFormatterVersion1): 'cluster_host_id': self.host_id } + if self.tower_uuid: + message['tower_uuid'] = self.tower_uuid + # Add extra fields message.update(self.get_extra_fields(record)) From 60aa22b01be719eba328aeda2c0ac637aa96062b Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Tue, 21 Feb 2017 10:25:29 -0500 Subject: [PATCH 5/6] flake8 --- awx/main/conf.py | 1 - awx/main/utils/formatters.py | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/awx/main/conf.py b/awx/main/conf.py index 6cecb9ec05..8a2b361ab6 100644 --- a/awx/main/conf.py +++ b/awx/main/conf.py @@ -2,7 +2,6 @@ import json import logging import os -import uuid # Django from django.utils.translation import ugettext_lazy as _ diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index e6095c11d7..bdfac517d5 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -107,7 +107,7 @@ class LogstashFormatter(LogstashFormatterVersion1): (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['x_api'] = {k: convert_to_type(t, response[k]) for (t, k) in headers} data_for_log['request'] = { 'method': request.method, From e78377dcfca87c3e9dff923ad058da2875b01426 Mon Sep 17 00:00:00 2001 From: Chris Meyers Date: Tue, 21 Feb 2017 12:31:15 -0500 Subject: [PATCH 6/6] remove formatters dependency on settings --- awx/main/utils/formatters.py | 12 +++++++----- awx/main/utils/handlers.py | 2 +- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index bdfac517d5..65cb8186a7 100644 --- a/awx/main/utils/formatters.py +++ b/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,9 +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 - self.tower_uuid = getattr(settings, "LOG_AGGREGATOR_TOWER_UUID", None) + 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): @@ -140,11 +141,12 @@ class LogstashFormatter(LogstashFormatterVersion1): # Extra Fields 'level': record.levelname, 'logger_name': record.name, - 'cluster_host_id': self.host_id } - if self.tower_uuid: + 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)) diff --git a/awx/main/utils/handlers.py b/awx/main/utils/handlers.py index 479eafef59..874a5e6046 100644 --- a/awx/main/utils/handlers.py +++ b/awx/main/utils/handlers.py @@ -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