From 0efe0a7d5c4559b39c793754df0bdee92ec8129f Mon Sep 17 00:00:00 2001 From: "Mitch Harding (the weird one)" Date: Thu, 21 Mar 2024 16:50:20 -0400 Subject: [PATCH] CASMCMS-8949: Improve BOS v2 debug logging (cherry picked from commit 2e375e62ad9cec7b9836c54cce0a7d0dd6773e10) --- CHANGELOG.md | 4 +++ src/bos/operators/actual_state_cleanup.py | 3 +- src/bos/operators/base.py | 8 +++++- src/bos/operators/power_on.py | 7 +++++ src/bos/operators/session_setup.py | 13 +++++---- src/bos/operators/utils/clients/bos/base.py | 28 +++++++++++++++---- .../operators/utils/clients/bos/options.py | 3 +- .../utils/clients/bos/sessions_status.py | 4 ++- src/bos/operators/utils/clients/bss.py | 5 +++- src/bos/operators/utils/clients/cfs.py | 17 ++++++++++- src/bos/operators/utils/clients/hsm.py | 9 ++++++ src/bos/operators/utils/rootfs/cpss3.py | 5 +++- src/bos/server/controllers/v2/base.py | 6 ++-- src/bos/server/controllers/v2/components.py | 23 +++++++++------ src/bos/server/controllers/v2/healthz.py | 3 +- src/bos/server/controllers/v2/options.py | 6 ++-- src/bos/server/controllers/v2/sessions.py | 13 +++++++-- .../server/controllers/v2/sessiontemplates.py | 23 ++++++++------- 18 files changed, 135 insertions(+), 45 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 081a9e65..86a1d191 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [2.10.9] - 2024-03-20 +### Changed +- Improvements to BOS v2 debug logging. + ## [2.10.8] - 2024-03-12 ### Fixed - Update base operator to handle case where all nodes to act on have exceeded their retry limit diff --git a/src/bos/operators/actual_state_cleanup.py b/src/bos/operators/actual_state_cleanup.py index 3129e665..17191e9f 100644 --- a/src/bos/operators/actual_state_cleanup.py +++ b/src/bos/operators/actual_state_cleanup.py @@ -2,7 +2,7 @@ # # MIT License # -# (C) Copyright 2021-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -64,6 +64,7 @@ def _act(self, components): data.append({'id': component_id, 'actual_state': EMPTY_ACTUAL_STATE}) if data: + LOGGER.info('Found %d components that require updates', len(data)) LOGGER.debug('Calling to update with payload: %s' %(data)) self.bos_client.components.update_components(data) return components diff --git a/src/bos/operators/base.py b/src/bos/operators/base.py index 92ce59f8..1c988203 100644 --- a/src/bos/operators/base.py +++ b/src/bos/operators/base.py @@ -114,7 +114,7 @@ def _run(self) -> None: if not components: LOGGER.debug('Found 0 components that require action') return - LOGGER.info('Found {} components that require action'.format(len(components))) + LOGGER.info('Found %d components that require action', len(components)) if self.retry_attempt_field: # Only check for failed components if we track retries for this operator components = self._handle_failed_components(components) if not components: @@ -191,6 +191,8 @@ def _update_database(self, components: List[dict], additional_fields: dict=None) if 'desired_state' in patch and 'session' not in patch: raise MissingSessionData data.append(patch) + LOGGER.info('Found %d components that require updates', len(data)) + LOGGER.debug(f'Updated components: {data}') self.bos_client.components.update_components(data) def _preset_last_action(self, components: List[dict]) -> None: @@ -211,6 +213,8 @@ def _preset_last_action(self, components: List[dict]) -> None: } patch['last_action'] = last_action_data data.append(patch) + LOGGER.info('Found %d components that require updates', len(data)) + LOGGER.debug(f'Updated components: {data}') self.bos_client.components.update_components(data) def _update_database_for_failure(self, components: List[dict]) -> None: @@ -226,6 +230,8 @@ def _update_database_for_failure(self, components: List[dict]) -> None: if not component['error']: patch['error'] = 'The retry limit has been hit for this component, but no services have reported specific errors' data.append(patch) + LOGGER.info('Found %d components that require updates', len(data)) + LOGGER.debug(f'Updated components: {data}') self.bos_client.components.update_components(data) diff --git a/src/bos/operators/power_on.py b/src/bos/operators/power_on.py index b0c81dcb..aefc4b36 100644 --- a/src/bos/operators/power_on.py +++ b/src/bos/operators/power_on.py @@ -127,6 +127,13 @@ def _set_bss(self, components, retries=5): bss_tokens.append({"id": node, "desired_state": {"bss_token": token}, "session": sessions[node]}) + LOGGER.info('Found %d components that require BSS token updates', len(bss_tokens)) + redacted_component_updates = [ + { "id": comp["id"], + "session": comp["session"] + } + for comp in bss_tokens ] + LOGGER.debug('Updated components (minus desired_state data): {}'.format(redacted_component_updates)) self.bos_client.components.update_components(bss_tokens) diff --git a/src/bos/operators/session_setup.py b/src/bos/operators/session_setup.py index f68e4991..934d38f2 100644 --- a/src/bos/operators/session_setup.py +++ b/src/bos/operators/session_setup.py @@ -71,7 +71,7 @@ def _run(self) -> None: sessions = self._get_pending_sessions() if not sessions: return - LOGGER.info('Found {} sessions that require action'.format(len(sessions))) + LOGGER.info('Found %d sessions that require action', len(sessions)) inventory_cache = Inventory() for data in sessions: session = Session(data, inventory_cache, self.bos_client) @@ -137,6 +137,8 @@ def _setup_components(self): except Exception as err: raise SessionSetupException(err) else: + self._log(LOGGER.info, 'Found %d components that require updates', len(data)) + self._log(LOGGER.debug, f'Updated components: {data}') self.bos_client.components.update_components(data) return list(set(all_component_ids)) @@ -250,8 +252,8 @@ def _mark_failed(self, err): sco._mark_session_complete(self.name, self.tenant) self._log(LOGGER.info, f'Session {self.name} has failed.') - def _log(self, logger, message): - logger('Session {}: {}'.format(self.name, message)) + def _log(self, logger, message, *xargs): + logger('Session {}: {}'.format(self.name, message), *xargs) # Operations def _operate(self, component_id, state): @@ -337,7 +339,8 @@ def assemble_kernel_boot_parameters(self, boot_set, artifact_info): # Parameters from the image itself if the parameters exist. if (artifact_info.get('boot_parameters') is not None and artifact_info.get('boot_parameters_etag') is not None): - LOGGER.info("++ _get_s3_download_url %s with etag %s.", + self._log(LOGGER.info, + "++ _get_s3_download_url %s with etag %s.", artifact_info['boot_parameters'], artifact_info['boot_parameters_etag']) @@ -351,7 +354,7 @@ def assemble_kernel_boot_parameters(self, boot_set, artifact_info): if image_kernel_parameters: boot_param_pieces.extend(image_kernel_parameters) except (ClientError, UnicodeDecodeError, S3ObjectNotFound) as error: - LOGGER.error("Unable to read file {}. Thus, no kernel boot parameters obtained " + self._log(LOGGER.error, "Unable to read file {}. Thus, no kernel boot parameters obtained " "from image".format(artifact_info['boot_parameters'])) LOGGER.error(error) raise diff --git a/src/bos/operators/utils/clients/bos/base.py b/src/bos/operators/utils/clients/bos/base.py index c3959e06..c3a89422 100644 --- a/src/bos/operators/utils/clients/bos/base.py +++ b/src/bos/operators/utils/clients/bos/base.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -70,6 +70,7 @@ def __init__(self): def get_item(self, item_id): """Get information for a single BOS item""" url = self.base_url + '/' + item_id + LOGGER.debug("GET %s", url) response = self.session.get(url) response.raise_for_status() item = json.loads(response.text) @@ -78,6 +79,7 @@ def get_item(self, item_id): @log_call_errors def get_items(self, **kwargs): """Get information for all BOS items""" + LOGGER.debug("GET %s with params=%s", self.base_url, kwargs) response = self.session.get(self.base_url, params=kwargs) response.raise_for_status() items = json.loads(response.text) @@ -87,6 +89,7 @@ def get_items(self, **kwargs): def update_item(self, item_id, data): """Update information for a single BOS item""" url = self.base_url + '/' + item_id + LOGGER.debug("PATCH %s with body=%s", url, data) response = self.session.patch(url, json=data) response.raise_for_status() item = json.loads(response.text) @@ -95,6 +98,7 @@ def update_item(self, item_id, data): @log_call_errors def update_items(self, data): """Update information for multiple BOS items""" + LOGGER.debug("PATCH %s with body=%s", self.base_url, data) response = self.session.patch(self.base_url, json=data) response.raise_for_status() items = json.loads(response.text) @@ -103,6 +107,7 @@ def update_items(self, data): @log_call_errors def put_items(self, data): """Put information for multiple BOS Items""" + LOGGER.debug("PUT %s with body=%s", self.base_url, data) response = self.session.put(self.base_url, json=data) response.raise_for_status() items = json.loads(response.text) @@ -111,6 +116,7 @@ def put_items(self, data): @log_call_errors def delete_items(self, **kwargs): """Delete information for multiple BOS items""" + LOGGER.debug("DELETE %s with params=%s", self.base_url, kwargs) response = self.session.delete(self.base_url, params=kwargs) response.raise_for_status() if response.text: @@ -129,6 +135,7 @@ class BaseBosTenantAwareEndpoint(BaseBosEndpoint): def get_item(self, item_id, tenant): """Get information for a single BOS item""" url = self.base_url + '/' + item_id + LOGGER.debug("GET %s for tenant=%s", url, tenant) response = self.session.get(url, headers=get_new_tenant_header(tenant)) response.raise_for_status() item = json.loads(response.text) @@ -139,8 +146,11 @@ def get_items(self, **kwargs): """Get information for all BOS items""" headers = None if "tenant" in kwargs: - headers = get_new_tenant_header(kwargs["tenant"]) - del kwargs["tenant"] + tenant = kwargs.pop("tenant") + headers = get_new_tenant_header(tenant) + LOGGER.debug("GET %s for tenant=%s with params=%s", self.base_url, tenant, kwargs) + else: + LOGGER.debug("GET %s with params=%s", self.base_url, kwargs) response = self.session.get(self.base_url, params=kwargs, headers=headers) response.raise_for_status() items = json.loads(response.text) @@ -150,6 +160,7 @@ def get_items(self, **kwargs): def update_item(self, item_id, tenant, data): """Update information for a single BOS item""" url = self.base_url + '/' + item_id + LOGGER.debug("PATCH %s for tenant=%s with body=%s", url, tenant, data) response = self.session.patch(url, json=data, headers=get_new_tenant_header(tenant)) response.raise_for_status() item = json.loads(response.text) @@ -158,6 +169,7 @@ def update_item(self, item_id, tenant, data): @log_call_errors def update_items(self, tenant, data): """Update information for multiple BOS items""" + LOGGER.debug("PATCH %s for tenant=%s with body=%s", self.base_url, tenant, data) response = self.session.patch(self.base_url, json=data, headers=get_new_tenant_header(tenant)) response.raise_for_status() items = json.loads(response.text) @@ -165,7 +177,8 @@ def update_items(self, tenant, data): @log_call_errors def put_items(self, tenant, data): - """Put information for multiple BOS Items""" + """Put information for multiple BOS items""" + LOGGER.debug("PUT %s for tenant=%s with body=%s", self.base_url, tenant, data) response = self.session.put(self.base_url, json=data, headers=get_new_tenant_header(tenant)) response.raise_for_status() items = json.loads(response.text) @@ -176,8 +189,11 @@ def delete_items(self, **kwargs): """Delete information for multiple BOS items""" headers = None if "tenant" in kwargs: - headers = get_new_tenant_header(kwargs["tenant"]) - del kwargs["tenant"] + tenant = kwargs.pop("tenant") + headers = get_new_tenant_header(tenant) + LOGGER.debug("DELETE %s for tenant=%s with params=%s", self.base_url, tenant, kwargs) + else: + LOGGER.debug("DELETE %s with params=%s", self.base_url, kwargs) response = self.session.delete(self.base_url, params=kwargs, headers=headers) response.raise_for_status() if response.text: diff --git a/src/bos/operators/utils/clients/bos/options.py b/src/bos/operators/utils/clients/bos/options.py index e77abb21..182e05ef 100644 --- a/src/bos/operators/utils/clients/bos/options.py +++ b/src/bos/operators/utils/clients/bos/options.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -50,6 +50,7 @@ def update(self): def _get_options(self): """Retrieves the current options from the BOS api""" session = requests_retry_session() + LOGGER.debug("GET %s", ENDPOINT) try: response = session.get(ENDPOINT) response.raise_for_status() diff --git a/src/bos/operators/utils/clients/bos/sessions_status.py b/src/bos/operators/utils/clients/bos/sessions_status.py index 69245c3e..df09d798 100644 --- a/src/bos/operators/utils/clients/bos/sessions_status.py +++ b/src/bos/operators/utils/clients/bos/sessions_status.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -42,6 +42,7 @@ def get_session_status(self, session_id, tenant): """Get information for a single BOS item""" url = self.base_url + '/' + session_id + '/status' session = requests_retry_session() + LOGGER.debug("GET %s for tenant=%s", url, tenant) response = session.get(url, headers=get_new_tenant_header(tenant)) response.raise_for_status() item = json.loads(response.text) @@ -55,6 +56,7 @@ def post_session_status(self, session_id, tenant): """ session = requests_retry_session() url = self.base_url + '/' + session_id + '/status' + LOGGER.debug("POST %s for tenant=%s", url, tenant) response = session.post(url, headers=get_new_tenant_header(tenant)) response.raise_for_status() items = json.loads(response.text) diff --git a/src/bos/operators/utils/clients/bss.py b/src/bos/operators/utils/clients/bss.py index 264a39a0..0f815e41 100644 --- a/src/bos/operators/utils/clients/bss.py +++ b/src/bos/operators/utils/clients/bss.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2019-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2019-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -71,8 +71,11 @@ def set_bss(node_set, kernel_params, kernel, initrd, session=None): "kernel": kernel, "initrd": initrd} + LOGGER.debug("PUT %s for hosts %s", url, node_set) try: resp = session.put(url, data=json.dumps(payload), verify=False) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", resp.status_code, + resp.reason, resp.text) resp.raise_for_status() return resp except HTTPError as err: diff --git a/src/bos/operators/utils/clients/cfs.py b/src/bos/operators/utils/clients/cfs.py index cd627a18..c6d43122 100644 --- a/src/bos/operators/utils/clients/cfs.py +++ b/src/bos/operators/utils/clients/cfs.py @@ -40,19 +40,27 @@ def get_components(session=None, **kwargs): if not session: session = requests_retry_session() + LOGGER.debug("GET %s with params=%s", COMPONENTS_ENDPOINT, kwargs) response = session.get(COMPONENTS_ENDPOINT, params=kwargs) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) try: response.raise_for_status() except HTTPError as err: LOGGER.error("Failed getting nodes from cfs: %s", err) raise - return response.json() + component_list = response.json() + LOGGER.debug("Returning %d components from CFS", len(component_list)) + return component_list def patch_components(data, session=None): if not session: session = requests_retry_session() + LOGGER.debug("PATCH %s with body=%s", COMPONENTS_ENDPOINT, data) response = session.patch(COMPONENTS_ENDPOINT, json=data) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) try: response.raise_for_status() except HTTPError as err: @@ -61,6 +69,7 @@ def patch_components(data, session=None): def get_components_from_id_list(id_list): + LOGGER.debug("get_components_from_id_list called with %d IDs", len(id_list)) session = requests_retry_session() component_list = [] while id_list: @@ -68,10 +77,14 @@ def get_components_from_id_list(id_list): next_comps = get_components(session=session, ids=','.join(next_batch)) component_list.extend(next_comps) id_list = id_list[GET_BATCH_SIZE:] + LOGGER.debug("get_components_from_id_list returning a total of %d components from CFS", + len(component_list)) return component_list def patch_desired_config(node_ids, desired_config, enabled=False, tags=None, clear_state=False): + LOGGER.debug("patch_desired_config called on %d IDs with desired_config=%s enabled=%s tags=%s" + " clear_state=%s", len(node_ids), desired_config, enabled, tags, clear_state) session = requests_retry_session() data = [] if not tags: @@ -94,6 +107,8 @@ def patch_desired_config(node_ids, desired_config, enabled=False, tags=None, cle def set_cfs(components, enabled, clear_state=False): + LOGGER.debug("set_cfs called on %d components with enabled=%s clear_state=%s", len(components), + enabled, clear_state) configurations = defaultdict(list) for component in components: config_name = component.get('desired_state', {}).get('configuration', '') diff --git a/src/bos/operators/utils/clients/hsm.py b/src/bos/operators/utils/clients/hsm.py index 34cf9489..2b9622a4 100644 --- a/src/bos/operators/utils/clients/hsm.py +++ b/src/bos/operators/utils/clients/hsm.py @@ -55,11 +55,14 @@ def read_all_node_xnames(): """ session = requests_retry_session() endpoint = '%s/State/Components/' % (BASE_ENDPOINT) + LOGGER.debug("GET %s", endpoint) try: response = session.get(endpoint) except ConnectionError as ce: LOGGER.error("Unable to contact HSM service: %s", ce) raise HWStateManagerException(ce) from ce + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) try: response.raise_for_status() except (HTTPError, MaxRetryError) as hpe: @@ -124,7 +127,10 @@ def get_components(node_list, enabled=None) -> dict[str,list[dict]]: payload = {'ComponentIDs': node_list} if enabled is not None: payload['enabled'] = [str(enabled)] + LOGGER.debug("POST %s with body=%s", ENDPOINT, payload) response = session.post(ENDPOINT, json=payload) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) response.raise_for_status() components = json.loads(response.text) except (ConnectionError, MaxRetryError) as e: @@ -217,7 +223,10 @@ def get(self, path, params=None): if self._session is None: self._session = requests_retry_session() try: + LOGGER.debug("HSM Inventory: GET %s with params=%s", url, params) response = self._session.get(url, params=params, verify=VERIFY) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) response.raise_for_status() except HTTPError as err: LOGGER.error("Failed to get '{}': {}".format(url, err)) diff --git a/src/bos/operators/utils/rootfs/cpss3.py b/src/bos/operators/utils/rootfs/cpss3.py index 19855b6a..099f8fa8 100644 --- a/src/bos/operators/utils/rootfs/cpss3.py +++ b/src/bos/operators/utils/rootfs/cpss3.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2022-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2022-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -76,8 +76,11 @@ def check_cpss3(session=None): """ session = session or requests_retry_session() uri = os.path.join(ENDPOINT, 'contents') + LOGGER.debug("GET %s", uri) try: response = session.get(uri) + LOGGER.debug("Response status code=%d, reason=%s, body=%s", response.status_code, + response.reason, response.text) response.raise_for_status() except HTTPError as he: raise ServiceNotReady(he) from he diff --git a/src/bos/server/controllers/v2/base.py b/src/bos/server/controllers/v2/base.py index 3ad5f99f..a66dfbe5 100644 --- a/src/bos/server/controllers/v2/base.py +++ b/src/bos/server/controllers/v2/base.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2022 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2022, 2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -69,10 +69,10 @@ def calc_version(details): def get_v2(): - LOGGER.debug('in get_version') + LOGGER.debug("GET /v2 invoked get_v2") return calc_version(details=True), 200 def get_version_v2(): - LOGGER.debug('in get_version') + LOGGER.debug("GET /v2/version invoked get_version_v2") return calc_version(details=True), 200 diff --git a/src/bos/server/controllers/v2/components.py b/src/bos/server/controllers/v2/components.py index 2995b1ea..56741854 100644 --- a/src/bos/server/controllers/v2/components.py +++ b/src/bos/server/controllers/v2/components.py @@ -46,7 +46,9 @@ def get_v2_components(ids="", enabled=None, session=None, staged_session=None, p Allows filtering using a comma separated list of ids. """ - LOGGER.debug("GET /components invoked get_components") + LOGGER.debug("GET /v2/components invoked get_v2_components with ids=%s enabled=%s session=%s " + "staged_session=%s phase=%s status=%s", ids, enabled, session, staged_session, + phase, status) id_list = [] if ids: try: @@ -56,8 +58,10 @@ def get_v2_components(ids="", enabled=None, session=None, staged_session=None, p status=400, title="Error parsing the ids provided.", detail=str(err)) tenant = get_tenant_from_header() + LOGGER.debug("GET /v2/components for tenant=%s with %d IDs specified", tenant, len(id_list)) response = get_v2_components_data(id_list=id_list, enabled=enabled, session=session, staged_session=staged_session, phase=phase, status=status, tenant=tenant) + LOGGER.debug("GET /v2/components returning data for tenant=%s on %d components", tenant, len(response)) for component in response: del_timestamp(component) return response, 200 @@ -158,7 +162,7 @@ def _matches_filter(data, enabled, session, staged_session, phase, status): @dbutils.redis_error_handler def put_v2_components(): """Used by the PUT /components API operation""" - LOGGER.debug("PUT /components invoked put_components") + LOGGER.debug("PUT /v2/components invoked put_v2_components") if not connexion.request.is_json: msg = "Must be in JSON format" LOGGER.error(msg) @@ -198,7 +202,7 @@ def put_v2_components(): @dbutils.redis_error_handler def patch_v2_components(): """Used by the PATCH /components API operation""" - LOGGER.debug("PATCH /components invoked patch_components") + LOGGER.debug("PATCH /v2/components invoked patch_v2_components") if not connexion.request.is_json: msg = "Must be in JSON format" LOGGER.error(msg) @@ -237,6 +241,7 @@ def patch_v2_components(): def patch_v2_components_list(data): try: + LOGGER.debug("patch_v2_components_list: %d components specified", len(data)) components = [] for component_data in data: component_id = component_data['id'] @@ -274,6 +279,7 @@ def patch_v2_components_dict(data): status=400, title="Error parsing the ids provided.", detail=str(err)) # Make sure all of the components exist and belong to this tenant (if any) + LOGGER.debug("patch_v2_components_dict: %d IDs specified", len(id_list)) for component_id in id_list: if component_id not in DB or not _is_valid_tenant_component(component_id): return connexion.problem( @@ -281,6 +287,7 @@ def patch_v2_components_dict(data): detail="Component {} could not be found".format(component_id)) elif session: id_list = [component["id"] for component in get_v2_components_data(session=session, tenant=get_tenant_from_header())] + LOGGER.debug("patch_v2_components_dict: %d IDs found for specified session", len(id_list)) else: return connexion.problem( status=400, title="Exactly one filter must be provided.", @@ -299,7 +306,7 @@ def patch_v2_components_dict(data): @dbutils.redis_error_handler def get_v2_component(component_id): """Used by the GET /components/{component_id} API operation""" - LOGGER.debug("GET /components/id invoked get_component") + LOGGER.debug("GET /v2/components/%s invoked get_v2_component", component_id) if component_id not in DB or not _is_valid_tenant_component(component_id): return connexion.problem( status=404, title="Component could not found.", @@ -313,7 +320,7 @@ def get_v2_component(component_id): @dbutils.redis_error_handler def put_v2_component(component_id): """Used by the PUT /components/{component_id} API operation""" - LOGGER.debug("PUT /components/id invoked put_component") + LOGGER.debug("PUT /v2/components/%s invoked put_v2_component", component_id) if not connexion.request.is_json: msg = "Must be in JSON format" LOGGER.error(msg) @@ -341,7 +348,7 @@ def put_v2_component(component_id): @dbutils.redis_error_handler def patch_v2_component(component_id): """Used by the PATCH /components/{component_id} API operation""" - LOGGER.debug("PATCH /components/id invoked patch_component") + LOGGER.debug("PATCH /v2/components/%s invoked patch_v2_component", component_id) if not connexion.request.is_json: msg = "Must be in JSON format" LOGGER.error(msg) @@ -398,7 +405,7 @@ def validate_actual_state_change_is_allowed(component_id): @dbutils.redis_error_handler def delete_v2_component(component_id): """Used by the DELETE /components/{component_id} API operation""" - LOGGER.debug("DELETE /components/id invoked delete_component") + LOGGER.debug("DELETE /v2/components/%s invoked delete_v2_component", component_id) if component_id not in DB or not _is_valid_tenant_component(component_id): return connexion.problem( status=404, title="Component could not found.", @@ -410,7 +417,7 @@ def delete_v2_component(component_id): @dbutils.redis_error_handler def post_v2_apply_staged(): """Used by the POST /applystaged API operation""" - LOGGER.debug("POST /applystaged invoked post_v2_apply_staged") + LOGGER.debug("POST /v2/applystaged invoked post_v2_apply_staged") response = {"succeeded": [], "failed": [], "ignored": []} # Obtain latest desired behavior for how to clear staging information # for all components diff --git a/src/bos/server/controllers/v2/healthz.py b/src/bos/server/controllers/v2/healthz.py index e060f233..cdfc5912 100644 --- a/src/bos/server/controllers/v2/healthz.py +++ b/src/bos/server/controllers/v2/healthz.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2022 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2022, 2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -51,6 +51,7 @@ def get_v2_healthz(): :rtype: Healthz """ + LOGGER.debug("GET /v2/healthz invoked get_v2_healthz") return Healthz( db_status=_get_db_status(), api_status='ok', diff --git a/src/bos/server/controllers/v2/options.py b/src/bos/server/controllers/v2/options.py index 60156e04..899c0225 100644 --- a/src/bos/server/controllers/v2/options.py +++ b/src/bos/server/controllers/v2/options.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2022 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2022, 2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -72,7 +72,7 @@ def _init(): @dbutils.redis_error_handler def get_v2_options(): """Used by the GET /options API operation""" - LOGGER.debug("GET /options invoked get_options") + LOGGER.debug("GET /v2/options invoked get_v2_options") data = get_v2_options_data() data = _clean_options_data(data) return data, 200 @@ -112,7 +112,7 @@ def _check_defaults(data): @dbutils.redis_error_handler def patch_v2_options(): """Used by the PATCH /options API operation""" - LOGGER.debug("PATCH /options invoked patch_options") + LOGGER.debug("PATCH /v2/options invoked patch_v2_options") try: data = connexion.request.get_json() except Exception as err: diff --git a/src/bos/server/controllers/v2/sessions.py b/src/bos/server/controllers/v2/sessions.py index 25ccf1eb..daef9c0a 100644 --- a/src/bos/server/controllers/v2/sessions.py +++ b/src/bos/server/controllers/v2/sessions.py @@ -58,6 +58,7 @@ def post_v2_session(): # noqa: E501 :rtype: Session """ + LOGGER.debug("POST /v2/sessions invoked post_v2_session") # -- Validation -- if connexion.request.is_json: LOGGER.debug("connexion.request.is_json") @@ -128,6 +129,7 @@ def patch_v2_session(session_id): Returns: Session Dictionary, Status Code """ + LOGGER.debug("PATCH /v2/sessions/%s invoked patch_v2_session", session_id) if not connexion.request.is_json: msg = "Post must be in JSON format" LOGGER.error(msg) @@ -161,6 +163,7 @@ def get_v2_session(session_id): # noqa: E501 Return: Session Dictionary, Status Code """ + LOGGER.debug("GET /v2/sessions/%s invoked get_v2_session", session_id) session_key = get_tenant_aware_key(session_id, get_tenant_from_header()) if session_key not in DB: return connexion.problem( @@ -176,10 +179,12 @@ def get_v2_sessions(min_age=None, max_age=None, status=None): # noqa: E501 List all sessions """ - LOGGER.info("Called get v2 sessions") + LOGGER.debug("GET /v2/sessions invoked get_v2_sessions with min_age=%s max_age=%s status=%s", + min_age, max_age, status) response = _get_filtered_sessions(tenant=get_tenant_from_header(), min_age=min_age, max_age=max_age, status=status) + LOGGER.debug("get_v2_sessions returning %d sessions", len(response)) return response, 200 @@ -189,6 +194,7 @@ def delete_v2_session(session_id): # noqa: E501 Delete the session by session id """ + LOGGER.debug("DELETE /v2/sessions/%s invoked delete_v2_session", session_id) session_key = get_tenant_aware_key(session_id, get_tenant_from_header()) if session_key not in DB: return connexion.problem( @@ -201,7 +207,8 @@ def delete_v2_session(session_id): # noqa: E501 @dbutils.redis_error_handler def delete_v2_sessions(min_age=None, max_age=None, status=None): # noqa: E501 - LOGGER.info("Called delete v2 sessions") + LOGGER.debug("DELETE /v2/sessions invoked delete_v2_sessions with min_age=%s max_age=%s status=%s", + min_age, max_age, status) tenant = get_tenant_from_header() try: sessions = _get_filtered_sessions(tenant=tenant, min_age=min_age, max_age=max_age, @@ -231,6 +238,7 @@ def get_v2_session_status(session_id): # noqa: E501 Return: Session Status Dictionary, Status Code """ + LOGGER.debug("GET /v2/sessions/status/%s invoked get_v2_session_status", session_id) session_key = get_tenant_aware_key(session_id, get_tenant_from_header()) if session_key not in DB: return connexion.problem( @@ -252,6 +260,7 @@ def save_v2_session_status(session_id): # noqa: E501 Return: Session Status Dictionary, Status Code """ + LOGGER.debug("POST /v2/sessions/status/%s invoked save_v2_session_status", session_id) session_key = get_tenant_aware_key(session_id, get_tenant_from_header()) if session_key not in DB: return connexion.problem( diff --git a/src/bos/server/controllers/v2/sessiontemplates.py b/src/bos/server/controllers/v2/sessiontemplates.py index 69076a82..9b21abe9 100644 --- a/src/bos/server/controllers/v2/sessiontemplates.py +++ b/src/bos/server/controllers/v2/sessiontemplates.py @@ -1,7 +1,7 @@ # # MIT License # -# (C) Copyright 2021-2023 Hewlett Packard Enterprise Development LP +# (C) Copyright 2021-2024 Hewlett Packard Enterprise Development LP # # Permission is hereby granted, free of charge, to any person obtaining a # copy of this software and associated documentation files (the "Software"), @@ -77,11 +77,11 @@ def _sanitize_xnames(st_json): @reject_invalid_tenant @dbutils.redis_error_handler def put_v2_sessiontemplate(session_template_id): # noqa: E501 - """PUT /v2/sessiontemplate + """PUT /v2/sessiontemplates Creates a new session template. # noqa: E501 """ - LOGGER.debug("PUT /v2/sessiontemplate invoked put_sessiontemplate") + LOGGER.debug("PUT /v2/sessiontemplates/%s invoked put_v2_sessiontemplate", session_template_id) if connexion.request.is_json: LOGGER.debug("connexion.request.is_json") LOGGER.debug("type=%s", type(connexion.request.get_json())) @@ -127,19 +127,20 @@ def get_v2_sessiontemplates(): # noqa: E501 List all sessiontemplates """ - LOGGER.debug("get_sessiontemplates: Fetching sessions.") + LOGGER.debug("GET /v2/sessiontemplates invoked get_v2_sessiontemplates") response = _get_filtered_templates(tenant=get_tenant_from_header()) + LOGGER.debug("get_v2_sessiontemplates returning %d templates", len(response)) return response, 200 @dbutils.redis_error_handler def get_v2_sessiontemplate(session_template_id): """ - GET /v2/sessiontemplate + GET /v2/sessiontemplates Get the session template by session template ID """ - LOGGER.debug("get_sessiontemplate by ID: %s", session_template_id) # noqa: E501 + LOGGER.debug("GET /v2/sessiontemplates/%s invoked get_v2_sessiontemplate", session_template_id) template_key = get_tenant_aware_key(session_template_id, get_tenant_from_header()) if template_key not in DB: return connexion.problem( @@ -156,17 +157,18 @@ def get_v2_sessiontemplatetemplate(): Get the example session template """ + LOGGER.debug("GET /v2/sessiontemplatetemplate invoked get_v2_sessiontemplatetemplate") return EXAMPLE_SESSION_TEMPLATE, 200 @dbutils.redis_error_handler def delete_v2_sessiontemplate(session_template_id): """ - DELETE /v2/sessiontemplate + DELETE /v2/sessiontemplates Delete the session template by session template ID """ - LOGGER.debug("delete_sessiontemplate by ID: %s", session_template_id) + LOGGER.debug("DELETE /v2/sessiontemplates/%s invoked delete_v2_sessiontemplate", session_template_id) template_key = get_tenant_aware_key(session_template_id, get_tenant_from_header()) if template_key not in DB: return connexion.problem( @@ -178,11 +180,11 @@ def delete_v2_sessiontemplate(session_template_id): @dbutils.redis_error_handler def patch_v2_sessiontemplate(session_template_id): """ - PATCH /v2/sessiontemplate + PATCH /v2/sessiontemplates Patch the session template by session template ID """ - LOGGER.debug("PATCH /v2/sessiontemplate invoked patch_sessiontemplate with ID: %s", session_template_id) + LOGGER.debug("PATCH /v2/sessiontemplates/%s invoked patch_v2_sessiontemplate", session_template_id) template_key = get_tenant_aware_key(session_template_id, get_tenant_from_header()) if template_key not in DB: return connexion.problem( @@ -231,6 +233,7 @@ def validate_v2_sessiontemplate(session_template_id: str): Validate a V2 session template. Look for missing elements or errors that would prevent a session from being launched using this template. """ + LOGGER.debug("GET /v2/sessiontemplatesvalid/%s invoked validate_v2_sessiontemplate", session_template_id) data, status_code = get_v2_sessiontemplate(session_template_id) if status_code != 200: