def handle_request(self):
"""
Handles the custom resource request from cloudformation
:return:
"""
start = datetime.now()
self._logger.info("Cloudformation request is {}",
safe_json(self._event, indent=2))
try:
result = CustomResource.handle_request(self)
return safe_dict({
"result":
result,
"datetime":
datetime.now().isoformat(),
"running-time": (datetime.now() - start).total_seconds()
})
except Exception as ex:
self._logger.error(ERR_HANDLING_SETUP_REQUEST, ex, full_stack())
raise ex
finally:
self._logger.flush()
def lambda_handler(event, context):
dt = datetime.utcnow()
log_stream_name = LOG_STREAM.format("OpsAutomatorMain", dt.year, dt.month, dt.day)
with outputs.queued_logger.QueuedLogger(logstream=log_stream_name, context=context, buffersize=20) as logger:
for handler_name in handlers.all_handlers():
try:
if not handlers.get_class_for_handler(handler_name).is_handling_request(event, context):
continue
except Exception as ex:
logger.error(ERR_IS_HANDLING, handler_name, safe_json(event, indent=2), ex)
break
if context is not None and os.getenv(ENV_DEBUG_MAIN_EVENT_HANDLER, "false").lower() == "true":
print("Handler is {}".format(handler_name))
print("Event is {}".format(safe_json(event, indent=3)))
handler = handlers.create_handler(handler_name, event, context)
try:
logger.debug(DEBUG_HANDLER_INFO, handler_name)
result = handler.handle_request()
return safe_dict(result)
except Exception as e:
logger.error(ERR_HANDLING_REQUEST, safe_json(event, indent=2), handler_name, e, full_stack())
finally:
if len(boto_retry.statistics) > 0:
logger.info(MSG_BOTO_STATS, safe_json(boto_retry.statistics, indent=3))
boto_retry.clear_statistics()
return
else:
logger.debug(MSG_NO_REQUEST_HANDLER, safe_json(event, indent=2))
def handle_request(self):
"""
Handles the cloudwatch rule timer event
:return: Started tasks, if any, information
"""
try:
start = datetime.now()
count = 0
tracking_table = TaskTrackingTable(context=self._context,
logger=self._logger)
for task in tracking_table.get_tasks_to_check_for_completion():
count += 1
task_id = task[handlers.TASK_TR_ID]
last_check_for_completion_time = datetime.now().isoformat()
tracking_table.update_task(
task_id,
task=task.get(handlers.TASK_TR_NAME, None),
task_metrics=task.get(handlers.TASK_TR_METRICS, False),
status_data={
handlers.TASK_TR_LAST_WAIT_COMPLETION:
last_check_for_completion_time
})
self._logger.debug("Task is {}", task)
self._logger.info(INF_SET_COMPLETION_TASK_TIMER,
task.get(handlers.TASK_TR_NAME, None),
task_id, last_check_for_completion_time)
running_time = float((datetime.now() - start).total_seconds())
self._logger.info(INF_COMPLETION_ITEMS_SET, running_time, count)
if count == 0 and not handlers.running_local(self._context):
rule = handlers.disable_completion_cloudwatch_rule(
self._context)
self._logger.info(INF_DISABLED_COMPLETION_TIMER, rule)
return safe_dict({
"datetime": datetime.now().isoformat(),
"running-time": running_time,
"tasks-to-check": count
})
except ValueError as ex:
self._logger.error(ERR_COMPLETION_HANDLER, ex,
safe_json(self._event, indent=2))
finally:
self._logger.flush()
def handle_request(self):
start = datetime.now()
self._logger.info("Cloudformation request is {}",
safe_json(self._event, indent=2))
try:
result = CustomResource.handle_request(self)
return safe_dict({
"datetime":
datetime.now().isoformat(),
"running-time": (datetime.now() - start).total_seconds(),
"result":
result
})
finally:
self._logger.flush()
def handle_execute_task_request(self, task_config):
self._logger.info(INF_HANDLING_EXEC_REQUEST, self.executed_task_name)
task_to_execute = task_config.get_task(name=self.executed_task_name)
if task_to_execute is None:
raise ValueError(
"Task with name {} does not exists for stack {}".format(
self.executed_task_name,
os.getenv(handlers.ENV_STACK_NAME)))
if not task_to_execute.get(handlers.TASK_ENABLED):
raise ValueError("Task with name {} is not enabled",
self.executed_task_name)
task_group, sub_tasks = self._execute_task(task_to_execute)
return safe_dict({
"datetime": datetime.now().isoformat(),
"executed-task": self.executed_task_name,
"task-group": task_group,
"sub-tasks": sub_tasks
})
def handle_request(self):
"""
Handles the event triggered by updates to the actions tracking table.
:return: results of handling selected updates
"""
def tasks_items_to_execute():
"""
Generator function that selects all record items from the event that need processing.
:return:
"""
def table_name(rec):
source_arn = rec["eventSourceARN"]
return source_arn.split("/")[1]
def from_tracking_table(rec):
return table_name(rec) == os.getenv(
handlers.ENV_ACTION_TRACKING_TABLE)
def from_concurrency_table(rec):
return table_name(rec) == os.getenv(
handlers.ENV_CONCURRENCY_TABLE)
def get_old_image(task_record):
return task_record["dynamodb"].get("OldImage", {})
def get_new_image(task_record):
return task_record["dynamodb"].get("NewImage", {})
def get_new_status(task_record):
return get_new_image(task_record).get(handlers.TASK_TR_STATUS,
{}).get("S")
def get_old_status(task_record):
return get_new_image(task_record).get(handlers.TASK_TR_STATUS,
{}).get("S")
def is_task_tracking_table_update(task_record):
if not from_tracking_table(task_record):
return False
return task_record["eventName"] in ["UPDATE", "MODIFY"]
def is_task_done(task_record):
if not is_task_tracking_table_update(task_record):
return False
new_status = get_new_status(task_record)
old_status = get_old_status(task_record)
if old_status != new_status:
return False
return new_status in handlers.task_tracking_table.NOT_LONGER_ACTIVE_STATUSES
def is_task_with_concurrency(task_record):
return get_new_image(task_record).get(
handlers.TASK_TR_CONCURRENCY_KEY, {}).get("S") is not None
def get_old_last_update(task_record):
return get_old_image(task_record).get(
handlers.TASK_TR_LAST_WAIT_COMPLETION, {}).get("S")
def get_new_last_update(task_record):
return get_new_image(task_record).get(
handlers.TASK_TR_LAST_WAIT_COMPLETION, {}).get("S")
def is_delete_task(task_record):
return from_tracking_table(
r) and task_record["eventName"] == "REMOVE"
def is_new_task(task_record):
if from_tracking_table(
r) and task_record["eventName"] == "INSERT":
return get_new_status(
task_record) == handlers.STATUS_PENDING
return False
def is_completed_with_concurrency(task_record):
return is_task_done(task_record) and is_task_with_concurrency(
task_record)
def is_completed_without_concurrency(task_record):
return is_task_done(
task_record) and not is_task_with_concurrency(task_record)
def is_wait_for_completion(task_record):
if not is_task_tracking_table_update(task_record):
return False
if get_old_status(task_record) != handlers.STATUS_WAIT_FOR_COMPLETION or \
get_new_status(task_record) != handlers.STATUS_WAIT_FOR_COMPLETION:
return False
return get_old_last_update(task_record) != get_new_last_update(
task_record)
def is_concurrency_task_completed(concurrency_record):
if not from_concurrency_table(concurrency_record):
return False
if concurrency_record["eventName"] == "REMOVE":
return False
return concurrency_record["dynamodb"].get("NewImage", {}).get(
"RunNext", {}).get("BOOL", False)
def get_action_type(rec):
if is_new_task(rec):
return NEW_TASK
if is_completed_without_concurrency(rec):
return FINISHED_TASK
if is_completed_with_concurrency(rec):
return FINISHED_CONCURRENCY_TASK
if is_wait_for_completion(rec):
return CHECK_COMPLETION
if is_delete_task(rec):
return DELETE_ITEM
if is_concurrency_task_completed(rec):
return START_WAITING_ACTION
return None
for r in self._event.get("Records"):
self._logger.debug("Record to process is {}",
safe_json(r, indent=2))
if r.get("eventSource") == "aws:dynamodb":
image_used = "NewImage" if "NewImage" in r[
"dynamodb"] else "OldImage"
if r["dynamodb"].get("NewImage", {}).get(handlers.TASK_TR_ACTION) is None and \
r["dynamodb"].get("OldImage", {}).get(handlers.TASK_TR_ACTION) is not None:
continue
self._logger.debug_enabled = r["dynamodb"][image_used].get(
handlers.TASK_TR_DEBUG, {}).get("BOOL", False)
update_to_handle = get_action_type(r)
if update_to_handle is not None:
yield update_to_handle, r
else:
self._logger.debug("No action for record")
try:
start = datetime.now()
task_handlers = [
self._handle_new_task_item,
self._handle_finished_task_without_completion,
self._handle_completed_concurrency_item,
self._handle_check_completion, self._handle_deleted_item,
self._handle_start_waiting_action
]
for task_tracking_update_type, record in tasks_items_to_execute():
self.done_work = True
used_image = "OldImage" if record[
"eventName"] == "REMOVE" else "NewImage"
image = record["dynamodb"][used_image]
handled_item = unpack_record(image)
self._logger.debug_enabled = handled_item.get(
handlers.TASK_TR_DEBUG, False)
self._logger.debug(
"Executing handler function {} for type {} ({})",
task_handlers[task_tracking_update_type].__name__,
self.task_string(task_tracking_update_type),
task_tracking_update_type)
task_handlers[task_tracking_update_type](handled_item)
if not self.done_work:
self._logger.clear()
running_time = float((datetime.now() - start).total_seconds())
if self.done_work:
self._logger.debug(DEBUG_RESULT, running_time)
return safe_dict({
"datetime": datetime.now().isoformat(),
"waiting-for-execution": self.waiting_for_execution_tasks,
"started-check-for-completion": self.started_completion_checks,
"started-execution": self.started_tasks,
"started-waiting": self.started_waiting_tasks,
"completed-concurrency-tasks": self.finished_concurrency_tasks,
"running-time": running_time
})
finally:
self._logger.flush()
def handle_scheduler_tasks(self, task_config):
started_tasks = {}
start = datetime.now()
last_run_dt = self._get_last_run()
self._logger.info(INFO_LAST_SAVED, last_run_dt.isoformat())
if self.configuration_update:
self._logger.info(INFO_CONFIG_RUN, self.updated_task)
current_dt = self._set_last_run()
already_ran_this_minute = last_run_dt == current_dt
if already_ran_this_minute and not (self.configuration_update
or self.execute_task_request):
self._logger.info(INFO_TASK_SCHEDULER_ALREADY_RAN)
else:
self._logger.info(INFO_CURRENT_SCHEDULING_DT, current_dt)
task = None
enabled_tasks = 0
next_executed_task = None
utc = pytz.timezone("UTC")
tasks = [
t for t in task_config.get_tasks()
if t.get(handlers.TASK_INTERVAL) is not None
and t.get(handlers.TASK_ENABLED, True)
]
try:
for task in tasks:
enabled_tasks += 1
self._logger.debug_enabled = task[handlers.TASK_DEBUG]
task_name = task[handlers.TASK_NAME]
# timezone for specific task
task_timezone = pytz.timezone(task[handlers.TASK_TIMEZONE])
# create cron expression to test if task needs te be executed
task_cron_expression = CronExpression(
expression=task[handlers.TASK_INTERVAL])
localized_last_run = last_run_dt.astimezone(task_timezone)
localized_current_dt = current_dt.astimezone(task_timezone)
next_execution = task_cron_expression.first_within_next(
timedelta(hours=24), localized_current_dt)
next_execution_utc = next_execution.astimezone(
utc).replace(microsecond=0
) if next_execution is not None else None
if next_execution_utc is not None:
if next_executed_task is None or next_execution_utc < next_executed_task[
0]:
next_executed_task = (next_execution_utc, task)
if already_ran_this_minute:
continue
# test if task needs te be executed since last run of ops automator
execute_dt_since_last = task_cron_expression.last_since(
localized_last_run, localized_current_dt)
if execute_dt_since_last is None:
if next_execution is not None:
next_execution = next_execution.astimezone(
task_timezone)
self._logger.info(INFO_NEXT_EXECUTION, task_name,
next_execution.isoformat(),
task_timezone)
else:
self._logger.info(INFO_NO_NEXT_WITHIN, task_name)
continue
self._logger.info(INFO_SCHEDULED_TASK, task_name,
execute_dt_since_last, task_timezone,
str(safe_json(task, indent=2)))
# create an event for lambda function that starts execution by selecting for resources for this task
task_group, sub_tasks = self._execute_task(
task, execute_dt_since_last)
started_tasks[task_name] = {
"task-group": task_group,
"sub-tasks": sub_tasks
}
if started_tasks:
self._logger.info(INFO_STARTED_TASKS, enabled_tasks,
",".join(started_tasks))
else:
self._logger.info(INFO_NO_TASKS_STARTED, enabled_tasks)
self._set_next_schedule_event(current_dt, next_executed_task)
running_time = float((datetime.now() - start).total_seconds())
return safe_dict({
"datetime": datetime.now().isoformat(),
"running-time": running_time,
"event-datetime": current_dt.isoformat(),
"enabled_tasks": enabled_tasks,
"started-tasks": started_tasks
})
except ValueError as ex:
self._logger.error(ERR_SCHEDULE_HANDLER, ex,
safe_json(task, indent=2))
def handle_request(self):
"""
Handles the select resources request. Creates new actions for resources found for a task
:return: Results of handling the request
"""
def filter_by_action_filter(srv, used_role, r):
filter_method = getattr(self.action_class,
actions.SELECT_AND_PROCESS_RESOURCE_METHOD,
None)
if filter_method is not None:
r = filter_method(srv, self._logger, self._resource_name, r,
self._context, self.task, used_role)
if r is None:
self._logger.debug(
DEBUG_FILTER_METHOD, self.action_class.__name__,
actions.SELECT_AND_PROCESS_RESOURCE_METHOD)
return None
else:
self._logger.debug(
DEBUG_FILTERED_RESOURCE, self.action_class.__name__,
actions.SELECT_AND_PROCESS_RESOURCE_METHOD,
safe_json(r, indent=3))
return r
def is_selected_resource(aws_service, resource, used_role, taskname,
tags_filter, does_resource_supports_tags):
# No tags then just use filter method if any
if not does_resource_supports_tags:
self._logger.debug(DEBUG_RESOURCE_NO_TAGS, resource)
return filter_by_action_filter(srv=aws_service,
used_role=used_role,
r=resource)
tags = resource.get("Tags", {})
# name of the tag that holds the list of tasks for this resource
tagname = self._task_tag
if tags_filter is None:
# test if name of the task is in list of tasks in tag value
if (tagname not in tags) or (taskname
not in tagging.split_task_list(
tags[tagname])):
self._logger.debug(
DEBUG_RESOURCE_NOT_SELECTED,
safe_json(resource, indent=2), taskname, ','.join(
["'{}'='{}'".format(t, tags[t]) for t in tags]))
return None
self._logger.debug(DEBUG_SELECTED_BY_TASK_NAME_IN_TAG_VALUE,
safe_json(resource, indent=2), tagname,
taskname)
else:
# using a tag filter, * means any tag
if tags_filter != tagging.tag_filter_set.WILDCARD_CHAR:
# test if there are any tags matching the tag filter
if not TagFilterExpression(tags_filter).is_match(tags):
self._logger.debug(
DEBUG_RESOURCE_NOT_SELECTED_TAG_FILTER,
safe_json(resource, indent=2), taskname, ','.join([
"'{}'='{}'".format(t, tags[t]) for t in tags
]))
return None
self._logger.debug(DEBUG_SELECTED_BY_TAG_FILTER,
safe_json(resource, indent=2), tags,
tag_filter_str, taskname)
else:
self._logger.debug(DEBUG_SELECTED_WILDCARD_TAG_FILTER,
safe_json(resource, indent=2), taskname)
return filter_by_action_filter(srv=aws_service,
used_role=used_role,
r=resource)
return filter_by_action_filter(srv=aws_service,
used_role=used_role,
r=resource)
def resource_batches(resources):
"""
Returns resources as chunks of size items. If the class has an optional custom aggregation function then the
resources are aggregated first using this function before applying the batch size
:param resources: resources to process
:return: Generator for blocks of resource items
"""
aggregate_func = getattr(self.action_class,
actions.CUSTOM_AGGREGATE_METHOD, None)
for i in aggregate_func(
resources, self.task_parameters,
self._logger) if aggregate_func is not None else [
resources
]:
if self.batch_size is None:
yield i
else:
first = 0
while first < len(i):
yield i[first:first + self.batch_size]
first += self.batch_size
def setup_tag_filtering(t_name):
# get optional tag filter
no_select_by_tags = self.action_properties.get(
actions.ACTION_NO_TAG_SELECT, False)
if no_select_by_tags:
tag_filter_string = tagging.tag_filter_set.WILDCARD_CHAR
else:
tag_filter_string = self.task.get(handlers.TASK_TAG_FILTER)
# set if only a single task is required for selecting the resources, it is used to optimise the select
select_tag = None
if tag_filter_string is None:
self._logger.debug(DEBUG_SELECT_BY_TASK_NAME,
self._resource_name, self._task_tag, t_name)
select_tag = self._task_tag
elif tag_filter_string == tagging.tag_filter_set.WILDCARD_CHAR:
self._logger.debug(DEBUG_SELECT_ALL_RESOURCES,
self._resource_name)
else:
self._logger.debug(DEBUG_TAG_FILTER_USED_TO_SELECT_RESOURCES,
self._resource_name)
# build the tag expression that us used to filter the resources
tag_filter_expression = TagFilterExpression(tag_filter_string)
# the keys of the used tags
tag_filter_expression_tag_keys = list(
tag_filter_expression.get_filter_keys())
# if there is only a single tag then we can optimize by just filtering on that specific tag
if len(tag_filter_expression_tag_keys) == 1 and \
tagging.tag_filter_set.WILDCARD_CHAR not in tag_filter_expression_tag_keys[0]:
select_tag = tag_filter_expression_tag_keys[0]
return select_tag, tag_filter_string
def add_aggregated(aggregated_resources):
# create tasks action for aggregated resources , optionally split in batch size chunks
for ra in resource_batches(aggregated_resources):
if self._check_can_execute(ra):
action_item = self.actions_tracking.add_task_action(
task=self.task,
assumed_role=assumed_role,
action_resources=ra,
task_datetime=self.task_dt,
source=self.source,
task_group=self.task_group)
self._logger.debug(DEBUG_ADDED_AGGREGATED_RESOURCES_TASK,
action_item[handlers.TASK_TR_ID],
len(ra), self._resource_name,
self.task[handlers.TASK_NAME])
self._logger.debug("Added item\n{}",
safe_json(action_item, indent=3))
yield action_item
def add_as_individual(resources):
for ri in resources:
# task action for each selected resource
if self._check_can_execute([ri]):
action_item = self.actions_tracking.add_task_action(
task=self.task,
assumed_role=assumed_role,
action_resources=ri,
task_datetime=self.task_dt,
source=self.source,
task_group=self.task_group)
self._logger.debug(DEBUG_ADD_SINGLE_RESOURCE_TASK,
action_item[handlers.TASK_TR_ID],
self._resource_name,
self.task[handlers.TASK_NAME])
self._logger.debug("Added item\n{}",
safe_json(action_item, indent=3))
yield action_item
try:
task_items = []
start = datetime.now()
self._logger.debug(DEBUG_EVENT, safe_json(self._event, indent=3))
self._logger.debug(DEBUG_ACTION,
safe_json(self.action_properties, indent=3))
self._logger.info(INFO_SELECTED_RESOURCES, self._resource_name,
self.service, self.task[handlers.TASK_NAME])
self._logger.info(INFO_AGGR_LEVEL, self.aggregation_level)
task_level_aggregated_resources = []
args = self._build_describe_argument()
service_resource_with_tags = services.create_service(
self.service).resources_with_tags
if self._resource_name == "":
supports_tags = len(service_resource_with_tags) != 0
else:
supports_tags = self._resource_name.lower() in [
r.lower() for r in service_resource_with_tags
]
args["tags"] = supports_tags
self._logger.info(INFO_USE_TAGS_TO_SELECT,
"R" if supports_tags else "No r")
task_name = self.task[handlers.TASK_NAME]
count_resource_items = 0
selected_resource_items = 0
select_on_tag, tag_filter_str = setup_tag_filtering(task_name)
filter_func = getattr(self.action_class,
actions.FILTER_RESOURCE_METHOD, None)
# timer to guard selection time and log warning if getting close to lambda timeout
if self._context is not None:
self.start_timer(REMAINING_TIME_AFTER_DESCRIBE)
try:
for assumed_role in self._task_assumed_roles():
retry_strategy = get_default_retry_strategy(
service=self.service, context=self._context)
service = services.create_service(
service_name=self.service,
service_retry_strategy=retry_strategy,
role_arn=assumed_role)
if self.is_timed_out():
break
# contains resources for account
account_level_aggregated_resources = []
self._logger.info(INFO_ACCOUNT, service.aws_account)
if assumed_role not in [None, ""]:
self._logger.info(INFO_ASSUMED_ROLE, assumed_role)
for region in self._regions:
# test for timeouts
if self.is_timed_out():
break
# handle region passed in the event
if region is not None:
args["region"] = region
else:
if "region" in args:
del args["region"]
# resources can be passed in the invent by event handlers
all_resources = self._event.get(
handlers.HANDLER_SELECT_RESOURCES, None)
if all_resources is None:
# actions can have an optional method to select resources
action_custom_describe_function = getattr(
self.action_class, "describe_resources", None)
if action_custom_describe_function is not None and self.use_custom_select:
all_resources = action_custom_describe_function(
service, self.task, region)
else:
# select resources from the service
self._logger.debug(DEBUG_SELECT_PARAMETERS,
self._resource_name,
self.service, args)
# selecting a list of all resources in this account/region
all_resources = list(
service.describe(
self._resource_name,
filter_func=filter_func,
select_on_tag=select_on_tag,
**args))
# test for timeout
if self.is_timed_out():
break
count_resource_items += len(all_resources)
self._logger.info(INFO_RESOURCES_FOUND,
len(all_resources))
# select resources that are processed by the task
selected_resources = []
for sr in all_resources:
sel = is_selected_resource(
aws_service=service,
resource=sr,
used_role=assumed_role,
taskname=task_name,
tags_filter=tag_filter_str,
does_resource_supports_tags=supports_tags)
if sel is not None:
selected_resources.append(sel)
selected_resource_items += len(selected_resources)
# display found and selected resources
if len(all_resources) > 0:
self._logger.info(INFO_RESOURCES_SELECTED,
len(selected_resources))
if len(selected_resources) == 0:
continue
# delete tags if not needed by the action
if not self.keep_tags:
for res in selected_resources:
if "Tags" in res:
del res["Tags"]
# add resources to total list of resources for this task
if self.aggregation_level == actions.ACTION_AGGREGATION_TASK:
task_level_aggregated_resources += selected_resources
# add resources to list of resources for this account
if self.aggregation_level == actions.ACTION_AGGREGATION_ACCOUNT:
account_level_aggregated_resources += selected_resources
# add batch(es) of resources for this region
if self.aggregation_level == actions.ACTION_AGGREGATION_REGION and len(
selected_resources) > 0:
task_items += list(
add_aggregated(selected_resources))
# no aggregation, add each individual resource
if self.aggregation_level == actions.ACTION_AGGREGATION_RESOURCE and len(
selected_resources) > 0:
task_items += list(
add_as_individual(selected_resources))
# at the end of the region loop, check if aggregated resources for account need to be added
if self.aggregation_level == actions.ACTION_AGGREGATION_ACCOUNT and len(
account_level_aggregated_resources) > 0:
task_items += list(
add_aggregated(account_level_aggregated_resources))
# at the end of the accounts loop, check if aggregated resources for task need to be added
if self.aggregation_level == actions.ACTION_AGGREGATION_TASK and len(
task_level_aggregated_resources) > 0:
task_items += list(
add_aggregated(task_level_aggregated_resources))
except Exception as ex:
raise_exception(ERR_SELECTING_TASK_RESOURCES,
self.task[handlers.TASK_NAME], ex)
finally:
if self._timer is not None:
# cancel time used avoid timeouts when selecting resources
self._timer.cancel()
if self.is_timed_out():
raise_exception(ERR_TIMEOUT_SELECTING_RESOURCES,
self._resource_name, self.service,
task_name)
self.start_timer(REMAINING_TIME_AFTER_STORE)
self.actions_tracking.flush(self._timeout_event)
if self.is_timed_out():
raise_exception(
ERR_CREATING_TASKS_FOR_SELECTED_RESOURCES,
task_name)
self._timer.cancel()
else:
self.actions_tracking.flush()
self._logger.info(INFO_ADDED_ITEMS, len(task_items),
self.task[handlers.TASK_NAME])
running_time = float((datetime.now() - start).total_seconds())
self._logger.info(INFO_RESULT, running_time)
if self.metrics:
put_task_select_data(task_name=task_name,
items=count_resource_items,
selected_items=selected_resource_items,
logger=self._logger,
selection_time=running_time)
return safe_dict({
"datetime": datetime.now().isoformat(),
"running-time": running_time,
"dispatched-tasks": task_items
})
finally:
self._logger.flush()
def handle_request(self, use_custom_select=True):
"""
Handled the cloudwatch rule timer event
:return: Started tasks, if any, information
"""
try:
self._logger.info("Handling CloudWatch event {}",
safe_json(self._event, indent=3))
result = []
start = datetime.now()
dt = self._event_time()
config_task = None
source_resource_tags = None
try:
# for all events tasks in configuration
for config_task in TaskConfiguration(
context=self._context,
logger=self._logger).get_tasks():
self._logger.debug_enabled = config_task.get(
handlers.TASK_DEBUG, False)
if not self._event_triggers_task(task=config_task):
continue
# tasks that can react to events with a wider resource scope than the actual resource causing the event may
# have a filter that can is used to filter based on the tags of the resource
event_source_tag_filter = config_task.get(
handlers.TASK_EVENT_SOURCE_TAG_FILTER, None)
if event_source_tag_filter is not None:
if source_resource_tags is None:
# get the tags for the source resource of the event
session = services.get_session(
self._role_executing_triggered_task,
logger=self._logger)
if session is None:
self._logger.error(
ERR_NO_SESSION_FOR_GETTING_TAGS)
continue
try:
source_resource_tags = self._source_resource_tags(
session, config_task)
except Exception as ex:
self._logger.error(
ERR_GETTING_EVENT_SOURCE_RESOURCE_TAGS, ex)
continue
self._logger.debug(
"Tags for event source resource are {}",
source_resource_tags)
# apply filter to source resource tags
if not TagFilterExpression(
event_source_tag_filter).is_match(
source_resource_tags):
self._logger.debug(
"Tags of source resource do not match tag filter {}",
event_source_tag_filter)
continue
task_name = config_task[handlers.TASK_NAME]
result.append(task_name)
select_parameters = self._select_parameters(
self._event_name(), config_task)
if select_parameters is None:
continue
self._logger.debug(DEBUG_EVENT, task_name,
self._event_name(), select_parameters,
self._event_account(),
self._event_region(),
safe_json(config_task, indent=3))
# create an event for lambda function that scans for resources for this task
lambda_event = {
handlers.HANDLER_EVENT_ACTION:
handlers.HANDLER_ACTION_SELECT_RESOURCES,
handlers.HANDLER_EVENT_CUSTOM_SELECT:
use_custom_select,
handlers.HANDLER_SELECT_ARGUMENTS: {
handlers.HANDLER_EVENT_REGIONS:
[self._event_region()],
handlers.HANDLER_EVENT_ACCOUNT:
self._event_account(),
handlers.HANDLER_EVENT_RESOURCE_NAME:
config_task[handlers.TASK_RESOURCE_TYPE],
},
handlers.HANDLER_EVENT_SOURCE:
"{}:{}:{}".format(self._handled_event_source,
self._handled_detail_type,
self._event_name()),
handlers.HANDLER_EVENT_TASK:
config_task,
handlers.HANDLER_EVENT_TASK_DT:
dt
}
for i in select_parameters:
lambda_event[handlers.HANDLER_SELECT_ARGUMENTS][
i] = select_parameters[i]
if self._event_resources() is not None:
self._logger.debug(
DEBUG_EVENT_RESOURCES,
safe_json(self._event_resources(), indent=3))
lambda_event[
handlers.
HANDLER_SELECT_RESOURCES] = self._event_resources(
)
if not handlers.running_local(self._context):
# start lambda function to scan for task resources
payload = str.encode(safe_json(lambda_event))
client = get_client_with_retries("lambda", ["invoke"],
context=self._context,
logger=self._logger)
client.invoke_with_retries(
FunctionName=self._context.function_name,
InvocationType="Event",
LogType="None",
Payload=payload)
else:
# or if not running in lambda environment pass event to main task handler
lambda_handler(lambda_event, None)
return safe_dict({
"datetime":
datetime.now().isoformat(),
"running-time": (datetime.now() - start).total_seconds(),
"event-datetime":
dt,
"started-tasks":
result
})
except ValueError as ex:
self._logger.error(ERR_HANDLING_EVENT_IN_BASE_HANDLER, ex,
safe_json(config_task, indent=2))
finally:
self._logger.flush()
def _handle_test_task_completion(self):
def completion_timed_out():
"""
Function is called when the handling of the request times out
:return:
"""
time_used = int(
os.getenv(handlers.ENV_LAMBDA_TIMEOUT) -
self._context.get_remaining_time_in_millis() / 1000)
self._logger.warning(WARN_COMPLETION_CHECK_TIMEOUT, time_used)
if self.action_properties.get(actions.ACTION_COMPLETION_SIZE,
None) is not None:
self._logger.warning(
WARN_ADJUST_LAMBDA_MEMORY_SETTINGS_COMPLETION, time_used,
self.task)
self._timeout_event.set()
self._logger.flush()
if self._timer is not None:
self._timer.cancel()
execution_time = int(time.time()) - self.started_at
execution_time_str = str(timedelta(seconds=execution_time))
result_data = {
"task": self.task,
"action": self.action,
"id": self.action_id,
"datetime": datetime.now().isoformat(),
"running-time": execution_time
}
if self._context is not None:
execution_time_left = (
self._context.get_remaining_time_in_millis() /
1000.00) - REMAINING_COMPLETION_CHECK
self._timer = threading.Timer(execution_time_left,
completion_timed_out)
self._timer.start()
try:
# make one more check for completion before testing for timeout
check_result = self._action_instance.is_completed(
self.start_result)
finally:
if self._timer is not None:
self._timer.cancel()
if self._timeout_event.is_set():
raise Exception("Task completion check timed out")
if check_result is not None:
self._action_tracking.update_task(
action_id=self.action_id,
task=self.task,
task_metrics=self.metrics,
status=handlers.STATUS_COMPLETED,
status_data={
handlers.TASK_TR_RESULT: check_result,
handlers.TASK_TR_EXECUTION_TIME: str(execution_time)
})
self._logger.info(INF_TASK_COMPLETED,
safe_json(check_result, indent=3),
execution_time_str)
result_data.update({
"result": handlers.STATUS_COMPLETED,
"action-result": str(check_result)
})
elif execution_time > self.timeout:
self._action_tracking.update_task(
action_id=self.action_id,
task=self.task,
task_metrics=self.metrics,
status=handlers.STATUS_TIMED_OUT,
status_data={
handlers.TASK_TR_EXECUTION_TIME: str(execution_time)
})
self._logger.error(ERR_TASK_TIMEOUT, execution_time_str)
result_data.update({"result": handlers.STATUS_TIMED_OUT})
return result_data
else:
self._logger.info(INF_ACTION_NOT_COMPLETED, execution_time_str)
result_data.update({"result": handlers.STATUS_WAIT_FOR_COMPLETION})
return safe_dict(result_data)
def _handle_task_execution(self):
def execute_timed_out():
"""
Function is called when the handling of the request times out
:return:
"""
time_used = int(
int(os.getenv(handlers.ENV_LAMBDA_TIMEOUT)) -
self._context.get_remaining_time_in_millis() / 1000)
self._logger.error(ERR_EXECUTION_NOT_COMPLETED, time_used)
if self.action_properties.get(actions.ACTION_EXECUTE_SIZE,
None) is not None:
self._logger.error(ERR_TIMEOUT, self.task)
self._timeout_event.set()
self._logger.flush()
self._timer.cancel()
def handle_metrics(result):
self._logger.info(
INF_SENDING_METRICS_DATA,
"enabled" if allow_send_metrics() else "disabled")
if allow_send_metrics():
try:
result_data = result if isinstance(
result, dict) else json.loads(result)
if actions.METRICS_DATA in result_data:
send_metrics_data(
metrics_data=result_data[actions.METRICS_DATA],
logger=self._logger)
except Exception as ex:
self._logger.warning(WARN_METRICS_DATA, str(ex))
self._logger.info(INF_ACTION, self.action, self.action_id, self.task,
safe_json(self.action_parameters, indent=3))
if not handlers.running_local(self._context):
self._logger.info(INF_LAMBDA_MEMORY, self._context.function_name,
self._context.memory_limit_in_mb)
self._logger.debug("Setting task state to {}", handlers.STATUS_STARTED)
self._action_tracking.update_task(self.action_id,
self.task,
task_metrics=self.metrics,
status=handlers.STATUS_STARTED)
start = time.time()
return_data = {
"task": self.task,
"action": self.action,
"id": self.action_id,
"dryrun": self.dryrun,
}
if self._context is not None:
execution_time_left = (
self._context.get_remaining_time_in_millis() /
1000.00) - EXECUTE_TIME_REMAINING
self._timer = threading.Timer(execution_time_left,
execute_timed_out)
self._timer.start()
try:
self._logger.debug("Start executing task")
action_result = self._action_instance.execute()
if isinstance(action_result, str):
action_result = json.loads(action_result)
finally:
if self._timer is not None:
self._timer.cancel()
if self._timeout_event.is_set():
raise Exception("Timeout execution action")
if not self._action_instance.properties.get(actions.ACTION_INTERNAL,
False):
handle_metrics(action_result)
execution_time = int(time.time() - start)
self._logger.debug("Task needs{}completion",
" no" if not self.has_completion else " ")
if not self.has_completion or self.dryrun:
self._logger.debug("Setting state of task to {} ",
handlers.STATUS_COMPLETED)
self._action_tracking.update_task(
action_id=self.action_id,
task=self.task,
task_metrics=self.metrics,
status=handlers.STATUS_COMPLETED,
status_data={
handlers.TASK_TR_STARTED_TS: int(start),
handlers.TASK_TR_RESULT: action_result,
handlers.TASK_TR_EXECUTION_TIME: str(execution_time),
handlers.TASK_TR_EXECUTION_LOGSTREAM:
self.execution_log_stream
})
# noinspection PyBroadException
try:
self._logger.info(INF_ACTION_RESULT, execution_time,
safe_json(action_result, indent=3))
except Exception:
self._logger.info(INF_ACTION_RESULT, execution_time,
str(action_result))
else:
# the action has a method for testing completion of the task, set the status to waiting and store the result
# of the execution that started the action as start result that will be passed to the completion method together
self._logger.debug("Setting state of task to {} ",
handlers.STATUS_WAIT_FOR_COMPLETION)
self._action_tracking.update_task(
action_id=self.action_id,
task=self.task,
task_metrics=self.metrics,
status=handlers.STATUS_WAIT_FOR_COMPLETION,
status_data={
handlers.TASK_TR_LAST_WAIT_COMPLETION:
datetime.now().isoformat(),
handlers.TASK_TR_STARTED_TS:
int(start),
handlers.TASK_TR_START_RESULT:
action_result,
handlers.TASK_TR_START_EXECUTION_TIME:
str(execution_time),
handlers.TASK_TR_EXECUTION_LOGSTREAM:
self.execution_log_stream
})
self._logger.info(INF_STARTED_AND_WAITING_FOR_COMPLETION,
safe_json(action_result, indent=3))
if not handlers.running_local(self._context):
rule = handlers.enable_completion_cloudwatch_rule(
self._context)
self._logger.info(INF_RULE_ENABLED, rule)
else:
self._logger.info(INF_SIMULATION_MODE_NO_RULE_ENABLED)
# no exception from action
return_data.update({
"result":
handlers.STATUS_WAIT_FOR_COMPLETION
if self.has_completion else handlers.STATUS_COMPLETED,
"action-result":
str(action_result),
"datetime":
datetime.now().isoformat(),
"running-time":
str(execution_time),
"task-group":
self._event[handlers.TASK_TR_GROUP],
"task-id":
self._event[handlers.TASK_TR_ID]
})
return safe_dict(return_data)
