diff --git a/code/ddns-lambda.py b/code/ddns-lambda.py index 9fcb4c8..b431876 100755 --- a/code/ddns-lambda.py +++ b/code/ddns-lambda.py @@ -64,7 +64,7 @@ import os import ipaddress from botocore.exceptions import ClientError -from collections import OrderedDict, defaultdict, namedtuple +from collections import OrderedDict, defaultdict, namedtuple, Counter from pprint import pformat from dateutil.parser import parse as date_parse @@ -73,7 +73,7 @@ LOGGER = logging.getLogger() account_id = None region = None -VERSION = '1.2.0b38' +VERSION = '1.2.0b40' # Read Env variables DEBUG_LOG_LEVEL = os.environ.get('DebugLogLevel', 'INFO') @@ -128,6 +128,7 @@ sts_client = None partition = None phz_collection_by_vpc = {} +count = Counter() def lineno(): # pragma: no cover @@ -230,7 +231,7 @@ def initialize_clients(): global sts_client global account_id - LOGGER.debug("initializing boto3 session and clients: %s", lineno()) + LOGGER.info("initializing boto3 session and clients: %s", lineno()) if session is None: session = boto3.session.Session() if sessions is None: @@ -294,6 +295,7 @@ def lambda_handler( global region global partition global phz_collection_by_vpc + global count LOGGER.info("event: %s", str(event) + lineno()) LOGGER.info("context: %s", str(context) + lineno()) @@ -344,6 +346,8 @@ def lambda_handler( while i < SLEEPTIME: LOGGER.debug("waiting count: %s", str(i) + lineno()) time.sleep(1) + count['sleep.count'] += 1 + count['sleep.time'] += 1 i += 1 try: @@ -553,6 +557,8 @@ def lambda_handler( LOGGER.debug("waiting random seconds, %s", str(wait_time) + lineno()) time.sleep(wait_time) + count['sleep.count'] += 1 + count['sleep.time'] += wait_time # Is there a DHCP option set? # Get DHCP option set configuration @@ -666,69 +672,33 @@ def lambda_handler( 'No DHCP Associated for VPC and no custom tags. Exiting Script') return caller_response -# if has_valid_hostname_tag and has_valid_zone_tag: -# LOGGER.info( -# "instance: %s, custom hostname tag and custom zone tag valid.", instance_id) -# final_private_hostname = custom_host_name -# final_hosted_zone_name = zone_tag_hosted_zone_name -# elif has_valid_hostname_tag and not (has_valid_zone_tag) and has_dhcp_dns_zone_associated_vpc: # 3 -# LOGGER.info("instance: %s, custom hostname tag valid only.", instance_id) -# final_private_hostname = custom_host_name -# final_hosted_zone_name = private_hosted_zone_name -# elif has_valid_Name_tag_hostname and has_valid_Name_tag_zonename: -# LOGGER.info( -# "instance: %s, Name tag hostname valid and Name tag zonename valid.", instance_id) -# final_private_hostname = name_host -# final_hosted_zone_name = name_domain_suffix -# elif has_valid_Name_tag_hostname and has_valid_zone_tag: -# LOGGER.info( -# "instance: %s, Name tag hostname valid and custom zone tag valid.", instance_id) -# final_private_hostname = name_host -# final_hosted_zone_name = zone_tag_hosted_zone_name -# elif has_valid_Name_tag_hostname and has_dhcp_dns_zone_associated_vpc: -# LOGGER.info( -# "instance: %s, Name tag hostname valid and DHCP zone is valid.", instance_id) -# final_private_hostname = name_host -# final_hosted_zone_name = private_hosted_zone_name -# elif has_valid_zone_tag and not (has_valid_hostname_tag) and not(has_valid_Name_tag_hostname): -# LOGGER.info( -# "instance: %s, custom zone tag valid but no custom hostname, using IP address.", instance_id) -# final_private_hostname = private_host_name -# final_hosted_zone_name = zone_tag_hosted_zone_name -# elif has_dhcp_dns_zone_associated_vpc: -# LOGGER.info("instance: %s, no custom tags - use default.", instance_id) -# final_private_hostname = private_host_name -# final_hosted_zone_name = private_hosted_zone_name -# else: -# LOGGER.error( -# "instance: %s, No DHCP Associated for VPC and no custom tags. Exiting Script", instance_id) -# # nothing to do, exit out script -# caller_response.append( -# 'No DHCP Associated for VPC and no custom tags. Exiting Script') -# return caller_response - - # put together the FQDN of the dns name... -# final_private_dns_name = final_private_hostname + '.' + final_hosted_zone_name final_private_hostname = f_hostname final_hosted_zone_name = f_zonename final_private_dns_name = '.'.join([f_hostname, f_zonename]) + zone_data_fields = ['name', 'zone_id', 'owner_account', 'is_amazon', 'enabled'] + zone_data_tuple = namedtuple('ZoneData', zone_data_fields) + LOGGER.info("instance: %s, final names for A and PTR record host %s zone %s fqdn %s: %s", instance_id, f_hostname, f_zonename, str(final_private_dns_name), lineno()) # Get the PHZ ID for the Zone -# final_hosted_zone_id = get_zone_id(final_hosted_zone_name, hosted_zones) final_hosted_zone_item = phz_collection_by_vpc[final_hosted_zone_name] final_hosted_zone_id = final_hosted_zone_item['zone_id'] + zone_data_forward = zone_data_tuple( + *phz_collection_by_vpc[final_hosted_zone_name].values()) + zone_data_reverse = zone_data_tuple( + *phz_collection_by_vpc[tag_data['ptr_entry'].zonename].values()) + + LOGGER.info(f"zone_data_forward: {pformat(zone_data_forward)}') + LOGGER.info(f"zone_data_reverse: {pformat(zone_data_reverse)}') + LOGGER.debug("private_hosted_zone_id:" " %s", str(final_hosted_zone_id) + lineno()) final_hosted_zone_owner = final_hosted_zone_item['owner_account'] LOGGER.debug("private_hosted_zone_owner: is_mine %s" " %s", final_hosted_zone_owner == account_id, str(final_hosted_zone_owner) + lineno()) -# LOGGER.debug("valid_dns_zones:" -# " %s", str(valid_dns_zones) + lineno()) - # create the TXT heritage record heritage = initialize_heritage(HERITAGE_TAG, VERSION, { @@ -763,6 +733,7 @@ def lambda_handler( ) append_msg = f"A record in zone id: {final_hosted_zone_id} for hostname {final_private_hostname} " + \ f"zone {final_hosted_zone_name} to value {private_ip}" + count[create_response] += 1 if create_response == 'success': LOGGER.info("instance: %s, Created %s", instance_id, append_msg + lineno()) @@ -792,6 +763,7 @@ def lambda_handler( append_msg = f"TXT record in zone id: {reverse_lookup_zone_id} for hostname {final_private_hostname} " + \ f"zone {final_hosted_zone_name} to value {heritage_value}" + count[create_response] += 1 if create_response == 'success': LOGGER.info("instance: %s, Created %s", instance_id, append_msg + lineno()) @@ -820,6 +792,7 @@ def lambda_handler( ) append_msg = f"PTR record in zone id: {reverse_lookup_zone_id} for hostname {tag_data['ptr_entry'].hostname} " + \ f"zone {tag_data['ptr_entry'].zonename} to value {final_private_dns_name}" + count[create_response] += 1 if create_response == 'success': LOGGER.info("instance: %s, Created %s", instance_id, append_msg + lineno()) @@ -850,6 +823,7 @@ def lambda_handler( append_msg = f"TXT record in zone id: {reverse_lookup_zone_id} for hostname {tag_data['ptr_entry'].hostname} " + \ f"zone {tag_data['ptr_entry'].zonename} to value {heritage_value}" + count[create_response] += 1 if create_response == 'success': LOGGER.info("instance: %s, Created %s", instance_id, append_msg + lineno()) @@ -882,6 +856,7 @@ def lambda_handler( delete_records = delete_records and process_response['delete_success'] # append to the lsit caller_response = caller_response + process_response['msg'] + count[f"delete_success.{process_response.get('delete_success')}"] += 1 if not flags['noreverse']: # Process and delete PTR record and associated TXT record @@ -903,6 +878,7 @@ def lambda_handler( delete_records = delete_records and process_response['delete_success'] # append to the lsit caller_response = caller_response + process_response['msg'] + count[f"delete_success.{process_response.get('delete_success')}"] += 1 # Process the CNAME record only if it has passed the check if tag_data['option_cname'].valid: @@ -1019,19 +995,20 @@ def lambda_handler( LOGGER.info("instance: %s, deleted the item from DynamoDB: %s", instance_id, DDBNAME + lineno()) caller_response.insert(0, 'Successfully removed recordsets') - return caller_response else: LOGGER.info("instance: %s, not all records deleted, leaving item in DynamoDB: %s", instance_id, DDBNAME + lineno()) caller_response.insert( 0, 'Failed to remove recordsets, leaving DynamoDB item for instance: ' + instance_id) - return caller_response else: LOGGER.info("instance: %s, Successfully created recordsets. %s", instance_id, lineno()) caller_response.insert(0, 'Successfully created recordsets') - return caller_response + + LOGGER.info(f'{APPNAME} stats: ' + + ' '.join([f"{c}={count[c]}" for c in sorted(count.keys())])) + return caller_response def get_cname_from_tags(tags): @@ -1080,6 +1057,8 @@ def get_instances(client, instance_id): LOGGER.info("instance: %s, describe_instances returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return instance_data @@ -1123,6 +1102,8 @@ def new_list_hosted_zones(client, instance_id): LOGGER.info("instance: %s, list_hosted_zones returned error, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if hosted_zones == {}: LOGGER.error("instance: %s, list_hosted_zones returned error. Timed out. %s", @@ -1177,6 +1158,8 @@ def new_list_hosted_zones_by_vpc(client, instance_id, vpc_id, region): LOGGER.info("instance: %s, list_hosted_zones_by_vpc %v returned error, waiting before retry. %s", vpc_id, instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if hosted_zones == {}: LOGGER.error("vpc_id: %s, instance: %s, list_hosted_zones_by_vpc returned error. Timed out. %s", @@ -1422,6 +1405,8 @@ def get_dhcp_option_set_id_for_vpc(client, instance_id, vpc_id): LOGGER.info("instance: %s, describe_vpcs returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return option_set_for_vpc @@ -1586,6 +1571,8 @@ def new_change_resource_recordset(oclient, instance_id, zone_id, host_name, host LOGGER.info("instance: %s, change_resource_record_sets UPSERT returned error, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if i >= MAX_API_RETRY: LOGGER.error("instance: %s, change_resource_record_sets exceeded max retry of %s", @@ -1628,9 +1615,6 @@ def create_resource_record(client, instance_id, zone_id, host_name, hosted_zone_ " %s hosted_zone_name: %s record_type: %s value: %s %s", zone_id, host_name, hosted_zone_name, record_type, value, lineno()) try: - # if host_name[-1] != '.': - # host_name = host_name + '.' - LOGGER.debug( "Updating %s in zone %s%s to %s %s", record_type, host_name, hosted_zone_name, value, lineno()) @@ -1801,6 +1785,8 @@ def new_get_resource_record(oclient, instance_id, zone_id, host_name, hosted_zon LOGGER.info("instance: %s, list_resource_record_sets returned error, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if i >= MAX_API_RETRY: LOGGER.error("instance: %s, list_resource_record_sets exceeded max retry of %s", @@ -1980,6 +1966,8 @@ def new_delete_resource_record(oclient, instance_id, zone_id, host_name, hosted_ LOGGER.info("instance: %s, change_resource_record_sets DELETE returned error, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if i >= MAX_API_RETRY: LOGGER.error("instance: %s, change_resource_record_sets exceeded max retry of %s", @@ -2162,6 +2150,8 @@ def get_dhcp_configurations(client, instance_id, dhcp_options_id): LOGGER.info("instance: %s, describe_dhcp_options returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return zone_name @@ -2338,6 +2328,8 @@ def is_dns_hostnames_enabled(client, instance_id, vpc_id): LOGGER.info("instance: %s, describe_vpc_attribute returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return dns_hostname_enabled @@ -2375,6 +2367,8 @@ def is_dns_support_enabled(client, instance_id, vpc_id): LOGGER.info("instance: %s, describe_vpc_attribute returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return dns_suppport_enabled @@ -2436,6 +2430,8 @@ def new_get_hosted_zone_properties(client, instance_id, zone_id): LOGGER.info("instance: %s, get_hosted_zone returned error, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i if hosted_zone_properties == {}: LOGGER.error("instance: %s, get_hosted_zone exceeded max retry of %s", @@ -2489,6 +2485,8 @@ def get_subnet_cidr_block(client, instance_id, subnet_id): LOGGER.info("instance: %s, describe_subnets returned RequestLimitExceeded, waiting before retry. %s", instance_id, str(i) + lineno()) time.sleep(i) + count['sleep.count'] += 1 + count['sleep.time'] += i return cidr_block @@ -3038,8 +3036,7 @@ def get_session_assume_role(account): """ this_session = sessions.get(account, None) -# try: - if True: + try: if this_session is None: LOGGER.debug("Existing session not found for account %s: %s", account, lineno()) @@ -3049,8 +3046,9 @@ def get_session_assume_role(account): LOGGER.debug("Called sts:assumerole for arn %s: %s", str(role_arn), lineno()) credentials = response['Credentials'] - LOGGER.debug("Got credentials, expiration %s: %s", - str(credentials['Expiration']), lineno()) + LOGGER.info( + f"Called assume_role for {account} ARN {role_arn}, got credentials with expiration {credentials['Expiration']}: {lineno()}") + count['assumed_role.new'] += 1 this_session = boto3.Session( aws_access_key_id=credentials["AccessKeyId"], aws_secret_access_key=credentials["SecretAccessKey"], @@ -3060,11 +3058,12 @@ def get_session_assume_role(account): LOGGER.debug("Crated new session for account %s: %s", str(account), lineno()) else: - LOGGER.debug("Found existing session for account %s: %s", account, lineno()) + LOGGER.debug(f"Found existing session for account {account}: {lineno()}") + count['assumed_role.cached_'] += 1 return this_session -# except Exception as err: -# LOGGER.error("Unable assume_role session in account %s: %s", -# str(zone_account), str(err) + lineno()) + except Exception as err: + LOGGER.error( + f"Unable assume_role session in account {account} error {err}: {lineno()}") return None diff --git a/code/ddns-lambda.zip b/code/ddns-lambda.zip index 5cd5c1d..3b98b49 100644 Binary files a/code/ddns-lambda.zip and b/code/ddns-lambda.zip differ