Merge pull request #131 from release-engineering/azure-preview-to-live-fix

Azure: fix bug preventing pushing preview offers live

Author: JAVGan

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.info("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)
 
@@ -205,7 +211,7 @@ def products(self) -> Iterator[ProductSummary]:
         params: Dict[str, str] = {}
 
         while has_next:
-            log.debug("Requesting the products list.")
+            log.info("Requesting the products list.")
             resp = self.session.get(path="/product", params=params)
             data = self._assert_dict(resp)
 
@@ -230,6 +236,7 @@ def list_products(self) -> List[ProductSummary]:
         Returns:
             list: A list with ProductSummary for all products in Azure.
         """
+        log.info("Listing the products on Azure server.")
         if not self._products:
             self._products = [p for p in self.products]
         return self._products
@@ -257,7 +264,7 @@ def get_product(self, product_id: str, first_target: str = "preview") -> Product
                 targets.append(tgt)
 
         for t in targets:
-            log.debug("Requesting the product ID \"%s\" with state \"%s\".", product_id, t)
+            log.info("Requesting the product ID \"%s\" with state \"%s\".", product_id, t)
             try:
                 resp = self.session.get(
                     path=f"/resource-tree/product/{product_id}", params={"targetType": t}
@@ -314,6 +321,7 @@ def get_submission_state(self, product_id, state="preview") -> Optional[ProductS
         Returns:
             Optional[ProductSubmission]: The requested submission when found.
         """
+        log.info("Looking up for submission in state \"%s\" for \"%s\"", state, product_id)
         submissions = self.get_submissions(product_id)
         for sub in submissions:
             if sub.target.targetType == state:
@@ -370,15 +378,15 @@ def get_plan_by_name(self, product: Product, plan_name: str) -> PlanSummary:
 
     def get_product_plan_by_name(
         self, product_name: str, plan_name: str
-    ) -> Tuple[Product, PlanSummary]:
+    ) -> Tuple[Product, PlanSummary, str]:
         """Return a tuple with the desired Product and Plan after iterating over all targets.
 
         Args:
             product_name (str): The name of the product to search for
             plan_name (str): The name of the plan to search for
 
         Returns:
-            Tuple[Product, PlanSummary]: The Product and PlanSummary when fonud
+            Tuple[Product, PlanSummary, str]: The Product, PlanSummary and target when fonud
         Raises:
             NotFoundError whenever all targets are exhausted and no information was found
         """
@@ -388,7 +396,7 @@ def get_product_plan_by_name(
             try:
                 product = self.get_product_by_name(product_name, first_target=tgt)
                 plan = self.get_plan_by_name(product, plan_name)
-                return product, plan
+                return product, plan, tgt
             except NotFoundError:
                 continue
         self._raise_error(
@@ -421,6 +429,7 @@ def submit_to_status(self, product_id: str, status: str) -> ConfigureStatus:
         Returns:
             The response from configure request.
         """
+        log.info("Submitting the status of \"%s\" to \"%s\"", product_id, status)
         # We need to get the previous state of the given one to request the submission
         prev_state_mapping = {
             "preview": "draft",
@@ -459,6 +468,7 @@ def ensure_can_publish(self, product_id: str) -> None:
         Raises:
             RuntimeError: whenever a publishing is already in progress.
         """
+        log.info("Ensuring no other publishing jobs are in progress for \"%s\"", product_id)
         submission_targets = ["preview", "live"]
 
         for target in submission_targets:
@@ -539,21 +549,21 @@ def _publish_preview(self, product: Product, product_name: str) -> None:
             List[ProductSubmission],
             self.filter_product_resources(product=product, resource="submission"),
         )[0]
-        if not self._is_submission_in_preview(submission):
-            log.info(
-                "Submitting the product \"%s (%s)\" to \"preview\"." % (product_name, product.id)
+        if self._is_submission_in_preview(submission):
+            log.info("The product \"%s\" is already set to preview", product_name)
+            return
+
+        res = self.submit_to_status(product_id=product.id, status='preview')
+
+        if res.job_result != 'succeeded' or not self.get_submission_state(
+            product.id, state="preview"
+        ):
+            errors = "\n".join(res.errors)
+            failure_msg = (
+                f"Failed to submit the product {product.id} to preview. "
+                f"Status: {res.job_result} Errors: {errors}"
             )
-            res = self.submit_to_status(product_id=product.id, status='preview')
-
-            if res.job_result != 'succeeded' or not self.get_submission_state(
-                product.id, state="preview"
-            ):
-                errors = "\n".join(res.errors)
-                failure_msg = (
-                    f"Failed to submit the product {product.id} to preview. "
-                    f"Status: {res.job_result} Errors: {errors}"
-                )
-                raise RuntimeError(failure_msg)
+            raise RuntimeError(failure_msg)
 
     @retry(
         wait=wait_fixed(wait=60),
@@ -572,7 +582,6 @@ def _publish_live(self, product: Product, product_name: str) -> None:
         """
         # Note: the offer can only go `live` after successfully being changed to `preview`
         # which takes up to 4 days.
-        log.info("Submitting the product \"%s (%s)\" to \"live\"." % (product_name, product.id))
         res = self.submit_to_status(product_id=product.id, status='live')
 
         if res.job_result != 'succeeded' or not self.get_submission_state(product.id, state="live"):
@@ -596,71 +605,111 @@ def publish(self, metadata: AzurePublishingMetadata) -> None:
         #   "product-name/plan-name"
         product_name = metadata.destination.split("/")[0]
         plan_name = metadata.destination.split("/")[-1]
-        product, plan = self.get_product_plan_by_name(product_name, plan_name)
+        product, plan, tgt = self.get_product_plan_by_name(product_name, plan_name)
         log.info(
-            "Preparing to associate the image with the plan \"%s\" from product \"%s\""
-            % (plan_name, product_name)
+            "Preparing to associate the image \"%s\" with the plan \"%s\" from product \"%s\" on \"%s\"",  # noqa: E501
+            metadata.image_path,
+            plan_name,
+            product_name,
+            tgt,
         )
 
         # 2. Retrieve the VM Technical configuration for the given plan
-        log.debug("Retrieving the technical config for \"%s\"." % metadata.destination)
+        log.info("Retrieving the technical config for \"%s\" on \"%s\".", metadata.destination, tgt)
         tech_config = self.get_plan_tech_config(product, plan)
 
         # 3. Prepare the Disk Version
-        log.debug("Creating the VMImageResource with SAS: \"%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=[])
 
         # Note: If `overwrite` is True it means we can set this VM image as the only one in the
         # plan's technical config and discard all other VM images which may've been present.
         disk_version = None  # just to make mypy happy
         if metadata.overwrite is True:
-            log.warning("Overwriting the plan %s with the given image.", plan_name)
+            log.warning(
+                "Overwriting the plan \"%s\" on \"%s\" with the given image: \"%s\".",
+                plan_name,
+                tgt,
+                metadata.image_path,
+            )
             disk_version = create_disk_version_from_scratch(metadata, source)
             tech_config.disk_versions = [disk_version]
 
         # We just want to append a new image if the SAS is not already present.
         elif not is_sas_present(tech_config, metadata.image_path, metadata.check_base_sas_only):
             # Here we can have the metadata.disk_version set or empty.
             # When set we want to get the existing disk_version which matches its value.
-            log.debug("Scanning the disk versions from %s" % metadata.destination)
+            log.info(
+                "Scanning the disk versions from \"%s\" on \"%s\" for the image \"%s\"",
+                metadata.destination,
+                tgt,
+                metadata.image_path,
+            )
             disk_version = seek_disk_version(tech_config, metadata.disk_version)
 
             # Check the images of the selected DiskVersion if it exists
             if disk_version:
-                log.debug(
-                    "DiskVersion \"%s\" exists in \"%s\"."
-                    % (disk_version.version_number, metadata.destination)
+                log.info(
+                    "DiskVersion \"%s\" exists in \"%s\" on \"%s\" for the image \"%s\".",
+                    disk_version.version_number,
+                    metadata.destination,
+                    tgt,
+                    metadata.image_path,
                 )
                 disk_version = set_new_sas_disk_version(disk_version, metadata, source)
 
             else:  # The disk version doesn't exist, we need to create one from scratch
-                log.debug("The DiskVersion doesn't exist, creating one from scratch.")
+                log.info("The DiskVersion doesn't exist, creating one from scratch.")
                 disk_version = create_disk_version_from_scratch(metadata, source)
                 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\" on \"%s\" already contains the SAS URI: \"%s\".",
+                metadata.destination,
+                tgt,
+                metadata.image_path,
             )
 
         # 4. With the updated disk_version we should adjust the SKUs and submit the changes
         if disk_version:
-            log.debug("Updating SKUs for \"%s\"." % metadata.destination)
+            log.info("Updating SKUs for \"%s\" on \"%s\".", metadata.destination, tgt)
             tech_config.skus = update_skus(
                 disk_versions=tech_config.disk_versions,
                 generation=metadata.generation,
                 plan_name=plan_name,
                 old_skus=tech_config.skus,
             )
-            log.debug("Updating the technical configuration for \"%s\"." % metadata.destination)
+            log.info(
+                "Updating the technical configuration for \"%s\" on \"%s\".",
+                metadata.destination,
+                tgt,
+            )
             self.configure(resource=tech_config)
 
         # 5. Proceed to publishing if it was requested.
         # Note: The publishing will only occur if it made changes in disk_version.
-        if disk_version and not metadata.keepdraft:
-            logdiff(self.diff_offer(product))
-            self.ensure_can_publish(product.id)
+        if not metadata.keepdraft:
+            # Get the submission state
+            submission: ProductSubmission = cast(
+                List[ProductSubmission],
+                self.filter_product_resources(product=product, resource="submission"),
+            )[0]
+
+            # We should only publish if there are new changes OR
+            # the existing offer was already in preview
+            if disk_version or self._is_submission_in_preview(submission):
+                log.info(
+                    "Publishing the new changes for \"%s\" on plan \"%s\"", product_name, plan_name
+                )
+                logdiff(self.diff_offer(product))
+                self.ensure_can_publish(product.id)
+
+                self._publish_preview(product, product_name)
+                self._publish_live(product, product_name)
 
-            self._publish_preview(product, product_name)
-            self._publish_live(product, product_name)
+        log.info(
+            "Finished publishing the image \"%s\" to \"%s\"",
+            metadata.image_path,
+            metadata.destination,
+        )

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)
@@ -117,7 +117,7 @@ def _validate_auth_keys(auth_keys: Dict[str, str]) -> Dict[str, str]:
 
     def _login(self) -> AccessToken:
         """Retrieve the authentication token from Microsoft."""
-        log.info("Retrieving the bearer token from Microsoft")
+        log.debug("Retrieving the bearer token from Microsoft")
         url = self.LOGIN_URL_TMPL.format(**self.auth_keys)
 
         headers = {
@@ -156,7 +156,7 @@ def _request(
                 params = {}
             params.update(self._mandatory_params)
 
-        log.info(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)