CASMCMS-8949: Improve BOS v2 debug logging

(cherry picked from commit 2e375e6)

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

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

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)
 
 

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)
 
 

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

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,14 +169,16 @@ 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)
         return items
 
     @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:

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()

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)

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:

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,17 +69,22 @@ 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:
         next_batch = id_list[:GET_BATCH_SIZE]
         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', '')