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: