Refactor installation of maui workload + logging (#4985)

matouskozak · web-flow · commit 44f9c8739bdb · 2025-09-29T10:59:26.000-07:00
diff --git a/src/scenarios/shared/mauisharedpython.py b/src/scenarios/shared/mauisharedpython.py
@@ -96,11 +96,15 @@ def install_versioned_maui(precommands: PreCommands):
 
     precommands.install_workload('maui', workload_install_args)
 
-def extract_latest_dotnet_feed_from_nuget_config(path: str) -> str:
+def extract_latest_dotnet_feed_from_nuget_config(path: str, offset: int = 0) -> str:
     '''
         Extract the latest dotnet feed from the NuGet.config file.
         The latest feed is the one that has the highest version number.
         Supports only single number versioning (dotnet9, dotnet10, etc.)
+        
+        Args:
+            path: Path to the NuGet.config file
+            offset: Offset from the latest version (0 = latest, 1 = second latest, etc.)
     '''
     tree = ET.parse(path)
     root = tree.getroot()
@@ -121,14 +125,19 @@ def extract_latest_dotnet_feed_from_nuget_config(path: str) -> str:
                 version = int(match.group(1))
                 dotnet_feeds[version] = value
 
-    # Find the highest version
+    # Find the requested version based on offset
     if not dotnet_feeds:
         raise ValueError("No dotnet feeds found in NuGet.config")
 
-    latest_version = max(dotnet_feeds.keys())
-    latest_feed = dotnet_feeds[latest_version]
+    sorted_versions = sorted(dotnet_feeds.keys(), reverse=True)
+    
+    if offset >= len(sorted_versions):
+        raise ValueError(f"Offset {offset} is too large. Only {len(sorted_versions)} dotnet feeds available")
+    
+    target_version = sorted_versions[offset]
+    target_feed = dotnet_feeds[target_version]
 
-    return latest_feed
+    return target_feed
 
 def install_latest_maui(
         precommands: PreCommands, 
@@ -139,6 +148,8 @@ def install_latest_maui(
         This function will create a rollback file and install the maui workload using that file.
     '''
 
+    getLogger().info("########## Installing latest MAUI workload ##########")
+
     if precommands.has_workload:
         getLogger().info("Skipping maui installation due to --has-workload=true")
         return
@@ -156,57 +167,106 @@ def install_latest_maui(
 
     # Get the latest published version of the maui workloads
     for workload in maui_rollback_dict.keys():
-        packages = precommands.get_packages_for_sdk_from_feed(workload, feed)
-
+        getLogger().info(f"Processing workload: {workload}")
         try:
-            packages = json.loads(packages)["searchResult"][0]['packages']
-        except json.JSONDecodeError as e:
-            raise Exception(f"Error parsing JSON output: {e}")
+            packages = precommands.get_packages_for_sdk_from_feed(workload, feed)
+        except Exception as e:
+            getLogger().warning(f"Failed to get packages for {workload} from latest feed: {e}")
+            getLogger().info("Trying second latest feed as fallback")
+            fallback_feed = extract_latest_dotnet_feed_from_nuget_config(
+                path=os.path.join(get_repo_root_path(), "NuGet.config"), 
+                offset=1
+            )
+            getLogger().info(f"Using fallback feed: {fallback_feed}")
+            packages = precommands.get_packages_for_sdk_from_feed(workload, fallback_feed)
+
+        # Log all package IDs before filtering
+        getLogger().debug(f"All package IDs for {workload}: {[pkg['id'] for pkg in packages]}")
 
         # Filter out packages that have ID that matches the pattern 'Microsoft.NET.Sdk.<workload>.Manifest-<version>'
-        packages = [pkg for pkg in packages if re.match(r'Microsoft\.NET\.Sdk\..*\.Manifest\-\d+\.\d+\.\d+(\-(preview|rc|alpha)\.\d+)?$', pkg['id'])]
+        pattern = r'Microsoft\.NET\.Sdk\..*\.Manifest\-\d+\.\d+\.\d+(\-(preview|rc|alpha)\.\d+)?$'
+        packages = [pkg for pkg in packages if re.match(pattern, pkg['id'])]
+        getLogger().info(f"After manifest pattern filtering, found {len(packages)} packages for {workload}")
+        getLogger().debug(f"Filtered package IDs for {workload}: {[pkg['id'] for pkg in packages]}")
 
         # Extract the .NET version from the package ID (Manifest-<version>($|-<preview|rc|alpha>.*))
         for package in packages:
+            getLogger().debug(f"Processing package ID: {package['id']}")
             match = re.search(r'Manifest-(.+)$', package["id"])
             if match:
                 sdk_version = match.group(1)
                 package['sdk_version'] = sdk_version
+                getLogger().debug(f"Extracted SDK version '{sdk_version}' from package {package['id']}")
 
                 # Extract the .NET version from sdk_version (first integer)
                 match = re.search(r'^\d+\.\d+', sdk_version)
                 if match:
                     dotnet_version = match.group(0)
                     package['dotnet_version'] = dotnet_version
+                    getLogger().debug(f"Extracted .NET version '{dotnet_version}' from SDK version '{sdk_version}'")
                 else:
+                    getLogger().error(f"Unable to find .NET version in SDK version '{sdk_version}' for package {package['id']}")
                     raise Exception("Unable to find .NET version in SDK version")
             else:
+                getLogger().error(f"Unable to find .NET SDK version in package ID: {package['id']}")
                 raise Exception("Unable to find .NET SDK version in package ID")
             
         # Filter out packages that have lower 'dotnet_version' than the rest of the packages
         # Sometimes feed can contain packages from previous release versions, so we need to filter them out
-        highest_dotnet_version = max(float(pkg['dotnet_version']) for pkg in packages)
+        dotnet_versions = [float(pkg['dotnet_version']) for pkg in packages]
+        getLogger().debug(f"Found .NET versions for {workload}: {dotnet_versions}")
+        highest_dotnet_version = max(dotnet_versions)
+        getLogger().info(f"Highest .NET version for {workload}: {highest_dotnet_version}")
+        packages_before_version_filter = len(packages)
         packages = [pkg for pkg in packages if float(pkg['dotnet_version']) == highest_dotnet_version]
+        getLogger().info(f"After .NET version filtering for {workload}: {len(packages)} packages (was {packages_before_version_filter})")
+        
+        pkg_details = [f"{pkg['id']} (v{pkg['dotnet_version']})" for pkg in packages]
+        getLogger().debug(f"Packages after .NET version filter: {pkg_details}")
 
         # Check if we have non-preview packages available and use them
-        non_preview_packages = [pkg for pkg in packages if not re.search(r'\-(preview|rc|alpha)\.\d+$', pkg['id'])]
+        preview_pattern = r'\-(preview|rc|alpha)\.\d+$'
+        non_preview_packages = [pkg for pkg in packages if not re.search(preview_pattern, pkg['id'])]
+        getLogger().info(f"Found {len(non_preview_packages)} non-preview packages for {workload} out of {len(packages)} total")
+        
+        preview_packages = [pkg['id'] for pkg in packages if re.search(preview_pattern, pkg['id'])]
+        getLogger().debug(f"Preview packages: {preview_packages}")
+        getLogger().debug(f"Non-preview packages: {[pkg['id'] for pkg in non_preview_packages]}")
+        
         if non_preview_packages:
+            getLogger().info(f"Using non-preview packages for {workload}")
             packages = non_preview_packages
+        else:
+            getLogger().info(f"No non-preview packages available for {workload}, using all packages")
 
         # Sort the packages by 'sdk_version'
+        before_sort = [f"{pkg['id']} (sdk_v{pkg['sdk_version']})" for pkg in packages]
+        newline = '\n'
+        getLogger().debug(f"Packages before sorting for {workload}: {newline.join(before_sort)}")
         packages.sort(key=lambda x: x['sdk_version'], reverse=True)
+        after_sort = [f"{pkg['id']} (sdk_v{pkg['sdk_version']})" for pkg in packages]
+        getLogger().debug(f"Packages after sorting for {workload}: {newline.join(after_sort)}")
 
         # Get the latest package
+        if not packages:
+            getLogger().error(f"No packages available for {workload} after filtering")
+            raise Exception(f"No packages available for {workload} after filtering")
+            
         latest_package = packages[0]
 
-        getLogger().info(f"Latest package for {workload} found: {latest_package['id']} {latest_package['latestVersion']}")
+        getLogger().info(f"Latest package details for {workload}: ID={latest_package['id']}, Version={latest_package['latestVersion']}, SDK_Version={latest_package['sdk_version']}, .NET_Version={latest_package['dotnet_version']}")
         
-        maui_rollback_dict[workload] = f"{latest_package['latestVersion']}/{latest_package['sdk_version']}"
+        rollback_value = f"{latest_package['latestVersion']}/{latest_package['sdk_version']}"
+        maui_rollback_dict[workload] = rollback_value
+        getLogger().info(f"Set rollback for {workload}: {rollback_value}")
 
     # Create the rollback file
+    getLogger().info(f"Final rollback dictionary: {maui_rollback_dict}")
     with open("rollback_maui.json", "w", encoding="utf-8") as f:
         f.write(json.dumps(maui_rollback_dict, indent=4))
+    getLogger().info("Created rollback_maui.json file")
 
     # Install the workload using the rollback file
     getLogger().info("Installing maui workload with rollback file")
     precommands.install_workload('maui', ['--from-rollback-file', 'rollback_maui.json'])
+    getLogger().info("########## Finished installing latest MAUI workload ##########")
diff --git a/src/scenarios/shared/precommands.py b/src/scenarios/shared/precommands.py
@@ -6,6 +6,7 @@
 import os
 import shutil
 import subprocess
+import json
 from logging import getLogger
 from argparse import ArgumentParser
 from typing import List, Optional
@@ -276,7 +277,12 @@ def install_workload(self, workloadid: str, install_args: List[str] = ["--skip-m
         if not self.has_workload:
             if self.readonly_dotnet:
                 raise Exception('workload needed to build, but has_workload=false, and readonly_dotnet=true')
-            subprocess.run(["dotnet", "workload", "install", workloadid] + install_args, check=True)
+            try:
+                subprocess.run(["dotnet", "workload", "install", workloadid] + install_args, check=True)
+                getLogger().info(f"Successfully installed workload {workloadid}")
+            except Exception as e:
+                getLogger().error(f"Error installing workload {workloadid}: {e}")
+                raise
 
     def uninstall_workload(self, workloadid: str):
         'Uninstalls the workload, if possible'
@@ -299,7 +305,7 @@ def print_dotnet_info(self):
 
 
     def get_packages_for_sdk_from_feed(self, sdk_name: str, feed: str):
-        'Gets the packages for the given sdk from the given feed'
+        'Gets the packages for the given sdk from the given feed and returns parsed package list'
 
         getLogger().debug(f"dotnet package search {sdk_name} --prerelease --take 999 --format json --source {feed}")
 
@@ -308,9 +314,32 @@ def get_packages_for_sdk_from_feed(self, sdk_name: str, feed: str):
             ["dotnet", "package", "search", sdk_name, "--prerelease", "--take", "999", "--format", "json", "--source", feed], check=True, capture_output=True, text=True)
         
         if result.returncode != 0:
+            getLogger().error(f"Package search command failed: {result.stderr}")
             raise Exception(f"Error querying package feed: {result.stderr}")
         
-        return result.stdout
+        getLogger().debug(f"Raw packages response for {sdk_name}: {result.stdout}")
+        
+        try:
+            parsed_response = json.loads(result.stdout)
+            getLogger().debug(f"Parsed JSON response for {sdk_name}: {parsed_response}")
+            
+            if not parsed_response.get("searchResult") or len(parsed_response["searchResult"]) == 0:
+                getLogger().error(f"No search results found for {sdk_name} in feed {feed}")
+                raise Exception(f"No search results found for {sdk_name} in feed {feed}")
+                
+            packages = parsed_response["searchResult"][0].get('packages', [])
+            getLogger().info(f"Found {len(packages)} total packages for {sdk_name}")
+            
+            if not packages:
+                getLogger().error(f"No packages found for SDK {sdk_name} in feed {feed}")
+                raise Exception(f"No packages found for SDK {sdk_name} in feed {feed}")
+                
+            return packages
+            
+        except json.JSONDecodeError as e:
+            getLogger().error(f"Failed to parse JSON response for {sdk_name}: {e}")
+            getLogger().debug(f"Raw response that failed to parse: {result.stdout}")
+            raise Exception(f"Error parsing JSON output for {sdk_name}: {e}")
 
     def _addstaticmsbuildproperty(self, projectfile: str):
         'Insert static msbuild property in the specified project file'
