Add post-migration script logging for Windows

internal/worker/scripts/first-boot.ps1

@@ -1,5 +1,7 @@
 $ErrorActionPreference = 'Stop'
 
+set-content -path "C:\AppData\migration-manager\first-boot.log" -value "Beginning post-migration first-boot service"
+
 # Delete the service so it doesn't run again.
 reg delete "hklm\system\currentcontrolset\services\migrationmanagerfirstboot" /f
 
@@ -9,19 +11,26 @@ remove-item "C:\migration-manager-first-boot.ps1"
 # Run the Incus agent if present.
 foreach ($drive in get-psdrive -psprovider filesystem) {
   if (test-path "$($drive.Root)\incus-agent") {
-    start-process powershell.exe -argumentlist "-file `"$($drive.Root)\install.ps1`"" -wait
+    add-content -path "C:\AppData\migration-manager\first-boot.log" -value "Installing Incus Agent"
+    $cmd = '-command "& ''{0}\install.ps1'' *> ''C:\AppData\migration-manager\incus-agent.log''"' -f "$($drive.Root)"
+    start-process powershell.exe -argumentlist $cmd -wait
     break
   }
 }
 
 # Bring disks that had a drive letter online.
 if (test-path "C:\migration-manager-virtio-assign-diskcfg.ps1") {
-  start-process powershell.exe -argumentlist "-file `"C:\migration-manager-virtio-assign-diskcfg.ps1`"" -wait
+  add-content -path "C:\AppData\migration-manager\first-boot.log" -value "Reassigning drive letters"
+
+  $cmd = '-command "& ''C:\migration-manager-virtio-assign-diskcfg.ps1'' *> ''C:\AppData\migration-manager\disk-assign.log''"'
+  start-process powershell.exe -argumentlist $cmd -wait
 }
 
 # Run network config reassignment if present.
 if (test-path "C:\migration-manager-virtio-assign-netcfg.ps1") {
-  $cmd = '-command "& ''C:\migration-manager-virtio-assign-netcfg.ps1'' *> ''C:\migration-manager-net.log''"'
+  add-content -path "C:\AppData\migration-manager\first-boot.log" -value "Reassigning network configs"
+
+  $cmd = '-command "& ''C:\migration-manager-virtio-assign-netcfg.ps1'' *> ''C:\AppData\migration-manager\net-assign.log''"'
   start-process powershell.exe -argumentlist $cmd -wait
 }
 

internal/worker/scripts/hivex-assign-netcfg.sh

@@ -7,8 +7,11 @@ hive_dir="${mount_dir}/Windows/System32/config/SYSTEM"
 old_guid_file="${mount_dir}/migration_manager_old_guids"
 nics_file="${mount_dir}/migration_manager_nics"
 
+echo "Setting up first-boot network reassignment script"
+
 # Just exit if no MACs provided.
 if [ 0 = ${#} ]; then
+  echo "No MACs supplied, exiting"
   exit 0
 fi
 
@@ -21,6 +24,8 @@ fi
 
 control_set="$(printf "ControlSet%03d" "${control_set_num}")"
 
+echo "Using control set ${control_set}"
+
 # Record each mapping of MAC to InstanceGUID because we can't tell which NIC is which after booting. (And also reading networksetup2 requires elevated privileges).
 # shellcheck disable=1003
 hivexregedit --export --prefix 'hklm\system' "${hive_dir}" "${control_set}\control\networksetup2\interfaces" --max-depth 3 \
@@ -32,18 +37,22 @@ hivexregedit --export --prefix 'hklm\system' "${hive_dir}" "${control_set}\contr
 
 # If we can't find any MACs, then exit.
 if [ "$(wc -l /tmp/macs_to_guids)" = 0 ]; then
+  echo "No GUID records found, exiting"
   exit 0
 fi
 
 # Remove the state files in case they exist.
 rm -rf "${old_guid_file}" "${nics_file}"
 
 for mac in "${@}" ; do
+  echo "  Checking mac ${mac}"
+
   # Grab the previous GUID for this MAC.
   mac="$(printf "%s" "${mac}" | tr '[:upper:]' '[:lower:]')"
   mapping="$(grep "^${mac}" -B1 --no-group-separator /tmp/macs_to_guids | head -2)"
 
   if [ -z "${mapping}" ] ; then
+    echo "  Mac ${mac} not found in GUID mappings"
     continue
   fi
 
@@ -52,9 +61,12 @@ for mac in "${@}" ; do
   mac="$(printf "%s" "${mac}" | tr '[:lower:]' '[:upper:]' | sed -e 's/:/-/g')"
 
   if [ -z "${old_guid}" ] || [ -z "${mac}" ]; then
+    echo "  Unexpected GUID mapping format: ${mapping}"
     exit 1
   fi
 
+  echo "  MAC: ${mac} GUID: ${old_guid}"
+
   echo "${old_guid}" >> "${old_guid_file}"
   echo "${mac}" >> "${nics_file}"
 done

internal/worker/scripts/hivex-cpu-hotplug-compat.sh

@@ -2,6 +2,8 @@
 
 set -e
 
+echo "Running Windows CPU-hotplug compatibility patches"
+
 mount_dir="/run/mount/win_main"
 hive_dir="${mount_dir}/Windows/System32/config"
 
@@ -13,14 +15,20 @@ remove_key="$(hivexregedit --export --prefix 'hklm\system' "${hive_dir}/SYSTEM"
 # Only perform the ACPI removal if the key is found.
 # See: https://forum.proxmox.com/threads/windows-2016-cpu-hot-plug-support.42302/
 if [ -n "${remove_key}" ]; then
+  echo "Removing invalid ACPI hidinterrupt.inf entry"
   cat << EOF | hivexregedit --merge --prefix 'HKLM\SYSTEM' "${hive_dir}/SYSTEM"
 [-DriverDatabase\DeviceIds\ACPI\ACPI0010]
 
 ${remove_key}
 
 EOF
+else
+  echo "Invalid ACPI hidinterrupt.inf entry not found, assuming Windows is patched"
 fi
 
+
+echo "Disabling VBS auto-start"
+
 # Disable Virtualization Based Security.
 cat << EOF | hivexregedit --merge --prefix 'HKLM\SYSTEM' "${hive_dir}/SYSTEM"
 [ControlSet001\Control]

internal/worker/scripts/hivex-disable-vm-tools.sh

@@ -5,6 +5,8 @@ set -e
 mount_dir="/run/mount/win_main"
 hive_dir="${mount_dir}/Windows/System32/config"
 
+echo "Cleaning up VMware tools"
+
 # No VMware tools, nothing to do.
 if ! test -e "${mount_dir}/Program Files/VMware/VMware Tools" ; then
   echo "VMware tools were not found"
@@ -327,3 +329,5 @@ rm -rf "${mount_dir}/ProgramData/VMware/VMware Tools"
 rm -rf "${mount_dir}/ProgramData/VMware/VMware VGAuth"
 rm -rf "${mount_dir}/Program Files/Common Files/VMware/Drivers"
 rm -rf "${mount_dir}/Program Files/Common Files/VMware/InstallerCache"
+
+echo "VMware Tools successfully cleaned up"

internal/worker/scripts/hivex-first-boot.sh

@@ -5,6 +5,8 @@ set -e
 mount_dir="/run/mount/win_main"
 hive_dir="${mount_dir}/Windows/System32/config/SYSTEM"
 
+echo "Setting up first-boot service"
+
 # Get the current control set before it's loaded.
 control_set_num="$(hivexregedit --export --prefix='HKEY_LOCAL_MACHINE\SYSTEM' "${hive_dir}" 'Select' | grep -io '^"Current"=dword:[0-9a-f]*' | cut -d':' -f2 | sed -e 's/^0*//')"
 
@@ -14,6 +16,8 @@ fi
 
 control_set="$(printf "ControlSet%03d" "${control_set_num}")"
 
+echo "Using control set ${control_set}"
+
 # Create a service that runs before any user boots. For some reason, we can't run powershell.exe directly here, it has to be called from cmd.exe.
 cat << EOF | hivexregedit --merge --prefix 'HKEY_LOCAL_MACHINE\SYSTEM' "${hive_dir}"
 [${control_set}\Services\MigrationManagerFirstBoot]

internal/worker/scripts/virtio-assign-diskcfg.ps1

@@ -1,5 +1,7 @@
 $ErrorActionPreference = 'Stop'
 
+write-output "Starting Drive letter reassignment"
+
 # Delete the script file before continuing any further.
 remove-item "C:\migration-manager-virtio-assign-diskcfg.ps1"
 
@@ -12,17 +14,22 @@ remove-item "C:\migration_manager_disk_ids"
 $disks = @()
 $ids | foreach-object {
   $id = $_
+
+  write-output ("  Checking ID {0}" -f $id)
   if ($id -match '^{') {
     # GPT
     $part = get-partition | where-object { $_.guid -eq $id }
     $disk = get-disk -number $part.disknumber
     $disks += $disk
+
+    write-output ("  Matching GPT Disk: {0} Part: {1}" -f $disk.number, $part.disknumber)
   } else {
     # MBR
     $disk = get-disk | where-object { $_.signature -eq $id }
     $disks += $disk
-  }
 
+    write-output ("  Matching MBR Disk: {0}" -f $disk.number)
+  }
 }
 
 # Bring online each disk that had a drive letter assigned in the previous boot.

internal/worker/util.go

@@ -1,10 +1,13 @@
 package worker
 
 import (
+	"bytes"
 	"context"
 	"fmt"
+	"io"
 	"log/slog"
 	"os"
+	"os/exec"
 	"path/filepath"
 	"slices"
 	"strings"
@@ -341,14 +344,27 @@ func injectScript(scriptName string, finalPath string, run bool, args ...string)
 	}
 
 	if run {
-		cmd := make([]string, 0, len(args)+1)
-		cmd = append(cmd, finalPath)
-		cmd = append(cmd, args...)
+		cmdArgs := make([]string, 0, len(args)+1)
+		cmdArgs = append(cmdArgs, finalPath)
+		cmdArgs = append(cmdArgs, args...)
 
-		slog.Debug("Running script", slog.String("script", scriptName), slog.Any("args", cmd))
-		_, err = subprocess.RunCommand("/bin/sh", cmd...)
+		slog.Debug("Running script", slog.String("script", scriptName), slog.Any("args", cmdArgs))
+
+		logFile, _ := strings.CutSuffix(scriptName, ".sh")
+		cmd := exec.CommandContext(context.TODO(), "/bin/sh", cmdArgs...)
+		f, err := os.Create(filepath.Join("/tmp", logDir, logFile+".log"))
+		if err != nil {
+			return err
+		}
+
+		defer f.Close()
+
+		var stdout, stderr bytes.Buffer
+		cmd.Stdout = io.MultiWriter(f, &stdout)
+		cmd.Stderr = io.MultiWriter(f, &stderr)
+		err = cmd.Run()
 		if err != nil {
-			return fmt.Errorf("Failed to run %q: %w", scriptName, err)
+			return fmt.Errorf("Failed to run %q: %w", scriptName, subprocess.NewRunError("/bin/sh", cmdArgs, err, &stdout, &stderr))
 		}
 	}
 

internal/worker/windows.go

@@ -171,6 +171,17 @@ func WindowsOpenBitLockerPartition(partition string, encryptionKey string) error
 
 func WindowsInjectDrivers(ctx context.Context, distroVersion string, osArchitecture, isoFile string, dryRun bool) error {
 	slog.Info("Preparing to inject Windows drivers into VM")
+	// Clear any existing logs from a previousr run.
+	err := os.RemoveAll(filepath.Join("/tmp", logDir))
+	if err != nil {
+		return err
+	}
+
+	err = os.MkdirAll(filepath.Join("/tmp", logDir), 0o755)
+	if err != nil {
+		return err
+	}
+
 	versionCode, err := internalUtil.MapWindowsVersionToAbbrev(distroVersion)
 	if err != nil {
 		return err
@@ -414,6 +425,15 @@ func WindowsInjectDrivers(ctx context.Context, distroVersion string, osArchitect
 		}
 	}
 
+	if !dryRun {
+		srcDir := filepath.Join("/tmp", logDir)
+		tgtDir := filepath.Join(windowsMainMountPath, "AppData", logDir)
+		err = internalUtil.DirCopy(srcDir, tgtDir)
+		if err != nil {
+			return err
+		}
+	}
+
 	slog.Info("Successfully injected drivers!")
 	return nil
 }