diff --git a/apps/dot_ext/views/authorization.py b/apps/dot_ext/views/authorization.py index 23dec15b5..b6a97ba0a 100644 --- a/apps/dot_ext/views/authorization.py +++ b/apps/dot_ext/views/authorization.py @@ -297,6 +297,7 @@ def dispatch(self, request, *args, **kwargs): try: self.application = validate_app_is_active(request) + request.application_id = self.application.id except InvalidClientError as error: return TemplateResponse( request, diff --git a/apps/logging/constants.py b/apps/logging/constants.py index ee7cfcf19..c4da81e85 100644 --- a/apps/logging/constants.py +++ b/apps/logging/constants.py @@ -874,3 +874,170 @@ def get_pre_fetch_fhir_log_entry_schema(version): ] HHS_SERVER_LOGNAME_FMT = 'hhs_server.{}' + +APP_LEVEL_METRICS = [ + 'app_fhir_v1_call_real_count', + 'app_fhir_v1_call_synthetic_count', + 'app_fhir_v1_eob_call_real_count', + 'app_fhir_v1_eob_call_synthetic_count', + 'app_fhir_v1_coverage_call_real_count', + 'app_fhir_v1_coverage_call_synthetic_count', + 'app_fhir_v1_patient_call_real_count', + 'app_fhir_v1_patient_call_synthetic_count', + 'app_fhir_v1_metadata_call_count', + 'app_fhir_v1_eob_since_call_real_count', + 'app_fhir_v1_eob_since_call_synthetic_count', + 'app_fhir_v1_coverage_since_call_real_count', + 'app_fhir_v1_coverage_since_call_synthetic_count', + 'app_fhir_v2_call_real_count', + 'app_fhir_v2_call_synthetic_count', + 'app_fhir_v2_eob_call_real_count', + 'app_fhir_v2_eob_call_synthetic_count', + 'app_fhir_v2_coverage_call_real_count', + 'app_fhir_v2_coverage_call_synthetic_count', + 'app_fhir_v2_patient_call_real_count', + 'app_fhir_v2_patient_call_synthetic_count', + 'app_fhir_v2_metadata_call_count', + 'app_fhir_v2_eob_since_call_real_count', + 'app_fhir_v2_eob_since_call_synthetic_count', + 'app_fhir_v2_coverage_since_call_real_count', + 'app_fhir_v2_coverage_since_call_synthetic_count', + 'app_fhir_v3_call_real_count', + 'app_fhir_v3_call_synthetic_count', + 'app_fhir_v3_eob_call_real_count', + 'app_fhir_v3_eob_call_synthetic_count', + 'app_fhir_v3_coverage_call_real_count', + 'app_fhir_v3_coverage_call_synthetic_count', + 'app_fhir_v3_patient_call_real_count', + 'app_fhir_v3_patient_call_synthetic_count', + 'app_fhir_v3_metadata_call_count', + 'app_fhir_v3_eob_since_call_real_count', + 'app_fhir_v3_eob_since_call_synthetic_count', + 'app_fhir_v3_coverage_since_call_real_count', + 'app_fhir_v3_coverage_since_call_synthetic_count', + 'app_fhir_v3_generate_insurance_card_call_real_count', + 'app_fhir_v3_generate_insurance_card_call_synthetic_count', + 'app_fhir_v3_eob_shared_systems_call_real_count', + 'app_fhir_v3_eob_shared_systems_call_synthetic_count', + 'app_auth_ok_real_bene_count', + 'app_auth_ok_synthetic_bene_count', + 'app_auth_fail_or_deny_real_bene_count', + 'app_auth_fail_or_deny_synthetic_bene_count', + 'app_auth_demoscope_required_choice_sharing_real_bene_count', + 'app_auth_demoscope_required_choice_sharing_synthetic_bene_count', + 'app_auth_demoscope_required_choice_not_sharing_real_bene_count', + 'app_auth_demoscope_required_choice_not_sharing_synthetic_bene_count', + 'app_auth_demoscope_required_choice_deny_real_bene_count', + 'app_auth_demoscope_required_choice_deny_synthetic_bene_count', + 'app_auth_demoscope_not_required_not_sharing_real_bene_count', + 'app_auth_demoscope_not_required_not_sharing_synthetic_bene_count', + 'app_auth_demoscope_not_required_deny_real_bene_count', + 'app_auth_demoscope_not_required_deny_synthetic_bene_count', + 'app_token_refresh_for_real_bene_count', + 'app_token_refresh_for_synthetic_bene_count', + 'app_token_authorization_code_for_real_bene_count', + 'app_token_authorization_code_for_synthetic_bene_count', + 'app_token_refresh_response_2xx_count', + 'app_token_refresh_response_4xx_count', + 'app_token_refresh_response_5xx_count', + 'app_token_authorization_code_2xx_count', + 'app_token_authorization_code_4xx_count', + 'app_token_authorization_code_5xx_count', + 'app_authorize_initial_count', + 'app_medicare_login_redirect_ok_count', + 'app_medicare_login_redirect_fail_count', + 'app_authentication_start_ok_count', + 'app_authentication_start_fail_count', + 'app_authentication_matched_new_bene_real_count', + 'app_authentication_matched_new_bene_synthetic_count', + 'app_authentication_matched_returning_bene_real_count', + 'app_authentication_matched_returning_bene_synthetic_count', + 'app_sls_callback_ok_real_count', + 'app_sls_callback_ok_synthetic_count', + 'app_sls_callback_fail_count', + 'app_approval_view_get_ok_real_count', + 'app_approval_view_get_ok_synthetic_count', + 'app_approval_view_get_fail_count', + 'app_approval_view_post_ok_real_count', + 'app_approval_view_post_ok_synthetic_count', + 'app_approval_view_post_fail_count', + 'app_sdk_requests_python_count', + 'app_sdk_requests_node_count', + 'app_access_grant_enabled', + 'app_access_grant_category', + 'app_successful_client_credentials_call', + 'app_unsuccessful_client_credentials_call', + 'app_successful_patient_match_call', + 'app_unsuccessful_patient_match_call', + 'app_auth_samhsa_presented_sharing_real_bene_count', + 'app_auth_samhsa_presented_sharing_synthetic_bene_count', + 'app_auth_samhsa_presented_not_sharing_real_bene_count', + 'app_auth_samhsa_presented_not_sharing_synthetic_bene_count', + 'app_auth_samhsa_not_presented_real_bene_count', + 'app_auth_samhsa_not_presented_synthetic_bene_count', +] + +GLOBAL_METRICS = [ + 'fhir_v1_call_real_count', + 'fhir_v1_eob_call_real_count', + 'fhir_v1_coverage_call_real_count', + 'fhir_v1_patient_call_real_count', + 'fhir_v2_call_real_count', + 'fhir_v2_eob_call_real_count', + 'fhir_v2_coverage_call_real_count', + 'fhir_v2_patient_call_real_count', + 'total_v1_v2_calls_using_since_param_percent', + 'fhir_v3_call_real_count', + 'fhir_v3_eob_call_real_count', + 'fhir_v3_coverage_call_real_count', + 'fhir_v3_patient_call_real_count', + 'fhir_v3_generate_insurance_card_call_real_count', + 'app_all_fhir_v3_eob_shared_systems_call_real_count', + 'app_all_fhir_v3_eob_shared_systems_call_synthetic_count', + 'fhir_v1_call_synthetic_count', + 'fhir_v1_eob_call_synthetic_count', + 'fhir_v1_coverage_call_synthetic_count', + 'fhir_v1_patient_call_synthetic_count', + 'fhir_v2_call_synthetic_count', + 'fhir_v2_eob_call_synthetic_count', + 'fhir_v2_coverage_call_synthetic_count', + 'fhir_v2_patient_call_synthetic_count', + 'fhir_v3_call_synthetic_count', + 'fhir_v3_eob_call_synthetic_count', + 'fhir_v3_coverage_call_synthetic_count', + 'fhir_v3_patient_call_synthetic_count', + 'fhir_v3_generate_insurance_card_call_synthetic_count', + 'total_developer_with_registered_app_count', + 'total_developer_with_first_api_call_count', + 'sdk_requests_node_count', + 'sdk_requests_python_count', + 'auth_demoscope_required_choice_not_sharing_real_bene_count', + 'auth_demoscope_required_choice_sharing_real_bene_count', + 'auth_v1_v2_user_makes_it_to_permission_screen_but_does_not_click_connect', + 'auth_v1_v2_user_makes_it_to_permission_screen_and_clicks_connect', + 'auth_v3_user_makes_it_to_permission_screen_but_does_not_click_connect', + 'auth_v3_user_makes_it_to_permission_screen_and_clicks_connect', + 'app_active_registered', + 'app_active_bene_cnt_gt25', + 'app_active_bene_cnt_le25', + 'app_all', + 'app_all_successful_client_credentials_call', + 'app_all_unsuccessful_client_credentials_call', + 'app_all_successful_patient_match_call', + 'app_all_unsuccessful_patient_match_call', + 'auth_samhsa_presented_sharing_real_bene_count', + 'auth_samhsa_presented_sharing_synthetic_bene_count', + 'auth_samhsa_presented_not_sharing_real_bene_count', + 'auth_samhsa_presented_not_sharing_synthetic_bene_count', + 'auth_samhsa_not_presented_real_bene_count', + 'auth_samhsa_not_presented_synthetic_bene_count', +] + +APP_NAMES_TO_IGNORE = [ + 'TestApp', + 'BlueButton Client (Test - Internal Use Only)', + 'MyMedicare PROD', + 'new-relic', + 'testing scopes fun', + 'datadog', +] diff --git a/apps/logging/its_log_handler.py b/apps/logging/its_log_handler.py new file mode 100644 index 000000000..7856603bd --- /dev/null +++ b/apps/logging/its_log_handler.py @@ -0,0 +1,194 @@ +import json +import logging +from concurrent.futures import ThreadPoolExecutor +from typing import Any, Dict + +import requests +from django.conf import settings + +from apps.logging.constants import HHS_SERVER_LOGNAME_FMT + +logger = logging.getLogger(HHS_SERVER_LOGNAME_FMT.format(__name__)) + +TYPES_TO_SKIP = [ + 'fhir_post_fetch', + 'fhir_pre_fetch', + 'fhir_auth_post_fetch', + 'global_state_metrics', + 'global_state_metrics_per_app', +] +# Other possibilities: +# auth_app_data_access_type, auth_app_id, path, req_grant_Type, +ACCEPTED_LOG_KEYS = [ + 'app_name', + 'app_id', + 'type', + 'response_code', + 'fhir_id_v2', + 'fhir_id_v3', + 'allow', + 'auth_status', + 'req_grant_type', + 'auth_require_demographic_scopes', + 'share_demographic_scopes', + 'path', + 'request_method', + 'auth_grant_type', + 'action', + 'sls_userinfo_status_code', + 'auth_crosswalk_action', + 'crosswalk_fhir_id', + 'auth_path', + 'patient_match_found', + 'csp', + 'patient', + 'req_qparam_lastupdated', + 'req_qparam__source', + 'req_qparam__tag', + 'auth_share_samhsa_data', + # 'auth_app_id', + # 'auth_app_name', +] +GRAB_FHIR_ID_FROM_USER_CROSSWALK = ['Authentication:success', 'Authorization'] +GRAB_FHIR_ID_FROM_CROSSWALK = ['AccessToken'] + + +class ITSLogAPIHandler(logging.Handler): + """ + Custom logging handler that forwards log records to the ITS Log API. + Fires asynchronously so it never blocks the main thread. + """ + + API_URL = 'http://host.docker.internal:8888/v1/log/create' + API_KEY = settings.ITSLOG_APIKEY + executor = ThreadPoolExecutor(max_workers=10, thread_name_prefix='its-log') + + def emit(self, record) -> None: + """Format the log message if it is a log type we want to post to its-log, + then send the log event to its-log. There is no check on a env var or waffle switch + here as the ITS_LOG_API_ENABLED env var controls in base_local.py and base_ec2.py determines + if we ever hit this function. + + Args: + record: Log record being checked and formatted for posting to its-log + """ + log_message = self._parse_log_message(record.__dict__) + if ( + log_message.get('type') in TYPES_TO_SKIP + or 'testclient' in log_message.get('path', '') + or 'admin' in log_message.get('path', '') + ): + return + + updated_log_message = self._format_log_message(log_message) + if not updated_log_message: + return + payload = self._build_payload(updated_log_message) + + self.executor.submit(self._post_to_api, payload) + + def _parse_log_message(self, record) -> Dict[str, Any]: + """Extracts the msg attribute of the log record, checks that value is a string that starts with + { or [, and returns the dictionary typed value of the msg attribute + + Args: + record: Log record being checked and formatted for posting to its-log + + Returns: + Dict[str, Any]: The dictionary typed vale of the log record's msg attribute + """ + msg = record.get('msg', '') + + # Only attempt JSON parsing if it looks like a JSON object or array + if isinstance(msg, str) and msg.strip().startswith(('{', '[')): + try: + return json.loads(msg) + except (json.JSONDecodeError, ValueError): + pass + + # Return None (or the raw string) if it's not valid JSON + return {} + + def _build_payload(self, log_message) -> Dict[str, Any]: + """Builds a paylod for the its-log API events endpoint. Tags is currently just an empty + list, could be removed or modified in the future. We only want certain log attributes in + the value column of itslog_events, so we filter for the specific log attributes that we want. + + Args: + log_message (dict): Dictionary containing the details of the log event + + Returns: + Dict[str, Any]: Formatted payload that the its-log API event endpoint expects + """ + tags = [] + filtered_log = {k: v for k, v in log_message.items() if k in ACCEPTED_LOG_KEYS} + + return { + 'tags': tags, + 'value': json.dumps(filtered_log), + 'type': 'text', + } + + def _format_log_message(self, log_message: Dict[str, Any]) -> Dict[str, Any]: + """Format the log_message before building the its-log API payload, so the payload + sent to its-log will have the fields that the different ETL steps are looking for + to calculate metrics + + Args: + log_message (Dict[str, Any]): Dictionary containing the details of the log event + + Returns: + Dict[str, Any]: Formatted log message with specific keys that are looked for in our data pipeline + """ + if log_message.get('type'): + if log_message.get('type') in GRAB_FHIR_ID_FROM_USER_CROSSWALK: + log_message['fhir_id_v2'] = log_message.get('user').get('crosswalk').get('fhir_id_v2') + log_message['fhir_id_v3'] = log_message.get('user').get('crosswalk').get('fhir_id_v3') + elif log_message.get('type') in GRAB_FHIR_ID_FROM_CROSSWALK: + log_message['fhir_id_v2'] = log_message.get('crosswalk').get('fhir_id') + if log_message.get('code'): + log_message['response_code'] = log_message.get('code') + if ( + '?' in log_message.get('location', '') + and 'authorize' in log_message.get('location', '') + and log_message.get('location', '').startswith('/v') + ): + log_message['auth_path'] = log_message.get('location').split('?')[0] + + if log_message.get('req_grant_type'): + log_message['auth_grant_type'] = log_message.get('req_grant_type') + + if not log_message.get('app_id') and log_message.get('auth_app_id'): + log_message['app_id'] = log_message.get('auth_app_id') + if not log_message.get('app_name') and log_message.get('auth_app_name'): + log_message['app_name'] = log_message.get('auth_app_name') + if not log_message.get('app_id') and log_message.get('resp_app_id'): + log_message['app_id'] = log_message.get('resp_app_id') + if not log_message.get('app_name') and log_message.get('resp_app_name'): + log_message['app_name'] = log_message.get('resp_app_name') + if not log_message.get('app_id') and log_message.get('req_app_id'): + log_message['app_id'] = log_message.get('req_app_id') + if not log_message.get('app_name') and log_message.get('req_app_name'): + log_message['app_name'] = log_message.get('req_app_name') + if not log_message.get('app_id') and log_message.get('application'): + log_message['app_id'] = log_message['application'].get('id') + log_message['app_name'] = log_message['application'].get('name') + + if 'allow' in log_message: + log_message['allow'] = 'True' if log_message.get('allow') is True else 'False' + + return log_message + + def _post_to_api(self, payload) -> None: + """Post the given payload to the its-log API events endpoint + + Args: + payload (dict): The payload being posted to the its-log API + """ + logger.debug(f'Payload for its-log: {json.dumps(payload)}') + try: + requests.post(self.API_URL, headers={'x-api-key': self.API_KEY}, json=payload, timeout=5) + logger.info('Successfully posted to its-log') + except Exception: + # Do not let ITS-log failures crash BlueButton + logger.error('Failed to post to its-log API') diff --git a/apps/logging/loggers.py b/apps/logging/loggers.py index ed0bb47e4..a8321813e 100644 --- a/apps/logging/loggers.py +++ b/apps/logging/loggers.py @@ -1,5 +1,7 @@ from datetime import datetime +import requests +from django.conf import settings from django.core.serializers.json import DjangoJSONEncoder import apps.logging.request_logger as logging @@ -16,6 +18,7 @@ get_token_bene_counts, ) from apps.fhir.bluebutton.models import get_crosswalk_bene_counts +from apps.logging.constants import APP_LEVEL_METRICS, APP_NAMES_TO_IGNORE, GLOBAL_METRICS from apps.logging.utils import format_timestamp """ @@ -24,7 +27,7 @@ logger = logging.getLogger(logging.AUDIT_GLOBAL_STATE_METRICS_LOGGER) -def log_global_state_metrics(group_timestamp=None, report_flag=True): +def log_global_state_metrics(group_timestamp=None, report_flag=True, its_log_flag=False): """ For use in apps/logging/management/commands/log_global_metrics.py management command NOTE: print statements are for output when run via Jenkins @@ -54,6 +57,11 @@ def log_global_state_metrics(group_timestamp=None, report_flag=True): elapsed_time = round(datetime.utcnow().timestamp() - start_time, 3) + # TODO: Change this before we actually start running this in prod. For testing purposes, it is helpful + # to have the current day. For actual prod, we'll need to look at the prior day. + # prior_day = (datetime.now() - timedelta(days=1)).strftime('%Y-%m-%d') + prior_day = datetime.now().strftime('%Y-%m-%d') + log_dict = { 'type': 'global_state_metrics', 'group_timestamp': group_timestamp, @@ -237,6 +245,19 @@ def log_global_state_metrics(group_timestamp=None, report_flag=True): logger.info(log_dict) + if its_log_flag: + for metric in GLOBAL_METRICS: + ping_api([], '0', metric, prior_day) + + for key in log_dict.keys(): + val_to_post = log_dict[key] + + if isinstance(val_to_post, bool) or isinstance(val_to_post, int): + val_to_post = str(val_to_post) + # ping_api([key], val_to_post, 'global') + # ping_api([], val_to_post, 'total_' + key, 'global_state_metrics') + ping_api([], val_to_post, 'total_' + key, prior_day) + if report_flag: print('---') print('--- Wrote top level log entry: [REDACTED]') @@ -251,6 +272,9 @@ def log_global_state_metrics(group_timestamp=None, report_flag=True): start_time = datetime.utcnow().timestamp() count = 0 + active_apps = 0 + active_apps_w_gt_25_real_benes = 0 + active_apps_w_lt_25_real_benes = 0 for app in applications: # Get UserProfile for application's dev user try: @@ -301,9 +325,34 @@ def log_global_state_metrics(group_timestamp=None, report_flag=True): 'user_limit_data_access': True, } + if app.name not in APP_NAMES_TO_IGNORE and app.active and log_dict.get('real_bene_cnt', 0) > 25: + active_apps_w_gt_25_real_benes += 1 + elif app.name not in APP_NAMES_TO_IGNORE and app.active: + active_apps_w_lt_25_real_benes += 1 + + if app.active and app.name not in APP_NAMES_TO_IGNORE: + active_apps += 1 + logger.info(log_dict, cls=DjangoJSONEncoder) - count = count + 1 + if its_log_flag and app.name not in APP_NAMES_TO_IGNORE: + # post all metrics for all apps to ensure we have data populated for each app, each day + for metric in APP_LEVEL_METRICS: + tag = [str(app.id), app.name] + ping_api(tag, '0', metric, prior_day) + + for key in log_dict.keys(): + tag = [str(app.id), app.name] + val_to_post = log_dict[key] + + if isinstance(val_to_post, bool) or isinstance(val_to_post, int): + val_to_post = str(val_to_post) + + ping_api(tag, val_to_post, 'app_' + key, prior_day) + if its_log_flag: + ping_api([], str(active_apps_w_gt_25_real_benes), 'app_active_bene_cnt_gt25', prior_day) + ping_api([], str(active_apps_w_lt_25_real_benes), 'app_active_bene_cnt_le25', prior_day) + ping_api([], str(active_apps), 'app_all', prior_day) elapsed_time = round(datetime.utcnow().timestamp() - start_time, 3) @@ -317,3 +366,40 @@ def log_global_state_metrics(group_timestamp=None, report_flag=True): ) print('---') print('SUCCESS') + + +def ping_api(tags, value, operation, date): + try: + result = requests.post( + 'http://host.docker.internal:8888/v1/summary/create', + headers={'x-api-key': settings.ITSLOG_APIKEY}, + json={ + 'tags': tags, + 'count': 1, + 'value': value, + 'operation': operation, + 'date': date, + }, + timeout=2, + ) + return result + except Exception: + pass # Never let logging failures crash your app + + +def ping_events_api(tags, value, cluster): + try: + result = requests.post( + 'http://host.docker.internal:8888/v1/log/create', + headers={'x-api-key': settings.ITSLOG_APIKEY}, + json={ + 'tags': tags, + 'value': value, + 'cluster': cluster, + 'type': 'text', + }, + timeout=2, + ) + return result + except Exception: + pass # Never let logging failures crash your app diff --git a/apps/logging/management/commands/log_global_state_metrics.py b/apps/logging/management/commands/log_global_state_metrics.py index 06771712d..d9824bb4b 100644 --- a/apps/logging/management/commands/log_global_state_metrics.py +++ b/apps/logging/management/commands/log_global_state_metrics.py @@ -10,7 +10,13 @@ class Command(BaseCommand): help = 'Management command to log global state type metrics when called on a schedule.' def add_arguments(self, parser): - # Optional argument to prevent console report in unit tests. + # Optional argument to post to ITS-log API + parser.add_argument( + '-l', + '--post-to-its-log', + action='store_true', + help='Post results to ITS-log API.', + ) parser.add_argument( '-n', '--no-report', @@ -23,5 +29,6 @@ def handle(self, *args, **options): group_timestamp = format_timestamp(datetime.now()) report_flag = False if options.get('no_report', None) else True + its_log_flag = options.get('post_to_its_log') - log_global_state_metrics(group_timestamp, report_flag) + log_global_state_metrics(group_timestamp, report_flag, its_log_flag) diff --git a/apps/logging/tests/test_its_log_handler.py b/apps/logging/tests/test_its_log_handler.py new file mode 100644 index 000000000..a5cc7dea2 --- /dev/null +++ b/apps/logging/tests/test_its_log_handler.py @@ -0,0 +1,529 @@ +import importlib +import json +import logging +import os +from time import sleep +from unittest.mock import patch + +import pytest + +from apps.constants import DEFAULT_SAMPLE_FHIR_ID_V2, DEFAULT_SAMPLE_FHIR_ID_V3 +from apps.logging.constants import AUDIT_AUTHN_SLS_LOGGER, AUDIT_AUTHZ_TOKEN_LOGGER, AUDIT_HHS_AUTH_SERVER_REQ_LOGGER +from apps.logging.its_log_handler import ITSLogAPIHandler + +log_handler = ITSLogAPIHandler() + + +def test_its_log_api_handler_absent_when_env_var_false(): + """Confirm that the its_log_api logging handler is not added to the base_local settings + if ITS_LOG_API_ENABLED is false + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'False', 'TARGET_ENV': 'local', 'DJANGO_SECRET_KEY': 'test'}): + from hhs_oauth_server.settings import base_local + + assert 'its_log_api' not in base_local.LOGGING['loggers']['audit']['handlers'] + assert 'its_log_api' not in base_local.LOGGING['loggers']['hhs_server']['handlers'] + + +def test_its_log_api_handler_present_when_env_var_true(): + """Confirm that the its_log_api logging handler is added to the base_local settings + if ITS_LOG_API_ENABLED is true + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'True', 'TARGET_ENV': 'local', 'DJANGO_SECRET_KEY': 'test'}): + from hhs_oauth_server.settings import base_local + + importlib.reload(base_local) + + assert 'its_log_api' in base_local.LOGGING['handlers'] + assert 'its_log_api' in base_local.LOGGING['loggers']['audit']['handlers'] + assert 'its_log_api' in base_local.LOGGING['loggers']['hhs_server']['handlers'] + + +def test_its_log_api_handler_absent_when_env_var_false_base_ec2(): + """Confirm that the its_log_api logging handler is not added to the base_ec2 settings + if ITS_LOG_API_ENABLED is false + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'False', 'TARGET_ENV': 'test'}): + from hhs_oauth_server.settings import base_ec2 + + assert 'its_log_api' not in base_ec2.LOGGING['loggers']['audit']['handlers'] + assert 'its_log_api' not in base_ec2.LOGGING['loggers']['hhs_server']['handlers'] + + +def test_its_log_api_handler_present_when_env_var_true_base_ec2(): + """Confirm that the its_log_api logging handler is added to the base_ec2 settings + if ITS_LOG_API_ENABLED is true + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'True', 'TARGET_ENV': 'test'}): + from hhs_oauth_server.settings import base_ec2 + + importlib.reload(base_ec2) + + assert 'its_log_api' in base_ec2.LOGGING['handlers'] + assert 'its_log_api' in base_ec2.LOGGING['loggers']['audit']['handlers'] + assert 'its_log_api' in base_ec2.LOGGING['loggers']['hhs_server']['handlers'] + + +@pytest.mark.parametrize( + 'log_type', + [ + 'fhir_post_fetch', + 'fhir_pre_fetch', + 'fhir_auth_post_fetch', + 'global_state_metrics', + 'global_state_metrics_per_app', + ], +) +@patch('apps.logging.its_log_handler.ITSLogAPIHandler._post_to_api') +def test_log_not_posted_when_type_is_skippable(mock_post_to_api, log_type): + """Confirm that we do not call the _post_to_api function if the log_type is not one of the types + we want to post to its-log + + Args: + mock_post_to_api: Patch for the _post_to_api function + log_type: The type of the log that was just output. We only post certain log types to the logging API + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'True'}): + record = logging.makeLogRecord( + {'name': 'test', 'level': logging.INFO, 'msg': 'Test connection established', 'type': log_type} + ) + log_handler.emit(record) + mock_post_to_api.assert_not_called() + + +@patch('apps.logging.its_log_handler.ITSLogAPIHandler._post_to_api') +def test_log_not_posted_when_testclient_in_path(mock_post_to_api): + """Confirm that we do not call the _post_to_api function if testclient is in the log.path + + Args: + mock_post_to_api: Patch for the _post_to_api function + """ + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'True'}): + record = logging.makeLogRecord( + { + 'name': 'test', + 'level': logging.INFO, + 'msg': 'Test connection established', + 'type': 'Authorization', + 'path': '/testclient/', + } + ) + log_handler.emit(record) + mock_post_to_api.assert_not_called() + + +@pytest.mark.parametrize( + 'log_msg, expected_result', + [ + (True, {}), + ( + '{"type": "request_response_middleware", "request_method": "GET", "path": "/testclient/PatientV2"}', + {'type': 'request_response_middleware', 'request_method': 'GET', 'path': '/testclient/PatientV2'}, + ), + ], +) +def test_parse_log_message(log_msg, expected_result): + """Pass different values to the _parse_log_message function and ensure we get the expected result + + Args: + log_msg: The log message being passed to _parse_log_message. + expected_result: The expected result of _parse_log_message + """ + record = logging.makeLogRecord( + { + 'name': 'test', + 'level': logging.INFO, + 'msg': log_msg, + 'type': 'Authorization', + 'path': '/testclient/', + } + ) + result = log_handler._parse_log_message(record.__dict__) + assert result == expected_result + + +@pytest.mark.parametrize( + 'log_message, expected_result', + [ + ( + { + 'access_token_scopes': 'profile patient/Patient.rs patient/ExplanationOfBenefit.rs patient/Coverage.rs', + 'app_id': 35, + 'app_name': 'local logging', + 'app_require_demographic_scopes': True, + 'dev_id': 1, + 'dev_name': 'root', + 'fhir_id_v2': '-10000010284531', + 'fhir_id_v3': '-512738563', + 'fhir_resource_id': '6e9a3123-4a40-44f2-a195-e870a8801418', + 'fhir_resource_type': 'Bundle', + 'location': '', + 'path': '/v3/fhir/Patient/', + 'req_fhir_id_v2': '-10000010284531', + 'req_fhir_id_v3': '-512738563', + 'req_header_accept_encoding': 'gzip, deflate, br', + 'req_header_host': 'localhost:8000', + 'req_header_user_agent': 'PostmanRuntime/2.8.0', + 'request_method': 'GET', + 'response_code': 200, + 'type': 'request_response_middleware', + }, + { + 'tags': [], + 'value': '{"app_id": 35, "app_name": "local logging", "fhir_id_v2": "-10000010284531", "fhir_id_v3": "-512738563", "path": "/v3/fhir/Patient/", "request_method": "GET", "response_code": 200, "type": "request_response_middleware"}', + 'type': 'text', + }, + ), + ( + { + 'access_token_hash': '', + 'app_id': 35, + 'app_name': 'local logging', + 'auth_grant_type': 'refresh_token', + 'dev_id': '', + 'dev_name': '', + 'elapsed': 1.2084159851074219, + 'end_time': 1790606675.534841, + 'location': '', + 'path': '/v3/o/token/', + 'req_client_id': None, + 'req_grant_type': 'refresh_token', + 'req_header_accept_encoding': 'gzip, deflate, br', + 'req_header_content_length': '166', + 'req_header_content_type': 'application/x-www-form-urlencoded', + 'req_header_host': 'localhost:8000', + 'req_header_user_agent': 'PostmanRuntime/7.56.1', + 'req_post_grant_type': 'refresh_token', + 'req_scope': 'profile%20patient%2FExplanationOfBenefit.rs%20patient%2FCoverage.rs%20patient%2FPatient.rs', + 'request_method': 'POST', + 'request_scheme': 'http', + 'request_uuid': '1f0fb7d4-bb4b-11f1-a1a1-9acbb38473dd', + 'resp_access_token_scopes': 'profile patient/Patient.rs patient/ExplanationOfBenefit.rs patient/Coverage.rs', + 'resp_app_id': 35, + 'resp_app_name': 'local logging', + 'resp_app_require_demographic_scopes': True, + 'resp_dev_id': 1, + 'resp_dev_name': 'root', + 'resp_expires_in': 3600, + 'resp_fhir_id': '-512738563', + 'resp_scope': 'profile patient/ExplanationOfBenefit.rs patient/Coverage.rs patient/Patient.rs', + 'resp_token_type': 'Bearer', + 'resp_user_id': 96, + 'response_code': 200, + 'type': 'request_response_middleware', + }, + { + 'tags': [], + 'value': '{"app_id": 35, "app_name": "local logging", "auth_grant_type": "refresh_token", "path": "/v3/o/token/", "req_grant_type": "refresh_token", "request_method": "POST", "response_code": 200, "type": "request_response_middleware"}', + 'type': 'text', + }, + ), + ], +) +def test_build_payload(log_message, expected_result): + """This test passes a sample log message to the _build_payload function, and confirms that the returned + dictionary contains the field names that we expected + + Args: + log_message: The log_message that is used to build the payload to the logging API + expected_result: The expected result of the _build_payload function + """ + result = log_handler._build_payload(log_message) + assert result == expected_result + + +@pytest.mark.parametrize( + 'log_message, expected_fhir_id_v2, expected_fhir_id_v3', + [ + ( + { + 'type': 'Authorization', + 'user': { + 'crosswalk': { + 'fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + } + }, + }, + DEFAULT_SAMPLE_FHIR_ID_V2, + DEFAULT_SAMPLE_FHIR_ID_V3, + ), + ( + { + 'type': 'Authentication:success', + 'user': { + 'crosswalk': { + 'fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + } + }, + }, + DEFAULT_SAMPLE_FHIR_ID_V2, + DEFAULT_SAMPLE_FHIR_ID_V3, + ), + ( + { + 'type': 'Authentication:success', + 'user': { + 'crosswalk': { + 'fhir_id_v2': None, + 'fhir_id_v3': None, + } + }, + }, + None, + None, + ), + ( + { + 'type': 'Authentication:success', + 'user': { + 'crosswalk': { + 'fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'fhir_id_v3': None, + } + }, + }, + DEFAULT_SAMPLE_FHIR_ID_V2, + None, + ), + ( + { + 'type': 'Authentication:success', + 'user': { + 'crosswalk': { + 'fhir_id_v2': None, + 'fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + } + }, + }, + None, + DEFAULT_SAMPLE_FHIR_ID_V3, + ), + ( + { + 'type': 'AccessToken', + 'crosswalk': { + 'fhir_id': DEFAULT_SAMPLE_FHIR_ID_V2, + }, + }, + DEFAULT_SAMPLE_FHIR_ID_V2, + None, + ), + ], +) +def test_format_log_message_fhir_id_retrieval(log_message, expected_fhir_id_v2, expected_fhir_id_v3): + """Confirm we successfully retrieve fhir_id values for different log types in the _format_log_message function + + Args: + log_message: Log message being passed for formatting + expected_fhir_id_v2: Expected fhir_id_v2 from _format_log_message + expected_fhir_id_v3: Expected fhir_id_v3 from _format_log_message + """ + result = log_handler._format_log_message(log_message) + assert result['fhir_id_v2'] == expected_fhir_id_v2 + if log_message.get('type') != 'AccessToken': + assert result['fhir_id_v3'] == expected_fhir_id_v3 + + +@pytest.mark.parametrize( + 'log_message, expected_auth_path, expected_grant_type, expected_app_id, expected_app_name, expected_allow', + [ + ( + { + 'location': '/v2/authorize?foo=bar', + 'req_grant_type': 'authorization_code', + 'auth_app_id': 1, + 'auth_app_name': 'TestApp', + 'allow': False, + }, + '/v2/authorize', + 'authorization_code', + 1, + 'TestApp', + 'False', + ), + ( + { + 'location': '/v2/authorize?foo=bar', + 'req_grant_type': 'authorization_code', + 'resp_app_id': 1, + 'resp_app_name': 'TestApp', + 'allow': True, + }, + '/v2/authorize', + 'authorization_code', + 1, + 'TestApp', + 'True', + ), + ( + { + 'location': '/v2/authorize?foo=bar', + 'req_grant_type': 'authorization_code', + 'req_app_id': 1, + 'req_app_name': 'TestApp', + 'allow': True, + }, + '/v2/authorize', + 'authorization_code', + 1, + 'TestApp', + 'True', + ), + ], +) +def test_format_log_message_other_fields( + log_message, + expected_auth_path, + expected_grant_type, + expected_app_id, + expected_app_name, + expected_allow, +): + """_summary_ + + Args: + log_message: Log message being passed for formatting + expected_auth_path: Expected auth_path from _format_log_message + expected_grant_type: Expected auth_path from _format_log_message + expected_app_id: Expected auth_path from _format_log_message + expected_app_name: Expected auth_path from _format_log_message + expected_allow: Expected auth_path from _format_log_message + """ + + result = log_handler._format_log_message(log_message) + assert result.get('auth_path') == expected_auth_path + assert result.get('auth_grant_type') == expected_grant_type + assert result.get('app_id') == expected_app_id + assert result.get('app_name') == expected_app_name + assert result.get('allow') == expected_allow + + +@pytest.mark.parametrize( + 'log_message, expected_payload, log_message_name', + [ + ( + { + 'access_token_id': 1612, + 'access_token_scopes': 'profile patient/Patient.rs patient/ExplanationOfBenefit.rs patient/Coverage.rs', + 'app_id': 35, + 'app_name': 'local logging', + 'app_require_demographic_scopes': True, + 'dev_id': 1, + 'dev_name': 'root', + 'elapsed': 0.38216400146484375, + 'end_time': 1790624896.192774, + 'fhir_attribute_count': 7, + 'fhir_bundle_type': 'searchset', + 'fhir_entry_count': 10, + 'fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + 'fhir_resource_id': '876b8bf6-e2bc-4207-aa22-51f396fdf68e', + 'fhir_resource_type': 'Bundle', + 'ip_addr': '192.168.127.1', + 'location': '', + 'path': '/v3/fhir/ExplanationOfBenefit', + 'req_fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'req_fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + 'req_header_accept_encoding': 'gzip, deflate, br', + 'req_header_host': 'localhost:8000', + 'req_header_user_agent': 'PostmanRuntime/2.8.0', + 'req_user_id': 93, + 'req_user_username': 'BBUser00000', + 'request_method': 'GET', + 'request_scheme': 'http', + 'request_uuid': '8be9972e-bb75-11f1-8bfe-02db1dcb95d4', + 'response_code': 200, + 'size': 723995, + 'start_time': 1790624895.810615, + 'type': 'request_response_middleware', + 'user': 'BBUser00000', + 'user_id': 93, + 'user_username': 'BBUser00000', + }, + { + 'tags': [], + 'value': '{"app_id": 35, "app_name": "local logging", "fhir_id_v2": "-20140000008325", "fhir_id_v3": "-30250000008325", "path": "/v3/fhir/ExplanationOfBenefit", "request_method": "GET", "response_code": 200, "type": "request_response_middleware"}', + 'type': 'text', + }, + AUDIT_HHS_AUTH_SERVER_REQ_LOGGER, + ), + ( + { + 'auth_app_data_access_type': 'THIRTEEN_MONTH', + 'auth_app_id': '35', + 'auth_app_name': 'local logging', + 'auth_client_id': 'iMJqiB3CFRfcQrqxew9uruvV8NjDVN8Wne0jwGYf', # betterleaks:allow + 'auth_crosswalk_action': 'R', + 'auth_pkce_method': 'S256', + 'auth_require_demographic_scopes': 'True', + 'path': 'v3/mymedicare/sls-callback', + 'request_uuid': '706a138e-bb75-11f1-8bfe-02db1dcb95d4', + 'sub': 'BBUser00000', + 'type': 'Authentication:success', + 'user': { + 'crosswalk': { + 'fhir_id_v2': DEFAULT_SAMPLE_FHIR_ID_V2, + 'fhir_id_v3': DEFAULT_SAMPLE_FHIR_ID_V3, + 'id': 92, + 'user_hicn_hash': 'f7dd6b126d55a6c49f05987f4aab450deae3f990dcb5697875fd83cc61583948', + 'user_id_type': 'M', + }, + 'id': 93, + 'username': 'BBUser00000', + }, + }, + { + 'tags': [], + 'value': '{"auth_crosswalk_action": "R", "auth_require_demographic_scopes": "True", "path": "v3/mymedicare/sls-callback", "type": "Authentication:success", "fhir_id_v2": "-20140000008325", "fhir_id_v3": "-30250000008325", "app_id": "35", "app_name": "local logging"}', + 'type': 'text', + }, + AUDIT_AUTHN_SLS_LOGGER, + ), + ( + { + 'access_token': '11b9e6f5f321d236403871724af71183e4a050f0e1f38e36bf5f6da6d28ac5c4', # betterleaks:allow + 'action': 'revoked', + 'application': { + 'data_access_type': 'THIRTEEN_MONTH', + 'id': 35, + 'name': 'local logging', + 'user': {'id': 1, 'username': 'root'}, + }, + 'crosswalk': { + 'fhir_id': '-10000010254618', + 'id': 92, + 'user_hicn_hash': 'f7dd6b126d55a6c49f05987f4aab450deae3f990dcb5697875fd83cc61583948', + 'user_id_type': 'M', + }, + 'id': 1613, + 'scopes': 'profile patient/Patient.rs patient/ExplanationOfBenefit.rs patient/Coverage.rs', + 'type': 'AccessToken', + 'user': {'id': 93, 'username': 'BBUser00000'}, + }, + { + 'tags': [], + 'value': '{"action": "revoked", "type": "AccessToken", "fhir_id_v2": "-10000010254618", "app_id": 35, "app_name": "local logging"}', + 'type': 'text', + }, + AUDIT_AUTHZ_TOKEN_LOGGER, + ), + ], +) +@patch('apps.logging.its_log_handler.ITSLogAPIHandler._post_to_api') +def test_post_api_is_called_with_specific_payload(mock_post_to_api, log_message, expected_payload, log_message_name): + with patch.dict(os.environ, {'ITS_LOG_API_ENABLED': 'True'}): + record = logging.makeLogRecord( + { + 'name': log_message_name, + 'level': logging.INFO, + 'msg': json.dumps(log_message), + } + ) + log_handler.emit(record) + # Without this sleep, the second and third parametrized tests will fail. They fail as ThreadPoolExecutor.submit + # does not execute the function immediately. We could also modify the test executor to immediately submit any + # threads, but then that would differ from how it would work in prod. Neither solution is ideal + sleep(0.1) + mock_post_to_api.assert_called_with(expected_payload) diff --git a/apps/logging/tests/test_loggers_management_command.py b/apps/logging/tests/test_loggers_management_command.py index 649f9a99a..a2cff56fc 100644 --- a/apps/logging/tests/test_loggers_management_command.py +++ b/apps/logging/tests/test_loggers_management_command.py @@ -1,6 +1,7 @@ import copy import json from io import StringIO +from unittest.mock import patch import jsonschema from django.contrib.auth import get_user_model @@ -61,7 +62,13 @@ def _call_management_command_log_global_state_metrics( if report_to_console: call_command('log_global_state_metrics', stdout=StringIO(), stderr=StringIO()) else: - call_command('log_global_state_metrics', '--no-report', stdout=StringIO(), stderr=StringIO()) + call_command( + 'log_global_state_metrics', + '--post-to-its-log', + '--no-report', + stdout=StringIO(), + stderr=StringIO(), + ) def _debug_show_value_differences(self, dict_a, dict_b): """ @@ -288,7 +295,8 @@ def _validate_global_state_per_app_metrics_log(self, validate_apps_dict): # Validate with orig schema. self.assertTrue(self._validateJsonSchema(GLOBAL_STATE_METRICS_PER_APP_LOG_SCHEMA, log_dict)) - def test_management_command_logging(self): + @patch('apps.logging.loggers.ping_api') + def test_management_command_logging(self, mock_ping_api): """ Setup variety of real/synth users, apps and grants for testing global state metrics logging. """ @@ -1309,3 +1317,4 @@ def test_management_command_logging(self): } ) self._validate_global_state_metrics_log(validate_global_dict) + assert mock_ping_api.call_count == 10908 diff --git a/docker-compose/bluebutton_server_start.sh b/docker-compose/bluebutton_server_start.sh index fe24408ae..c040fd4c0 100755 --- a/docker-compose/bluebutton_server_start.sh +++ b/docker-compose/bluebutton_server_start.sh @@ -11,6 +11,8 @@ BB2_SERVER_STD2FILE=${BB2_SERVER_STD2FILE:-''} DJANGO_LOG_JSON_FORMAT_PRETTY=${DJANGO_LOG_JSON_FORMAT_PRETTY:-True} DJANGO_USER_ID_SALT=${DJANGO_USER_ID_SALT:-"6E6F747468657265616C706570706572"} DJANGO_USER_ID_ITERATIONS=${DJANGO_USER_ID_ITERATIONS:-"2"} +ITS_LOG_API_ENABLED=${ITS_LOG_API_ENABLED:-false} +ITSLOG_APIKEY=${ITSLOG_APIKEY:-""} if [ "${DJANGO_SLSX_CLIENT_SECRET}" = "xxxxx" ] then diff --git a/docker-compose/web-env-vars.env b/docker-compose/web-env-vars.env index c7e112e68..4e9726a50 100644 --- a/docker-compose/web-env-vars.env +++ b/docker-compose/web-env-vars.env @@ -24,3 +24,7 @@ DJANGO_FHIR_CERTSTORE=/code/docker-compose/certstore/ CORS_ORIGIN_ALLOW_ALL=True # Comma-separated list of allowed origins when CORS_ORIGIN_ALLOW_ALL is False # Example: CORS_ALLOWED_ORIGINS=https://localhost:3000, https://sandbox.bluebutton.cms.gov + +# ITS-log API +ITS_LOG_API_ENABLED=False +ITSLOG_APIKEY=${ITSLOG_APIKEY} diff --git a/hhs_oauth_server/settings/base_ec2.py b/hhs_oauth_server/settings/base_ec2.py index de6418d8e..e0c9b3727 100644 --- a/hhs_oauth_server/settings/base_ec2.py +++ b/hhs_oauth_server/settings/base_ec2.py @@ -452,6 +452,19 @@ BOTO3_LOGS_CLIENT = boto3.client('logs', region_name=AWS_REGION_NAME) +ITS_LOG_API_ENABLED = bool_env(env('ITS_LOG_API_ENABLED', 'False')) +ITSLOG_APIKEY = env('ITSLOG_APIKEY', default=None) + + +def _add_its_log_api_handler(loggers_list): + """Check if the ITS_LOG_API_ENABLED env var is set to True. If it is, append the + its_log_api logging handler, so we ping the ITS Log API + """ + if ITS_LOG_API_ENABLED: + loggers_list.append('its_log_api') + return loggers_list + + # TODO - remove this after we move to Fargate, django_logging is defined in Ansible playbooks # in the deployment repo that aren't being migrated LOGGING = env( @@ -481,6 +494,10 @@ }, }, 'handlers': { + 'its_log_api': { + '()': 'apps.logging.its_log_handler.ITSLogAPIHandler', + 'level': 'INFO', + }, 'console': { 'level': 'INFO', 'class': 'logging.StreamHandler', @@ -537,7 +554,7 @@ }, 'loggers': { 'hhs_server': { - 'handlers': ['wt_debug', 'wt_perf_mon', 'console'], + 'handlers': _add_its_log_api_handler(['wt_debug', 'wt_perf_mon', 'console']), 'level': 'DEBUG', }, 'hhs_oauth_server.accounts': { @@ -577,7 +594,7 @@ 'level': 'DEBUG', }, 'audit': { - 'handlers': ['wt_perf_mon', 'console'], + 'handlers': _add_its_log_api_handler(['wt_perf_mon', 'console']), 'level': 'INFO', }, 'performance': { diff --git a/hhs_oauth_server/settings/base_local.py b/hhs_oauth_server/settings/base_local.py index a8771a239..053c4b9f6 100644 --- a/hhs_oauth_server/settings/base_local.py +++ b/hhs_oauth_server/settings/base_local.py @@ -190,6 +190,19 @@ # keep backward compatible with AutoField instead of BigAutoField DEFAULT_AUTO_FIELD = 'django.db.models.AutoField' +ITS_LOG_API_ENABLED = env.bool('ITS_LOG_API_ENABLED', default=False) +ITSLOG_APIKEY = env('ITSLOG_APIKEY', default=None) + + +def _add_its_log_api_handler(loggers_list): + """Check if the ITS_LOG_API_ENABLED env var is set to True. If it is, append the + its_log_api logging handler, so we ping the ITS Log API + """ + if ITS_LOG_API_ENABLED: + loggers_list.append('its_log_api') + return loggers_list + + # Use env-specific logging config if present LOGGING = { 'version': 1, @@ -204,6 +217,10 @@ }, }, 'handlers': { + 'its_log_api': { + '()': 'apps.logging.its_log_handler.ITSLogAPIHandler', + 'level': 'INFO', + }, 'console': { 'class': 'logging.StreamHandler', 'formatter': 'verbose', @@ -222,7 +239,7 @@ # 'handlers': ['console'], # }, 'hhs_server': { - 'handlers': ['console'], + 'handlers': _add_its_log_api_handler(['console']), 'level': 'DEBUG', }, 'hhs_oauth_server.accounts': { @@ -250,7 +267,7 @@ 'level': 'DEBUG', }, 'audit': { - 'handlers': ['console'], + 'handlers': _add_its_log_api_handler(['console']), 'level': 'INFO', }, 'performance': { diff --git a/insights/etls/README.md b/insights/etls/README.md new file mode 100644 index 000000000..63a7023f3 --- /dev/null +++ b/insights/etls/README.md @@ -0,0 +1,11 @@ +## About this folder + +The purpose of this folder is to store ETLs that are used in the its-log API. These ETLs are used to transform +data from the itslog_events table into the itslog_summary table. These different database tables help us track +Blue Button API metrics. + +There is a script within insights/scripts, called encode_etl_post_to_logging_api.py. The purpose of that script +is to take every file within the etls directory, encode it, and post it to the its-log API so the ETL can be used. + +If you add a new ETL for its-log, add it to this directory. You'll also need to modify the encode_etl_post_to_logging_api.py +script (details in the script). \ No newline at end of file diff --git a/insights/etls/app-summary.star b/insights/etls/app-summary.star new file mode 100644 index 000000000..297d3f4a8 --- /dev/null +++ b/insights/etls/app-summary.star @@ -0,0 +1,499 @@ +# We do not want to track metrics for the following app names +APP_NAMES_TO_IGNORE = ['TestApp', 'BlueButton Client (Test - Internal Use Only)', 'MyMedicare PROD', 'new-relic', 'datadog'] + +REQUEST_RESPONSE_MIDDLEWARE_TYPE = 'request_response_middleware' + +AUDIT_EVENT_TYPES = [ + "Authentication:start", + "Authentication:success", + "Authorization", + "AccessToken" +] + +REDIRECT_STATUS_CODE = 302 +OK_STATUS_CODE = 200 + + +# Various helper functions +def to_int(value): + if value == None or value == "": + return None + return int(value) + +def is_real(fhir_id_v2, fhir_id_v3): + """ + True if either FHIR ID indicates a real beneficiary. + Mirrors SQL: fhir_id_v2 > 0 OR COALESCE(fhir_id_v3, 0) > 0 + """ + v2 = to_int(fhir_id_v2) + v3 = to_int(fhir_id_v3) + v3_val = v3 if v3 != None else 0 + return (v2 != None and v2 > 0) or v3_val > 0 + +def response_code_equals(response_code, val): + return to_int(response_code) == val + +def response_code_not_equals(response_code, val): + return to_int(response_code) != val + +def response_code_in(response_code, vals): + return to_int(response_code) in vals + +def response_code_not_in(response_code, vals): + return to_int(response_code) not in vals + +def response_code_range(response_code, low, high): + rc = to_int(response_code) + if rc == None: + return False + return (low <= rc and rc < high) + +def response_code_gte(response_code, low): + rc = to_int(response_code) + if rc == None: + return False + return rc >= low + +def path_matches_versioned_token(path): + for v in ["v1", "v2", "v3"]: + if path.startswith("/" + v + "/o/token"): + return True + return False + +def path_matches_authorize_prefix(path): + for v in ["v1", "v2", "v3"]: + if path.startswith("/" + v + "/o/authorize/"): + return True + return False + +def path_matches_authorize_full(path): + for v in ["v1", "v2", "v3"]: + prefix = "/" + v + "/o/authorize/" + if path.startswith(prefix) and path.endswith("/") and len(path) > len(prefix): + return True + return False + +def tag_source_parameter_shared_systems_check(qparam_source, qparam_tag): + """ + Starlark equivalent of: + LOWER(qparam_source) LIKE '%fiss%' OR ... OR + qparam_tag LIKE '%https://bluebutton.cms.gov/fhir/CodeSystem/System-Type|SharedSystem%' + """ + source_lower = qparam_source.lower() if qparam_source != None else "" + tag = qparam_tag if qparam_tag != None else "" + + return ( + "fiss" in source_lower or + "mcs" in source_lower or + "vms" in source_lower or + "map" in source_lower or + "cwf" in source_lower or + "https://bluebutton.cms.gov/fhir/CodeSystem/System-Type|SharedSystem" in tag + ) + +def evaluate_request_response_metrics(tags): + # Specifically analyze logs with type = 'request_response_middleware' + matched = [] + + path = tags.get("path") or "" + request_method = tags.get("request_method") or "" + response_code = tags.get("response_code") + fhir_id_v2 = tags.get("fhir_id_v2") + fhir_id_v3 = tags.get("fhir_id_v3") + lastupdated = tags.get("req_qparam_lastupdated") or "" + auth_grant_type = tags.get("auth_grant_type") or "" + sdk_header = tags.get("req_header_bluebutton_sdk") or "" + qparam_source = tags.get("req_qparam__source") or "" + qparam_tag = tags.get("req_qparam__tag") or "" + patient_match_found = tags.get("patient_match_found") or "" + + # FHIR Resource call stats tracking + # Top level conditional used in each real call, then check if real beneficiary or not, then check path + if request_method == "GET" and response_code_equals(response_code, OK_STATUS_CODE): + if is_real(fhir_id_v2, fhir_id_v3): + # V1 Real Beneficiaries + if path.startswith("/v1/fhir"): + matched.append("app_fhir_v1_call_real_count") + + if path.startswith("/v1/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v1_eob_call_real_count") + + if path.startswith("/v1/fhir/Coverage"): + matched.append("app_fhir_v1_coverage_call_real_count") + + if path.startswith("/v1/fhir/Patient"): + matched.append("app_fhir_v1_patient_call_real_count") + + if path.startswith("/v1/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v1_eob_since_call_real_count") + + if path.startswith("/v1/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v1_coverage_since_call_real_count") + + # V2 Real Beneficiaries + if path.startswith("/v2/fhir"): + matched.append("app_fhir_v2_call_real_count") + + if path.startswith("/v2/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v2_eob_call_real_count") + + if path.startswith("/v2/fhir/Coverage"): + matched.append("app_fhir_v2_coverage_call_real_count") + + if path.startswith("/v2/fhir/Patient"): + matched.append("app_fhir_v2_patient_call_real_count") + + if path.startswith("/v2/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v2_eob_since_call_real_count") + + if path.startswith("/v2/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v2_coverage_since_call_real_count") + + # V3 Real Beneficiaries + if path.startswith("/v3/fhir"): + matched.append("app_fhir_v3_call_real_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v3_eob_call_real_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit") and tag_source_parameter_shared_systems_check(qparam_source, qparam_tag): + matched.append("app_fhir_v3_eob_shared_systems_call_real_count") + + if path.startswith("/v3/fhir/Coverage"): + matched.append("app_fhir_v3_coverage_call_real_count") + + if path.startswith("/v3/fhir/Patient"): + matched.append("app_fhir_v3_patient_call_real_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v3_eob_since_call_real_count") + + if path.startswith("/v3/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v3_coverage_since_call_real_count") + + if path.startswith("/v3/fhir/Patient/") and "insurance-card" in path: + matched.append("app_fhir_v3_generate_insurance_card_call_real_count") + + else: + # V1 Synthetic Beneficiaries + if path.startswith("/v1/fhir"): + matched.append("app_fhir_v1_call_synthetic_count") + + if path.startswith("/v1/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v1_eob_call_synthetic_count") + + if path.startswith("/v1/fhir/Coverage"): + matched.append("app_fhir_v1_coverage_call_synthetic_count") + + if path.startswith("/v1/fhir/Patient"): + matched.append("app_fhir_v1_patient_call_synthetic_count") + + if path.startswith("/v1/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v1_eob_since_call_synthetic_count") + + if path.startswith("/v1/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v1_coverage_since_call_synthetic_count") + + # V2 Synthetic Beneficiaries + if path.startswith("/v2/fhir"): + matched.append("app_fhir_v2_call_synthetic_count") + + if path.startswith("/v2/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v2_eob_call_synthetic_count") + + if path.startswith("/v2/fhir/Coverage"): + matched.append("app_fhir_v2_coverage_call_synthetic_count") + + if path.startswith("/v2/fhir/Patient"): + matched.append("app_fhir_v2_patient_call_synthetic_count") + + if path.startswith("/v2/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v2_eob_since_call_synthetic_count") + + if path.startswith("/v2/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v2_coverage_since_call_synthetic_count") + + # V3 Synthetic Beneficiaries + if path.startswith("/v3/fhir"): + matched.append("app_fhir_v3_call_synthetic_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit"): + matched.append("app_fhir_v3_eob_call_synthetic_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit") and tag_source_parameter_shared_systems_check(qparam_source, qparam_tag): + matched.append("app_fhir_v3_eob_shared_systems_call_synthetic_count") + + if path.startswith("/v3/fhir/Coverage"): + matched.append("app_fhir_v3_coverage_call_synthetic_count") + + if path.startswith("/v3/fhir/Patient"): + matched.append("app_fhir_v3_patient_call_synthetic_count") + + if path.startswith("/v3/fhir/ExplanationOfBenefit") and lastupdated != "": + matched.append("app_fhir_v3_eob_since_call_synthetic_count") + + if path.startswith("/v3/fhir/Coverage") and lastupdated != "": + matched.append("app_fhir_v3_coverage_since_call_synthetic_count") + + if path.startswith("/v3/fhir/Patient/") and "insurance-card" in path: + matched.append("app_fhir_v3_generate_insurance_card_call_synthetic_count") + + if path.startswith("/v1/fhir/metadata") and request_method == "GET" and response_code_equals(response_code, OK_STATUS_CODE): + matched.append("app_fhir_v1_metadata_call_count") + + if path.startswith("/v2/fhir/metadata") and request_method == "GET" and response_code_equals(response_code, OK_STATUS_CODE): + matched.append("app_fhir_v2_metadata_call_count") + + if path.startswith("/v3/fhir/metadata") and request_method == "GET" and response_code_equals(response_code, OK_STATUS_CODE): + matched.append("app_fhir_v3_metadata_call_count") + + # Token request stats + if request_method == "POST" and path_matches_versioned_token(path) and auth_grant_type == "refresh_token": + if response_code_range(response_code, OK_STATUS_CODE, 300): + matched.append("app_token_refresh_response_2xx_count") + elif response_code_range(response_code, 400, 500): + matched.append("app_token_refresh_response_4xx_count") + elif response_code_gte(response_code, 500): + matched.append("app_token_refresh_response_5xx_count") + + if request_method == "POST" and path_matches_versioned_token(path) and auth_grant_type == "authorization_code": + if response_code_range(response_code, OK_STATUS_CODE, 300): + matched.append("app_token_authorization_code_2xx_count") + elif response_code_range(response_code, 400, 500): + matched.append("app_token_authorization_code_4xx_count") + elif response_code_gte(response_code, 500): + matched.append("app_token_authorization_code_5xx_count") + + if request_method == "POST" and path_matches_versioned_token(path) and auth_grant_type == "client_credentials": + if response_code_range(response_code, OK_STATUS_CODE, 300): + matched.append("app_successful_client_credentials_call") + else: + matched.append("app_unsuccessful_client_credentials_call") + + if path_matches_versioned_token(path) and patient_match_found == True: + matched.append("app_successful_patient_match_call") + if path_matches_versioned_token(path) and patient_match_found == False: + matched.append("app_unsuccessful_patient_match_call") + + # Auth flow stats + if path_matches_authorize_prefix(path): + matched.append("app_authorize_initial_count") + + if path == "/mymedicare/login" and response_code_equals(response_code, REDIRECT_STATUS_CODE): + matched.append("app_medicare_login_redirect_ok_count") + + if path == "/mymedicare/login" and response_code_not_equals(response_code, REDIRECT_STATUS_CODE): + matched.append("app_medicare_login_redirect_fail_count") + + if path == "/mymedicare/sls-callback" and response_code_equals(response_code, REDIRECT_STATUS_CODE): + if is_real(fhir_id_v2, fhir_id_v3): + matched.append("app_sls_callback_ok_real_count") + else: + matched.append("app_sls_callback_ok_synthetic_count") + + if path == "/mymedicare/sls-callback" and response_code_not_equals(response_code, REDIRECT_STATUS_CODE): + matched.append("app_sls_callback_fail_count") + + if path_matches_authorize_full(path) and request_method == "GET" and response_code_in(response_code, [OK_STATUS_CODE, REDIRECT_STATUS_CODE]): + if is_real(fhir_id_v2, fhir_id_v3): + matched.append("app_approval_view_get_ok_real_count") + else: + matched.append("app_approval_view_get_ok_synthetic_count") + + if path_matches_authorize_full(path) and request_method == "GET" and response_code_not_in(response_code, [OK_STATUS_CODE, REDIRECT_STATUS_CODE]): + matched.append("app_approval_view_get_fail_count") + + if path_matches_authorize_full(path) and request_method == "POST" and response_code_in(response_code, [OK_STATUS_CODE, REDIRECT_STATUS_CODE]): + if is_real(fhir_id_v2, fhir_id_v3): + matched.append("app_approval_view_post_ok_real_count") + else: + matched.append("app_approval_view_post_ok_synthetic_count") + + if path_matches_authorize_full(path) and request_method == "POST" and response_code_not_in(response_code, [OK_STATUS_CODE, REDIRECT_STATUS_CODE]): + matched.append("app_approval_view_post_fail_count") + + if sdk_header == "python": + matched.append("app_sdk_requests_python_count") + + if sdk_header == "node": + matched.append("app_sdk_requests_node_count") + + return matched + +def evaluate_audit_metrics(tags): + # Specifically analyze log events with type equal to Authentication:start, Authentication:success, AccessToken or Authorization + matched = [] + + event_type = tags.get("type") or "" + auth_status = tags.get("auth_status") or "" + allow = tags.get("allow") or "" + auth_grant_type = tags.get("auth_grant_type") or "" + auth_action = tags.get("action") or "" + auth_crosswalk_action = tags.get("auth_crosswalk_action") or "" + auth_require_demographic_scopes = tags.get("auth_require_demographic_scopes") or "" + share_demographic_scopes = tags.get("share_demographic_scopes") or "" + sls_status = tags.get("sls_userinfo_status_code") + auth_share_samhsa_data = tags.get("auth_share_samhsa_data") or "" + path = tags.get("path") or "" + + # For Authorization/Authentication:success events + crosswalk_fhir_id = tags.get("fhir_id_v2") + crosswalk_fhir_id_v3 = tags.get("fhir_id_v3") + + if event_type == "Authorization": + + if auth_status == "OK" and allow == "True": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_ok_real_bene_count") + else: + matched.append("app_auth_ok_synthetic_bene_count") + + if auth_status == "FAIL": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_fail_or_deny_real_bene_count") + else: + matched.append("app_auth_fail_or_deny_synthetic_bene_count") + + + if auth_status == "OK" and allow == "True" and auth_require_demographic_scopes == "True" and share_demographic_scopes == "True": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_demoscope_required_choice_sharing_real_bene_count") + else: + matched.append("app_auth_demoscope_required_choice_sharing_synthetic_bene_count") + + if auth_status == "OK" and allow == "True" and auth_require_demographic_scopes == "True" and share_demographic_scopes == "False": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_demoscope_required_choice_not_sharing_real_bene_count") + else: + matched.append("app_auth_demoscope_required_choice_not_sharing_synthetic_bene_count") + + if allow == "False" and auth_require_demographic_scopes == "True": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_demoscope_required_choice_deny_real_bene_count") + else: + matched.append("app_auth_demoscope_required_choice_deny_synthetic_bene_count") + + if auth_status == "OK" and allow == "True" and auth_require_demographic_scopes == "False": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_demoscope_not_required_not_sharing_real_bene_count") + else: + matched.append("app_auth_demoscope_not_required_not_sharing_synthetic_bene_count") + + if allow == "False" and auth_require_demographic_scopes == "False": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_demoscope_not_required_deny_real_bene_count") + else: + matched.append("app_auth_demoscope_not_required_deny_synthetic_bene_count") + + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3) and (path.startswith('/v1/o/authorize') or path.startswith('/v2/o/authorize')): + matched.append("app_auth_v1_v2_user_clicks_connect_bene_count") + + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3) and path.startswith('/v3/o/authorize'): + matched.append("app_auth_v3_user_clicks_connect_bene_count") + + if auth_status == "OK" and (allow == "True" or allow == True) and (auth_share_samhsa_data == "True" or auth_share_samhsa_data == True): + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_samhsa_presented_sharing_real_bene_count") + else: + matched.append("app_auth_samhsa_presented_sharing_synthetic_bene_count") + + if auth_status == "OK" and (allow == "True" or allow == True) and (auth_share_samhsa_data == "False" or auth_share_samhsa_data == False): + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_samhsa_presented_not_sharing_real_bene_count") + else: + matched.append("app_auth_samhsa_presented_not_sharing_synthetic_bene_count") + + if auth_status == "OK" and (allow == "True" or allow == True) and auth_share_samhsa_data == "": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_auth_samhsa_not_presented_real_bene_count") + else: + matched.append("app_auth_samhsa_not_presented_synthetic_bene_count") + + if event_type == "AccessToken": + + if auth_action == "authorized" and auth_grant_type == "refresh_token": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_token_refresh_for_real_bene_count") + else: + matched.append("app_token_refresh_for_synthetic_bene_count") + + if auth_grant_type == "authorization_code": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_token_authorization_code_for_real_bene_count") + else: + matched.append("app_token_authorization_code_for_synthetic_bene_count") + + if event_type == "Authentication:start": + + if response_code_equals(sls_status, OK_STATUS_CODE): + matched.append("app_authentication_start_ok_count") + else: + matched.append("app_authentication_start_fail_count") + + if event_type == "Authentication:success": + + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3) and (path == 'v1/mymedicare/sls-callback' or path == 'v2/mymedicare/sls-callback'): + matched.append("app_auth_v1_v2_user_makes_it_to_permission_screen_bene_count") + + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3) and path == 'v3/mymedicare/sls-callback': + matched.append("app_auth_v3_user_makes_it_to_permission_screen_bene_count") + + if auth_crosswalk_action == "C": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_authentication_matched_new_bene_real_count") + else: + matched.append("app_authentication_matched_new_bene_synthetic_count") + + if auth_crosswalk_action == "R": + if is_real(crosswalk_fhir_id, crosswalk_fhir_id_v3): + matched.append("app_authentication_matched_returning_bene_real_count") + else: + matched.append("app_authentication_matched_returning_bene_synthetic_count") + + return matched + +def summarize(): + # Entry point for app-summary ETL + + # Dictionary to track event counts grouped by metric/app + # For each event that applies to a specific metric for an app, + # We increment the count for that metric/app key + accumulator = {} + + # List that will contain the summary rows that will be returned/written to itslog_summary + returning_summary_rows = [] + + events = query('events', 'SELECT * FROM itslog_events') + + for event in events: + # for event_dict in EVENTS: + event_dict = json.decode(event.get('value')) + print("THE EVENT: ", event_dict) + + app_name = event_dict.get('app_name') + app_id = event_dict.get('app_id') + + if not app_name or not app_id: + continue + + app_tag = str(app_id) + '.' + app_name + + if event_dict.get('type') == REQUEST_RESPONSE_MIDDLEWARE_TYPE: + for metric in evaluate_request_response_metrics(event_dict): + key = (metric, app_tag) + accumulator[key] = accumulator.get(key, 0) + 1 + + if event_dict.get('type') in AUDIT_EVENT_TYPES: + for metric in evaluate_audit_metrics(event_dict): + key = (metric, app_tag) + accumulator[key] = accumulator.get(key, 0) + 1 + + for (metric_tag, app_tag), count in accumulator.items(): + returning_summary_rows.append({ + "operation": metric_tag, + "tags": app_tag, + "value": str(count), + "count": 1, + }) + + return returning_summary_rows diff --git a/insights/etls/global-metrics.star b/insights/etls/global-metrics.star new file mode 100644 index 000000000..46bdad90a --- /dev/null +++ b/insights/etls/global-metrics.star @@ -0,0 +1,97 @@ +APP_GLOBAL_METRIC_KEYS = [ + 'fhir_v1_patient_call_synthetic_count', + 'fhir_v1_coverage_call_synthetic_count', + 'fhir_v1_eob_call_synthetic_count', + 'fhir_v1_call_synthetic_count', + 'fhir_v1_patient_call_real_count', + 'fhir_v1_coverage_call_real_count', + 'fhir_v1_eob_call_real_count', + 'fhir_v1_call_real_count', + 'fhir_v1_metadata_call_count', + 'fhir_v1_coverage_since_call_synthetic_count', + 'fhir_v1_coverage_since_call_real_count', + 'fhir_v1_eob_since_call_synthetic_count', + 'fhir_v1_eob_since_call_real_count', + + 'fhir_v2_patient_call_synthetic_count', + 'fhir_v2_coverage_call_synthetic_count', + 'fhir_v2_eob_call_synthetic_count', + 'fhir_v2_call_synthetic_count', + 'fhir_v2_patient_call_real_count', + 'fhir_v2_coverage_call_real_count', + 'fhir_v2_eob_call_real_count', + 'fhir_v2_call_real_count', + 'fhir_v2_metadata_call_count', + 'fhir_v2_coverage_since_call_synthetic_count', + 'fhir_v2_coverage_since_call_real_count', + 'fhir_v2_eob_since_call_synthetic_count', + 'fhir_v2_eob_since_call_real_count', + + 'fhir_v3_generate_insurance_card_call_synthetic_count', + 'fhir_v3_patient_call_synthetic_count', + 'fhir_v3_coverage_call_synthetic_count', + 'fhir_v3_eob_call_synthetic_count', + 'fhir_v3_call_synthetic_count', + 'fhir_v3_generate_insurance_card_call_real_count', + 'fhir_v3_patient_call_real_count', + 'fhir_v3_coverage_call_real_count', + 'fhir_v3_eob_call_real_count', + 'fhir_v3_call_real_count', + 'fhir_v3_metadata_call_count', + 'fhir_v3_coverage_since_call_synthetic_count', + 'fhir_v3_coverage_since_call_real_count', + 'fhir_v3_eob_since_call_synthetic_count', + 'fhir_v3_eob_since_call_real_count', + + 'fhir_v3_eob_shared_systems_call_real_count', + 'fhir_v3_eob_shared_systems_call_synthetic_count', + + 'auth_v1_v2_user_makes_it_to_permission_screen_bene_count', + 'auth_v1_v2_user_clicks_connect_bene_count', + 'auth_v3_user_makes_it_to_permission_screen_bene_count', + 'auth_v3_user_clicks_connect_bene_count', + + 'auth_samhsa_presented_sharing_real_bene_count', + 'auth_samhsa_presented_sharing_synthetic_bene_count', + 'auth_samhsa_presented_not_sharing_real_bene_count', + 'auth_samhsa_presented_not_sharing_synthetic_bene_count', + 'auth_samhsa_not_presented_real_bene_count', + 'auth_samhsa_not_presented_synthetic_bene_count', + + 'successful_client_credentials_call', + 'unsuccessful_client_credentials_call', + 'successful_patient_match_call', + 'unsuccessful_patient_match_call' +] + + +# needed this function as starlark does not seem to have a sum function +def sum_total(list_of_summary_values): + total = 0 + for value in list_of_summary_values: + total += int(value) + return total + +def summarize(): + summaries = [] + for value in APP_GLOBAL_METRIC_KEYS: + # Grab all summary records for specific app-level value + # Starlark does not support string formatting, hence concatenation + # We only need the value back + app_value = 'app_' + value + summary_query = "SELECT * from itslog_summary WHERE operation = '" + app_value + "';" + summary_rows = query('summary', summary_query) + + # Only grab the value from the retrieved summaries + summary_values_for_specific_metric = [s[app_value] for s in summary_rows] + + total = sum_total(summary_values_for_specific_metric) + # Construct the global summary record and append it to the list that will be returned + global_summary = { + 'operation': value, + 'value': str(total), + 'count': 1 + } + summaries.append(global_summary) + + return summaries diff --git a/insights/etls/remove-outdated-summaries.sql b/insights/etls/remove-outdated-summaries.sql new file mode 100644 index 000000000..559a95fd4 --- /dev/null +++ b/insights/etls/remove-outdated-summaries.sql @@ -0,0 +1 @@ +DELETE FROM itslog_summary WHERE id NOT IN (SELECT MAX(id) FROM itslog_summary GROUP BY operation, tags) RETURNING 0; \ No newline at end of file diff --git a/insights/scripts/encode_etl_post_to_logging_api.py b/insights/scripts/encode_etl_post_to_logging_api.py new file mode 100644 index 000000000..becc5af2b --- /dev/null +++ b/insights/scripts/encode_etl_post_to_logging_api.py @@ -0,0 +1,74 @@ +"""The purpose of this script is to pull in files from the insights/etls directory, encode them, and post them +to the its-log API. This aids in testing the its-log API locally, by programmatically creating the ETLs and bb sequence +rather than needing to do it manually. + +If you add a new ETL for its-log, add the file in the etls directory. If you want the file to be ignored and not posted in this +script, prefix the file with an underscore. + +Must run the script from the project root and set the ITSLOG_APIKEY value in your terminal before running. +""" + +import base64 +import os +from pathlib import Path + +import requests + +ETL_FILE_EXTENSIONS = ['.star', '.sql', '.go'] +ETL_FILE_DIR = 'insights/etls' +ETL_CREATION_ENDPOINT = 'http://localhost:8888/v1/etl/create' +SEQUENCE_CREATION_ENDPOINT = 'http://localhost:8888/v1/sequence/create' +ETL_DIRECTORY = Path('insights/etls') +# Can't use settings in this script so retrieve via getenv +API_KEY = os.getenv('ITSLOG_APIKEY') + + +def encode_file(file_path: Path) -> str: + with open(file_path, 'rb') as f: + file_bytes = f.read() + encoded_file = base64.b64encode(file_bytes).decode('ascii') + return encoded_file + + +def post_etl_to_its_log(etl_name: str, file_extension: str, encoded_file: str) -> None: + if file_extension == 'star': + file_extension = 'starlark' + payload = { + 'name': etl_name, + 'kind': file_extension, + 'body': encoded_file, + 'date': 'today', + } + + response = requests.post(ETL_CREATION_ENDPOINT, headers={'x-api-key': API_KEY}, json=payload, timeout=5) + print(f'response status code: {response.status_code}') + + +def main(): + files = [ + f for f in ETL_DIRECTORY.iterdir() if f.is_file() and (not f.name.startswith('_') or f.name == 'README.md') + ] + file_names_list = [] + + for file in files: + print(f'file: {file.name}') + encoded_file = encode_file(file) + etl_name = file.stem + file_extension = file.suffix.replace('.', '') + post_etl_to_its_log(etl_name, file_extension, encoded_file) + file_names_list.append({'name': etl_name}) + + sequence_payload = { + 'name': 'bb', + 'kind': 'sequence', + 'body': file_names_list, + 'date': 'today', + } + sequence_response = requests.post( + SEQUENCE_CREATION_ENDPOINT, headers={'x-api-key': API_KEY}, json=sequence_payload, timeout=5 + ) + print(f'sequence creation status code: {sequence_response.status_code}') + + +if __name__ == '__main__': + main() diff --git a/ops/containers/.env.local b/ops/containers/.env.local index 9772e8100..4f67d7b5d 100644 --- a/ops/containers/.env.local +++ b/ops/containers/.env.local @@ -69,4 +69,7 @@ DJANGO_USER_ID_ITERATIONS="2" # 20260210 Added as part of BB2-4438, move to django-environ for local env var sourcing TARGET_ENV="local" -DJANGO_SECRET_KEY='please-change-me' \ No newline at end of file +DJANGO_SECRET_KEY='please-change-me' + +ITS_LOG_API_ENABLED=False +ITSLOG_APIKEY=${ITSLOG_APIKEY} \ No newline at end of file diff --git a/ops/containers/bb-api/files/external/.env.codebuild b/ops/containers/bb-api/files/external/.env.codebuild index cc6dd95af..470ad5458 100644 --- a/ops/containers/bb-api/files/external/.env.codebuild +++ b/ops/containers/bb-api/files/external/.env.codebuild @@ -57,3 +57,7 @@ TARGET_ENV="${TARGET_ENV}" MIGRATE="${MIGRATE}" COLLECTSTATIC="${COLLECTSTATIC}" DATABASES_CUSTOM="sqlite:////tmp/db.sqlite3" +ITS_LOG_API_ENABLED="${ITS_LOG_API_ENABLED}" +JWKS_PUBLIC_KEY_PEM="${JWKS_PUBLIC_KEY_PEM}" +CAN_PRIVATE_KEY="${CAN_PRIVATE_KEY}" +ITSLOG_APIKEY="${ITSLOG_APIKEY}" diff --git a/ops/containers/bb-api/files/external/.env.container b/ops/containers/bb-api/files/external/.env.container index 4e6071d20..627644d22 100644 --- a/ops/containers/bb-api/files/external/.env.container +++ b/ops/containers/bb-api/files/external/.env.container @@ -59,4 +59,6 @@ CAN_INTEGRATION_TEST="${CAN_INTEGRATION_TEST}" JWKS_PRIVATE_KEY_PEM="${JWKS_PRIVATE_KEY_PEM}" TARGET_ENV="${TARGET_ENV}" MIGRATE="${MIGRATE}" -COLLECTSTATIC="${COLLECTSTATIC}" \ No newline at end of file +COLLECTSTATIC="${COLLECTSTATIC}" +ITS_LOG_API_ENABLED="${ITS_LOG_API_ENABLED}" +ITSLOG_APIKEY="${ITSLOG_APIKEY}" \ No newline at end of file diff --git a/ops/containers/bb-api/scripts/external/prepare-environment-support.bash b/ops/containers/bb-api/scripts/external/prepare-environment-support.bash index 273047777..d30b202eb 100755 --- a/ops/containers/bb-api/scripts/external/prepare-environment-support.bash +++ b/ops/containers/bb-api/scripts/external/prepare-environment-support.bash @@ -102,6 +102,8 @@ load_env_vars () { export SUPER_USER_PASSWORD="${SUPER_USER_PASSWORD:-blue123}" export MIGRATE="${MIGRATE}" export COLLECTSTATIC="${COLLECTSTATIC}" + export ITS_LOG_API_ENABLED="${ITS_LOG_API_ENABLED:-false}" + export ITSLOG_APIKEY="${ITSLOG_APIKEY}" return 0 else echo "⛔ Cannot load env vars for non-local environments." diff --git a/ops/services/01-config/values/prod.sopsw.yaml b/ops/services/01-config/values/prod.sopsw.yaml index 6bbfd1cff..f63f3a284 100644 --- a/ops/services/01-config/values/prod.sopsw.yaml +++ b/ops/services/01-config/values/prod.sopsw.yaml @@ -74,6 +74,7 @@ /bb/prod/app/sensitive/django_slsx_relationships_endpoint: ENC[AES256_GCM,data:0plM6QA3vo90Wk+esghBtScKJm+JBkiHD+ERdvFiJ7U7P88VmsDuorfVyowR2Xd3HFpPjCSdk8xiV6C5sD1Er5KUbms=,iv:suKskNbapvYCk2UgLcZ9UcKw4Rm/kzY9BEniEOSLnn4=,tag:JFj3noGPhF/kUSGkXYJbew==,type:str] /bb/prod/app/nonsensitive/django_slsx_verify_ssl_internal: "False" /bb/prod/app/nonsensitive/django_slsx_verify_ssl_external: "True" +/bb/prod/app/nonsensitive/its_log_api_enabled: "False" #ENC[AES256_GCM,data:cjxYrqg/L58XyzZNVBl/xzq6OkIsxhtHe/gyDGvbSnUMuEmBybfd4e+JzGhG49ztVDIUP1btyokUy6mF5BOW53npkRsJrqJoPzLpGeQ=,iv:qaDWHiwa+TT+2/uBMtdSIm7EpbwgeTsMx8XUhBcDh48=,tag:FsvNuBIpoRdn1KWTaIM7iA==,type:comment] #ENC[AES256_GCM,data:WA4aaT2R1Z24ZZ6BJuxQxPBkFsdAqxv0o7ymazQHZbKakWlw/Fp2OOJjp97c10fXYcYcm0CoHZ0DggtAWUdGya5FfPXKmQSpNareWm4=,iv:a2bjHzKr6UJleUt+QH0sBY4I8+7bJa2rczi32jgOwo8=,tag:qUCmbduZaUPTyCg8EAhNTQ==,type:comment] #ENC[AES256_GCM,data:cjxYrqg/L58XyzZNVBl/xzq6OkIsxhtHe/gyDGvbSnUMuEmBybfd4e+JzGhG49ztVDIUP1btyokUy6mF5BOW53npkRsJrqJoPzLpGeQ=,iv:qaDWHiwa+TT+2/uBMtdSIm7EpbwgeTsMx8XUhBcDh48=,tag:FsvNuBIpoRdn1KWTaIM7iA==,type:comment] diff --git a/ops/services/01-config/values/sandbox.sopsw.yaml b/ops/services/01-config/values/sandbox.sopsw.yaml index 1fdacd3c6..39883e7f8 100644 --- a/ops/services/01-config/values/sandbox.sopsw.yaml +++ b/ops/services/01-config/values/sandbox.sopsw.yaml @@ -71,6 +71,7 @@ /bb/sandbox/app/sensitive/django_slsx_relationships_endpoint: ENC[AES256_GCM,data:hT8Ra89Rv73RWnv+76ZqmKDCkADcN+tNf3mkPp18cPE2zYZ7Z1oZgxgm4JNLjBAZIaWz1/TbnshGJDKSOZqGg9v6LRE=,iv:sKwV0zzbfVuqlhK6oRrI1QuPxvjAtG+66ORSGSX8pX4=,tag:1/knJicWu5SeFG2pz2lKuA==,type:str] /bb/sandbox/app/nonsensitive/django_slsx_verify_ssl_internal: "False" /bb/sandbox/app/nonsensitive/django_slsx_verify_ssl_external: "True" +/bb/sandbox/app/nonsensitive/its_log_api_enabled: "False" #ENC[AES256_GCM,data:etJuMbKWQ0eVN2BYCoqNPOCysTgkaSkJlDAhs4q7QcdoMf8EN+xJ4RwNOf+xCRGcOZeHkzUJlCETeZ179TWzfB3N49R8p3LU2ZrSF54=,iv:ZwQ7c8FbeCF4jQKXALyxcK+WXwV5o6X2/QFGqAeo2tI=,tag:4Utwk/gsCx+eMXSo5L9SCw==,type:comment] #ENC[AES256_GCM,data:oVVurYECDJWPSpwd3HW7bg==,iv:Z5A0OIYmDMnVOl5vya5hiv8tobIEtDj9iMGHtVwsmY0=,tag:tBOcqe3ywUtOBLWPlTneYw==,type:comment] #ENC[AES256_GCM,data:etJuMbKWQ0eVN2BYCoqNPOCysTgkaSkJlDAhs4q7QcdoMf8EN+xJ4RwNOf+xCRGcOZeHkzUJlCETeZ179TWzfB3N49R8p3LU2ZrSF54=,iv:ZwQ7c8FbeCF4jQKXALyxcK+WXwV5o6X2/QFGqAeo2tI=,tag:4Utwk/gsCx+eMXSo5L9SCw==,type:comment] diff --git a/ops/services/01-config/values/test.sopsw.yaml b/ops/services/01-config/values/test.sopsw.yaml index 891437882..eee661f52 100644 --- a/ops/services/01-config/values/test.sopsw.yaml +++ b/ops/services/01-config/values/test.sopsw.yaml @@ -69,6 +69,7 @@ /bb/test/app/sensitive/django_slsx_relationships_endpoint: ENC[AES256_GCM,data:oAYMSEu0KTYIqyIIjj6xhsnRVsMegHIZWfqCFYu09e7tp3Sh9NdpAFxPu7BFE9XMN3u6/fQ2qkUUDS0hymvB9UNBUD85H1Sp0g==,iv:hL2pR/qr0CdAzTe/RFCk/8Rcc/TGEGqPN+1KQqzWxPo=,tag:qv2HFQLdaYI6mrE8GAZ52A==,type:str] /bb/test/app/nonsensitive/django_slsx_verify_ssl_internal: "False" /bb/test/app/nonsensitive/django_slsx_verify_ssl_external: "True" +/bb/test/app/nonsensitive/its_log_api_enabled: "False" #ENC[AES256_GCM,data:NEJYqpcJLWvsdG8PYRiAeGCrFpURmucrKzWdyMaq6WEstOCPfJS6JfMTFhthqBzBu8CVXGDcQlvlnlXpNH1SjOGpTA7vsBFt2shvegI=,iv:H9c/gKlV7taXi3VeOGys7O2XBdZ/EQvd0NSBsY6I48g=,tag:qS6CR1nX3w+jUcGPLAyWgg==,type:comment] #ENC[AES256_GCM,data:iVoQibbwQkn8s8Pss+qMiw==,iv:upVv0NvD2KQq8hH6JHRV+06stcBbM8/wW+BriWU6XOY=,tag:RxxF/GIvS1Z7+syXUBuNNg==,type:comment] #ENC[AES256_GCM,data:NEJYqpcJLWvsdG8PYRiAeGCrFpURmucrKzWdyMaq6WEstOCPfJS6JfMTFhthqBzBu8CVXGDcQlvlnlXpNH1SjOGpTA7vsBFt2shvegI=,iv:H9c/gKlV7taXi3VeOGys7O2XBdZ/EQvd0NSBsY6I48g=,tag:qS6CR1nX3w+jUcGPLAyWgg==,type:comment] diff --git a/ops/services/01-config/values/test.sopsw.yaml.seed b/ops/services/01-config/values/test.sopsw.yaml.seed index f4745a233..0a36f0267 100644 --- a/ops/services/01-config/values/test.sopsw.yaml.seed +++ b/ops/services/01-config/values/test.sopsw.yaml.seed @@ -61,3 +61,8 @@ # ============================================================================ /bb/${env}/app/nonsensitive/aws_s3_custom_domain: "s3.amazonaws.com" /bb/${env}/app/nonsensitive/aws_storage_bucket_name: "bb-test-static-content" + +# ============================================================================ +# ITS-log API +# ============================================================================ +/bb/${env}/app/nonsensitive/its_log_api_enabled: "False"