From 7734def856bc28f12bb5c87ca304cc035cb925fe Mon Sep 17 00:00:00 2001 From: Alan Rominger Date: Mon, 30 Nov 2020 11:22:06 -0500 Subject: [PATCH] Fix inventory log timestamp, organize logging code The fixes and issue where the timestaps in the stdout for inventory updates gave the time since the start of the dispatcher instead of the time since the start of the update. This commit also moves the handler into the utils module where other custom AWX handlers live, instead of tasks.py this is to keep tasks.py relatively clean, as best as possible --- awx/main/tasks.py | 52 ++++----------------------------- awx/main/utils/formatters.py | 10 ++++++- awx/main/utils/handlers.py | 56 ++++++++++++++++++++++++++++++++++++ 3 files changed, 70 insertions(+), 48 deletions(-) diff --git a/awx/main/tasks.py b/awx/main/tasks.py index 238f002562..93195edb12 100644 --- a/awx/main/tasks.py +++ b/awx/main/tasks.py @@ -78,6 +78,7 @@ from awx.main.utils.external_logging import reconfigure_rsyslog from awx.main.utils.safe_yaml import safe_dump, sanitize_jinja from awx.main.utils.reload import stop_local_services from awx.main.utils.pglock import advisory_lock +from awx.main.utils.handlers import SpecialInventoryHandler from awx.main.consumers import emit_channel_notification from awx.main import analytics from awx.conf import settings_registry @@ -2740,52 +2741,7 @@ class RunInventoryUpdate(BaseTask): if inventory_update.verbosity: options['verbosity'] = inventory_update.verbosity - # Mock ansible-runner events - class CallbackHandler(logging.Handler): - def __init__(self, event_handler, cancel_callback, job_timeout, verbosity, - start_time=None, counter=0, initial_line=0, **kwargs): - self.event_handler = event_handler - self.cancel_callback = cancel_callback - self.job_timeout = job_timeout - if start_time is None: - self.job_start = now() - else: - self.job_start = start_time - self.last_check = self.job_start - self.counter = counter - self.skip_level = [logging.WARNING, logging.INFO, logging.DEBUG, 0][verbosity] - self._start_line = initial_line - super(CallbackHandler, self).__init__(**kwargs) - - def emit(self, record): - this_time = now() - if (this_time - self.last_check).total_seconds() > 0.5: - self.last_check = this_time - if self.cancel_callback(): - raise PostRunError('Inventory update has been canceled', status='canceled') - if self.job_timeout and ((this_time - self.job_start).total_seconds() > self.job_timeout): - raise PostRunError('Inventory update has timed out', status='canceled') - - # skip logging for low severity logs - if record.levelno < self.skip_level: - return - - self.counter += 1 - msg = self.format(record) - n_lines = len(msg.strip().split('\n')) # don't count new-lines at boundry of text - dispatch_data = dict( - created=now().isoformat(), - event='verbose', - counter=self.counter, - stdout=msg, - start_line=self._start_line, - end_line=self._start_line + n_lines - ) - self._start_line += n_lines - - self.event_handler(dispatch_data) - - handler = CallbackHandler( + handler = SpecialInventoryHandler( self.event_handler, self.cancel_callback, verbosity=inventory_update.verbosity, job_timeout=self.get_instance_timeout(self.instance), @@ -2793,7 +2749,9 @@ class RunInventoryUpdate(BaseTask): counter=self.event_ct, initial_line=self.end_line ) inv_logger = logging.getLogger('awx.main.commands.inventory_import') - handler.formatter = inv_logger.handlers[0].formatter + formatter = inv_logger.handlers[0].formatter + formatter.job_start = inventory_update.started + handler.formatter = formatter inv_logger.handlers[0] = handler from awx.main.management.commands.inventory_import import Command as InventoryImportCommand diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index 171a994435..8afd121d5c 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -9,6 +9,7 @@ import socket from datetime import datetime from dateutil.tz import tzutc +from django.utils.timezone import now from django.core.serializers.json import DjangoJSONEncoder from django.conf import settings @@ -17,8 +18,15 @@ class TimeFormatter(logging.Formatter): ''' Custom log formatter used for inventory imports ''' + def __init__(self, start_time=None, **kwargs): + if start_time is None: + self.job_start = now() + else: + self.job_start = start_time + super(TimeFormatter, self).__init__(**kwargs) + def format(self, record): - record.relativeSeconds = record.relativeCreated / 1000.0 + record.relativeSeconds = (now() - self.job_start).total_seconds() return logging.Formatter.format(self, record) diff --git a/awx/main/utils/handlers.py b/awx/main/utils/handlers.py index c5e0014f8e..b6eefd9c59 100644 --- a/awx/main/utils/handlers.py +++ b/awx/main/utils/handlers.py @@ -7,6 +7,10 @@ import os.path # Django from django.conf import settings +from django.utils.timezone import now + +# AWX +from awx.main.exceptions import PostRunError class RSysLogHandler(logging.handlers.SysLogHandler): @@ -40,6 +44,58 @@ class RSysLogHandler(logging.handlers.SysLogHandler): pass +class SpecialInventoryHandler(logging.Handler): + """Logging handler used for the saving-to-database part of inventory updates + ran by the task system + this dispatches events directly to be processed by the callback receiver, + as opposed to ansible-runner + """ + + def __init__(self, event_handler, cancel_callback, job_timeout, verbosity, + start_time=None, counter=0, initial_line=0, **kwargs): + self.event_handler = event_handler + self.cancel_callback = cancel_callback + self.job_timeout = job_timeout + if start_time is None: + self.job_start = now() + else: + self.job_start = start_time + self.last_check = self.job_start + self.counter = counter + self.skip_level = [logging.WARNING, logging.INFO, logging.DEBUG, 0][verbosity] + self._current_line = initial_line + super(SpecialInventoryHandler, self).__init__(**kwargs) + + def emit(self, record): + # check cancel and timeout status regardless of log level + this_time = now() + if (this_time - self.last_check).total_seconds() > 0.5: # cancel callback is expensive + self.last_check = this_time + if self.cancel_callback(): + raise PostRunError('Inventory update has been canceled', status='canceled') + if self.job_timeout and ((this_time - self.job_start).total_seconds() > self.job_timeout): + raise PostRunError('Inventory update has timed out', status='canceled') + + # skip logging for low severity logs + if record.levelno < self.skip_level: + return + + self.counter += 1 + msg = self.format(record) + n_lines = len(msg.strip().split('\n')) # don't count line breaks at boundry of text + dispatch_data = dict( + created=now().isoformat(), + event='verbose', + counter=self.counter, + stdout=msg, + start_line=self._current_line, + end_line=self._current_line + n_lines + ) + self._current_line += n_lines + + self.event_handler(dispatch_data) + + ColorHandler = logging.StreamHandler if settings.COLOR_LOGS is True: