Azure: more improvements on logs

JAVGan · JAVGan · commit 8b856cb73f7e · 2025-09-02T09:36:35.000-03:00
- Use lazy mode for matting with logger
- Use a standard for logging messages
- Performance improvements on some DEBUG logs

Refers to SPSTRAT-583

Signed-off-by: Jonathan Gangi &lt;jgangi@redhat.com&gt;
diff --git a/cloudpub/ms_azure/service.py b/cloudpub/ms_azure/service.py
@@ -103,7 +103,10 @@ def _configure(self, data: Dict[str, Any]) -> ConfigureStatus:
         Returns:
             The job ID to track its status alongside the initial status.
         """
-        log.debug("Received the following data to create/modify: %s" % json.dumps(data, indent=2))
+        if log.isEnabledFor(logging.DEBUG):
+            log.debug(
+                "Received the following data to create/modify: %s", json.dumps(data, indent=2)
+            )
         resp = self.session.post(path="configure", json=data)
         self._raise_for_status(response=resp)
         rsp_data = resp.json()
@@ -121,17 +124,19 @@ def _query_job_details(self, job_id: str) -> ConfigureStatus:
         Returns:
             The updated job status.
         """
-        log.debug(f"Query job details for \"{job_id}\"")
+        log.debug("Query job details for \"%s\"", job_id)
         resp = self.session.get(path=f"configure/{job_id}/status")
 
         # We don't want to fail if there's a server error thus we make a fake
         # response for it so the query job details will be retried.
         if resp.status_code >= 500:
             log.warning(
                 (
-                    f"Got HTTP {resp.status_code} from server when querying job {job_id} status."
-                    " Considering the job_status as \"pending\"."
-                )
+                    "Got HTTP %s from server when querying job %s status."
+                    " Considering the job_status as \"pending\".",
+                ),
+                resp.status_code,
+                job_id,
             )
             return ConfigureStatus.from_json(
                 {
@@ -177,7 +182,7 @@ def _wait_for_job_completion(self, job_id: str) -> ConfigureStatus:
             error_message = f"Job {job_id} failed: \n{job_details.errors}"
             self._raise_error(InvalidStateError, error_message)
         elif job_details.job_result == "succeeded":
-            log.debug(f"Job {job_id} succeeded")
+            log.debug("Job %s succeeded", job_id)
         return job_details
 
     def configure(self, resource: AzureResource) -> ConfigureStatus:
@@ -194,7 +199,8 @@ def configure(self, resource: AzureResource) -> ConfigureStatus:
             "$schema": self.CONFIGURE_SCHEMA.format(AZURE_API_VERSION=self.AZURE_API_VERSION),
             "resources": [resource.to_json()],
         }
-        log.debug("Data to configure: %s", json.dumps(data, indent=2))
+        if log.isEnabledFor(logging.DEBUG):
+            log.debug("Data to configure: %s", json.dumps(data, indent=2))
         res = self._configure(data=data)
         return self._wait_for_job_completion(job_id=res.job_id)
 
@@ -601,16 +607,18 @@ def publish(self, metadata: AzurePublishingMetadata) -> None:
         plan_name = metadata.destination.split("/")[-1]
         product, plan = self.get_product_plan_by_name(product_name, plan_name)
         log.info(
-            "Preparing to associate the image \"%s\" with the plan \"%s\" from product \"%s\""
-            % (metadata.image_path, plan_name, product_name)
+            "Preparing to associate the image \"%s\" with the plan \"%s\" from product \"%s\"",
+            metadata.image_path,
+            plan_name,
+            product_name,
         )
 
         # 2. Retrieve the VM Technical configuration for the given plan
-        log.info("Retrieving the technical config for \"%s\"." % metadata.destination)
+        log.info("Retrieving the technical config for \"%s\".", metadata.destination)
         tech_config = self.get_plan_tech_config(product, plan)
 
         # 3. Prepare the Disk Version
-        log.info("Creating the VMImageResource with SAS for image: \"%s\"" % metadata.image_path)
+        log.info("Creating the VMImageResource with SAS for image: \"%s\"", metadata.image_path)
         sas = OSDiskURI(uri=metadata.image_path)
         source = VMImageSource(source_type="sasUri", os_disk=sas.to_json(), data_disks=[])
 
@@ -640,8 +648,10 @@ def publish(self, metadata: AzurePublishingMetadata) -> None:
             # Check the images of the selected DiskVersion if it exists
             if disk_version:
                 log.info(
-                    "DiskVersion \"%s\" exists in \"%s\" for the image \"%s\"."
-                    % (disk_version.version_number, metadata.destination, metadata.image_path)
+                    "DiskVersion \"%s\" exists in \"%s\" for the image \"%s\".",
+                    disk_version.version_number,
+                    metadata.destination,
+                    metadata.image_path,
                 )
                 disk_version = set_new_sas_disk_version(disk_version, metadata, source)
 
@@ -651,20 +661,21 @@ def publish(self, metadata: AzurePublishingMetadata) -> None:
                 tech_config.disk_versions.append(disk_version)
         else:
             log.info(
-                "The destination \"%s\" already contains the SAS URI: \"%s\"."
-                % (metadata.destination, metadata.image_path)
+                "The destination \"%s\" already contains the SAS URI: \"%s\".",
+                metadata.destination,
+                metadata.image_path,
             )
 
         # 4. With the updated disk_version we should adjust the SKUs and submit the changes
         if disk_version:
-            log.info("Updating SKUs for \"%s\"." % metadata.destination)
+            log.info("Updating SKUs for \"%s\".", metadata.destination)
             tech_config.skus = update_skus(
                 disk_versions=tech_config.disk_versions,
                 generation=metadata.generation,
                 plan_name=plan_name,
                 old_skus=tech_config.skus,
             )
-            log.info("Updating the technical configuration for \"%s\"." % metadata.destination)
+            log.info("Updating the technical configuration for \"%s\".", metadata.destination)
             self.configure(resource=tech_config)
 
         # 5. Proceed to publishing if it was requested.
diff --git a/cloudpub/ms_azure/session.py b/cloudpub/ms_azure/session.py
@@ -24,7 +24,7 @@ def __init__(self, json: Dict[str, str]):
         """
         self.expires_on = datetime.fromtimestamp(int(json["expires_on"]))
         self.access_token = json["access_token"]
-        log.debug(f"Obtained token with expiration date on {self.expires_on}")
+        log.debug("Obtained token with expiration date on %s", self.expires_on)
 
     def is_expired(self) -> bool:
         """Return True if the token is expired and False otherwise."""
@@ -108,7 +108,7 @@ def _validate_auth_keys(auth_keys: Dict[str, str]) -> Dict[str, str]:
             "AZURE_API_SECRET",
         ]
         for key in mandatory_keys:
-            log.debug(f"Validating mandatory key \"{key}\"")
+            log.debug("Validating mandatory key \"%s\"", key)
             if key not in auth_keys.keys() or not auth_keys.get(key):
                 err_msg = f'The key/value for "{key}" must be set.'
                 log.error(err_msg)
@@ -156,7 +156,7 @@ def _request(
                 params = {}
             params.update(self._mandatory_params)
 
-        log.debug(f"Sending a {method} request to {path}")
+        log.debug("Sending a %s request to %s", method, path)
         formatted_url = self._prefix_url.format(**self.auth_keys)
         url = join_url(formatted_url, path)
         return self.session.request(method, url=url, params=params, headers=headers, **kwargs)
diff --git a/cloudpub/ms_azure/utils.py b/cloudpub/ms_azure/utils.py
@@ -150,22 +150,23 @@ def is_sas_eq(sas1: str, sas2: str, base_only=False) -> bool:
 
     # Base URL differs
     if base_sas1 != base_sas2:
-        log.debug("Got different base SAS: %s - Expected: %s" % (base_sas1, base_sas2))
+        log.debug("Got different base SAS: %s - Expected: %s", base_sas1, base_sas2)
         return False
 
     if not base_only:
         # Parameters lengh differs
         if len(params_sas1) != len(params_sas2):
             log.debug(
-                "Got different lengh of SAS parameters: len(%s) - Expected len(%s)"
-                % (params_sas1, params_sas2)
+                "Got different lengh of SAS parameters: len(%s) - Expected len(%s)",
+                params_sas1,
+                params_sas2,
             )
             return False
 
         # Parameters values differs
         for k, v in params_sas1.items():
             if v != params_sas2.get(k, None):
-                log.debug("The SAS parameter %s doesn't match %s." % (v, params_sas2.get(k, None)))
+                log.debug("The SAS parameter %s doesn't match %s.", v, params_sas2.get(k, None))
                 return False
 
     # Equivalent SAS
@@ -203,8 +204,8 @@ def is_azure_job_not_complete(job_details: ConfigureStatus) -> bool:
     Returns:
         bool: False if job completed, True otherwise
     """
-    log.debug(f"Checking if the job \"{job_details.job_id}\" is still running")
-    log.debug(f"job {job_details.job_id} is in {job_details.job_status} state")
+    log.debug("Checking if the job \"%s\" is still running", job_details.job_id)
+    log.debug("job %s is in %s state", job_details.job_id, job_details.job_status)
     if job_details.job_status != "completed":
         return True
     return False
@@ -559,14 +560,15 @@ def set_new_sas_disk_version(
     log.info("Setting up a new SAS disk version for \"%s\"", metadata.image_path)
     # If we already have a VMImageDefinition let's use it
     if disk_version.vm_images:
-        log.debug("The DiskVersion \"%s\" contains inner images." % disk_version.version_number)
+        log.debug("The DiskVersion \"%s\" contains inner images.", disk_version.version_number)
         img, img_legacy = vm_images_by_generation(disk_version, metadata.architecture)
 
         # Now we replace the SAS URI for the vm_images
         log.info(
             "Adjusting the VMImages from existing DiskVersion \"%s\""
-            "to fit the new image with SAS \"%s\"."
-            % (disk_version.version_number, metadata.image_path)
+            "to fit the new image with SAS \"%s\".",
+            disk_version.version_number,
+            metadata.image_path,
         )
         disk_version.vm_images = prepare_vm_images(
             metadata=metadata,
@@ -578,11 +580,12 @@ def set_new_sas_disk_version(
     # If no VMImages, we need to create them from scratch
     else:
         log.debug(
-            "The DiskVersion \"%s\" does not contain inner images." % disk_version.version_number
+            "The DiskVersion \"%s\" does not contain inner images.", disk_version.version_number
         )
         log.info(
-            "Setting the new image \"%s\" on DiskVersion \"%s\"."
-            % (metadata.image_path, disk_version.version_number)
+            "Setting the new image \"%s\" on DiskVersion \"%s\".",
+            metadata.image_path,
+            disk_version.version_number,
         )
         disk_version.vm_images = create_vm_image_definitions(metadata, source)
 
@@ -592,4 +595,4 @@ def set_new_sas_disk_version(
 def logdiff(diff: DeepDiff) -> None:
     """Log the offer diff if it exists."""
     if diff:
-        log.warning(f"Found the following offer diff before publishing:\n{diff.pretty()}")
+        log.warning("Found the following offer diff before publishing:\n%s", diff.pretty())
