From 53c87b214981962a0edf4b2a098e11040109dce7 Mon Sep 17 00:00:00 2001 From: xdkaine <55013938+xdkaine@users.noreply.github.com> Date: Mon, 23 Feb 2026 15:49:18 -0800 Subject: [PATCH 1/4] added kayhon auditing logs --- internal/cloning/cloning_service.go | 121 ++++++++++++++++++++++++---- internal/proxmox/networking.go | 58 ++++++++++--- internal/proxmox/vms.go | 43 ++++++++-- 3 files changed, 189 insertions(+), 33 deletions(-) diff --git a/internal/cloning/cloning_service.go b/internal/cloning/cloning_service.go index c97a8b4..4f17aff 100644 --- a/internal/cloning/cloning_service.go +++ b/internal/cloning/cloning_service.go @@ -19,6 +19,8 @@ func LoadCloningConfig() (*Config, error) { if err := envconfig.Process("", &config); err != nil { return nil, fmt.Errorf("failed to process cloning configuration: %w", err) } + log.Printf("[kayhon] Loaded cloning config: RouterName=%s, RouterVMID=%d, RouterNode=%s, MinPodID=%d, MaxPodID=%d, CloneTimeout=%s, SDNApplyTimeout=%s, RouterWaitTimeout=%s", + config.RouterName, config.RouterVMID, config.RouterNode, config.MinPodID, config.MaxPodID, config.CloneTimeout, config.SDNApplyTimeout, config.RouterWaitTimeout) return &config, nil } @@ -49,6 +51,9 @@ func NewCloningService(proxmoxService proxmox.Service, db *sql.DB, ldapService l return nil, fmt.Errorf("incomplete cloning configuration") } + log.Printf("[kayhon] Initializing CloningService with config: RouterName=%s, RouterVMID=%d, RouterNode=%s", + config.RouterName, config.RouterVMID, config.RouterNode) + return &CloningService{ ProxmoxService: proxmoxService, DatabaseService: NewDatabaseService(db), @@ -62,11 +67,21 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { var createdPools []string var clonedRouters []RouterInfo + log.Printf("[kayhon] === CloneTemplate START === Template=%s, Targets=%d, CheckExisting=%v, StartingVMID=%d", + req.Template, len(req.Targets), req.CheckExistingDeployments, req.StartingVMID) + log.Printf("[kayhon] Current config: RouterName=%s, RouterVMID=%d, RouterNode=%s, MinPodID=%d, MaxPodID=%d", + cs.Config.RouterName, cs.Config.RouterVMID, cs.Config.RouterNode, cs.Config.MinPodID, cs.Config.MaxPodID) + // 1. Get the template pool and its VMs templatePool, err := cs.ProxmoxService.GetPoolVMs("kamino_template_" + req.Template) if err != nil { + log.Printf("[kayhon] Failed to get template pool 'kamino_template_%s': %v", req.Template, err) return fmt.Errorf("failed to get template pool: %w", err) } + log.Printf("[kayhon] Step 1: Got template pool 'kamino_template_%s' with %d VMs", req.Template, len(templatePool)) + for _, vm := range templatePool { + log.Printf("[kayhon] Template VM: Name=%s, VMID=%d, Node=%s, Status=%s", vm.Name, vm.VmId, vm.NodeName, vm.RunningStatus) + } // 2. Check if any template is already deployed (if requested) if req.CheckExistingDeployments { @@ -106,15 +121,24 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { // If no router was found in the template, use the default router template if router == nil { + log.Printf("[kayhon] Step 3: No router found in template pool, using default router: Name=%s, VMID=%d, Node=%s", + cs.Config.RouterName, cs.Config.RouterVMID, cs.Config.RouterNode) router = &proxmox.VM{ Name: cs.Config.RouterName, Node: cs.Config.RouterNode, VMID: cs.Config.RouterVMID, } + } else { + log.Printf("[kayhon] Step 3: Found router in template pool: Name=%s, VMID=%d, Node=%s", router.Name, router.VMID, router.Node) } // 4. Verify that the pool is not empty + log.Printf("[kayhon] Step 4: Template has %d non-router VMs", len(templateVMs)) + for _, vm := range templateVMs { + log.Printf("[kayhon] Non-router VM: Name=%s, VMID=%d, Node=%s", vm.Name, vm.VMID, vm.Node) + } if len(templateVMs) == 0 { + log.Printf("[kayhon] ERROR: Template pool %s contains no VMs", req.Template) return fmt.Errorf("template pool %s contains no VMs", req.Template) } @@ -124,11 +148,15 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { podIDs, podNumbers, err := cs.ProxmoxService.GetNextPodIDs(cs.Config.MinPodID, cs.Config.MaxPodID, len(req.Targets)) if err != nil { + log.Printf("[kayhon] Failed to get next pod IDs (range %d-%d, count %d): %v", cs.Config.MinPodID, cs.Config.MaxPodID, len(req.Targets), err) return fmt.Errorf("failed to get next pod IDs: %w", err) } + log.Printf("[kayhon] Step 5: Allocated PodIDs=%v, PodNumbers=%v", podIDs, podNumbers) // Lock the vmid allocation mutex to prevent race conditions during vmid allocation + log.Printf("[kayhon] Acquiring vmidMutex lock for VM ID allocation") cs.vmidMutex.Lock() + log.Printf("[kayhon] vmidMutex lock acquired") // Use StartingVMID from request if provided, otherwise get next available VMIDs var vmIDs []int @@ -141,9 +169,11 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { } else { vmIDs, err = cs.ProxmoxService.GetNextVMIDs(numVMs) if err != nil { + log.Printf("[kayhon] Failed to get next VM IDs (count %d): %v", numVMs, err) return fmt.Errorf("failed to get next VM IDs: %w", err) } } + log.Printf("[kayhon] Step 5: Allocated VMIDs=%v (total %d VMs)", vmIDs, numVMs) for i := range req.Targets { req.Targets[i].PoolName = fmt.Sprintf("%s_%s_%s", podIDs[i], req.Template, req.Targets[i].Name) @@ -156,13 +186,18 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { } // 6. Create new pool for each target + log.Printf("[kayhon] Step 6: Creating pools for %d targets", len(req.Targets)) for _, target := range req.Targets { + log.Printf("[kayhon] Creating pool: %s (Target=%s, PodID=%s, PodNumber=%d, VMIDs=%v)", + target.PoolName, target.Name, target.PodID, target.PodNumber, target.VMIDs) err = cs.ProxmoxService.CreateNewPool(target.PoolName) if err != nil { + log.Printf("[kayhon] Failed to create pool %s: %v", target.PoolName, err) cs.cleanupFailedClones(createdPools) return fmt.Errorf("failed to create new pool for %s: %w", target.Name, err) } createdPools = append(createdPools, target.PoolName) + log.Printf("[kayhon] Pool created successfully: %s", target.PoolName) } // 7. Clone targets to proxmox @@ -173,13 +208,16 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { }, ) + log.Printf("[kayhon] Step 7: Cloning VMs for %d targets", len(req.Targets)) for _, target := range req.Targets { // Find best node per target bestNode, err := cs.ProxmoxService.FindBestNode() if err != nil { + log.Printf("[kayhon] Failed to find best node for target %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to find best node for %s: %v", target.Name, err)) continue } + log.Printf("[kayhon] Best node for target %s: %s", target.Name, bestNode) // Clone router routerCloneReq := proxmox.VMCloneRequest{ @@ -189,10 +227,15 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { NewVMID: target.VMIDs[0], TargetNode: bestNode, } + log.Printf("[kayhon] Cloning router for target %s: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s", + target.Name, routerCloneReq.SourceVM.Name, routerCloneReq.SourceVM.VMID, routerCloneReq.SourceVM.Node, + routerCloneReq.NewVMID, routerCloneReq.PoolName, routerCloneReq.TargetNode) err = cs.ProxmoxService.CloneVM(routerCloneReq) if err != nil { + log.Printf("[kayhon] Failed to clone router VM for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to clone router VM for %s: %v", target.Name, err)) } else { + log.Printf("[kayhon] Router clone initiated successfully for target %s (NewVMID=%d)", target.Name, routerCloneReq.NewVMID) // Determine router type routerType, err := cs.ProxmoxService.GetRouterType(*router) if err != nil { @@ -218,82 +261,103 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { NewVMID: target.VMIDs[i+1], TargetNode: bestNode, } + log.Printf("[kayhon] Cloning VM %d/%d for target %s: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s", + i+1, len(templateVMs), target.Name, vm.Name, vm.VMID, vm.Node, vmCloneReq.NewVMID, vmCloneReq.PoolName, vmCloneReq.TargetNode) err := cs.ProxmoxService.CloneVM(vmCloneReq) if err != nil { + log.Printf("[kayhon] Failed to clone VM %s for %s: %v", vm.Name, target.Name, err) errors = append(errors, fmt.Sprintf("failed to clone VM %s for %s: %v", vm.Name, target.Name, err)) + } else { + log.Printf("[kayhon] VM clone initiated: %s -> NewVMID=%d for target %s", vm.Name, vmCloneReq.NewVMID, target.Name) } } } // 8. Wait for all VM clone operations to complete before configuring VNets - log.Printf("Waiting for clone operations to complete for %d targets", len(req.Targets)) + log.Printf("[kayhon] Step 8: Waiting for clone operations to complete for %d targets", len(req.Targets)) for _, target := range req.Targets { // Wait for all VMs in the pool to be properly cloned - log.Printf("Waiting for VMs in pool %s to be available", target.PoolName) + log.Printf("[kayhon] Waiting for VMs in pool %s to be available (target: %s)", target.PoolName, target.Name) time.Sleep(2 * time.Second) // First wait for all VMs to appear in the pool for retries := range 30 { poolVMs, err := cs.ProxmoxService.GetPoolVMs(target.PoolName) if err != nil { + log.Printf("[kayhon] Retry %d/30: Error getting pool VMs for %s: %v", retries+1, target.PoolName, err) time.Sleep(2 * time.Second) continue } if len(poolVMs) >= numVMsPerTarget { - log.Printf("Pool %s has %d VMs (expected %d) - all VMs present", target.PoolName, len(poolVMs), numVMsPerTarget) + log.Printf("[kayhon] Pool %s has %d VMs (expected %d) - all VMs present", target.PoolName, len(poolVMs), numVMsPerTarget) + for _, vm := range poolVMs { + log.Printf("[kayhon] Pool VM: Name=%s, VMID=%d, Node=%s, Status=%s", vm.Name, vm.VmId, vm.NodeName, vm.RunningStatus) + } break } - log.Printf("Pool %s has %d VMs, waiting for %d (retry %d/30)", target.PoolName, len(poolVMs), numVMsPerTarget, retries+1) + log.Printf("[kayhon] Pool %s has %d VMs, waiting for %d (retry %d/30)", target.PoolName, len(poolVMs), numVMsPerTarget, retries+1) time.Sleep(2 * time.Second) } // Wait for all VM locks to be released - log.Printf("Waiting for all VM clone operations to complete for pool %s (checking locks)", target.PoolName) + log.Printf("[kayhon] Checking VM locks for pool %s", target.PoolName) poolVMs, err := cs.ProxmoxService.GetPoolVMs(target.PoolName) if err != nil { + log.Printf("[kayhon] Failed to get pool VMs after waiting for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to get pool VMs after waiting for %s: %v", target.Name, err)) continue } for _, vm := range poolVMs { - log.Printf("Waiting for VM %d (%s) lock to be released", vm.VmId, vm.Name) + log.Printf("[kayhon] Waiting for VM %d (%s) lock to be released on node %s", vm.VmId, vm.Name, vm.NodeName) if err := cs.ProxmoxService.WaitForLock(vm.NodeName, vm.VmId); err != nil { - log.Printf("Warning: timeout waiting for VM %d lock, continuing anyway: %v", vm.VmId, err) + log.Printf("[kayhon] WARNING: Timeout waiting for VM %d (%s) lock: %v", vm.VmId, vm.Name, err) + } else { + log.Printf("[kayhon] VM %d (%s) lock released", vm.VmId, vm.Name) } } - log.Printf("All clone operations complete for pool %s", target.PoolName) + log.Printf("[kayhon] All clone operations complete for pool %s (target: %s)", target.PoolName, target.Name) } // Release the vmid allocation mutex now that all of the VMs are cloned on proxmox + log.Printf("[kayhon] Releasing vmidMutex lock") cs.vmidMutex.Unlock() + log.Printf("[kayhon] vmidMutex lock released") // 9. Wait for all router disks to be fully available before configuring VNets. // Proxmox clone is two-phase: the clone lock (Phase 1) releases before the storage // backend finishes writing the disk (Phase 2). If SetPodVnet runs before Phase 2 // completes, Proxmox's disk finalization can overwrite the net1 config change, // leaving the router connected to the wrong vnet. - log.Printf("Waiting for router disks to be available before configuring VNets") + log.Printf("[kayhon] Step 9: Waiting for router disks to be available before configuring VNets (timeout: %s)", cs.Config.RouterWaitTimeout) routerDiskReady := make(map[int]bool) for _, routerInfo := range clonedRouters { - log.Printf("Waiting for router disk to be available for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) + log.Printf("[kayhon] Waiting for router disk: Target=%s, VMID=%d, Node=%s, RouterType=%s, PodNumber=%d", + routerInfo.TargetName, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType, routerInfo.PodNumber) if err := cs.ProxmoxService.WaitForDisk(routerInfo.Node, routerInfo.VMID, cs.Config.RouterWaitTimeout); err != nil { + log.Printf("[kayhon] Router disk unavailable for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("router disk unavailable for %s: %v", routerInfo.TargetName, err)) } else { + log.Printf("[kayhon] Router disk ready for %s (VMID=%d)", routerInfo.TargetName, routerInfo.VMID) routerDiskReady[routerInfo.VMID] = true } } // 10. Configure VNet of all VMs - log.Printf("Configuring VNets for %d targets", len(req.Targets)) + log.Printf("[kayhon] Step 10: Configuring VNets for %d targets", len(req.Targets)) for _, target := range req.Targets { vnetName := fmt.Sprintf("kamino%d", target.PodNumber) - log.Printf("Setting VNet %s for pool %s (target: %s)", vnetName, target.PoolName, target.Name) + log.Printf("[kayhon] Setting VNet %s for pool %s (target=%s, PodNumber=%d, VMIDs=%v)", + vnetName, target.PoolName, target.Name, target.PodNumber, target.VMIDs) err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName) if err != nil { + log.Printf("[kayhon] Failed to update pod vnet for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to update pod vnet for %s: %v", target.Name, err)) + } else { + log.Printf("[kayhon] VNet %s configured successfully for pool %s", vnetName, target.PoolName) } } @@ -304,25 +368,31 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { Progress: 25, }, ) - log.Printf("Starting %d routers", len(clonedRouters)) + log.Printf("[kayhon] Step 11: Starting %d routers", len(clonedRouters)) for _, routerInfo := range clonedRouters { if !routerDiskReady[routerInfo.VMID] { + log.Printf("[kayhon] Skipping router start for %s (VMID=%d) - disk not ready", routerInfo.TargetName, routerInfo.VMID) continue } // Start the router - log.Printf("Starting router VM for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) + log.Printf("[kayhon] Starting router VM: Target=%s, VMID=%d, Node=%s, RouterType=%s, PodNumber=%d", + routerInfo.TargetName, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType, routerInfo.PodNumber) err = cs.ProxmoxService.StartVM(routerInfo.Node, routerInfo.VMID) if err != nil { + log.Printf("[kayhon] Failed to start router VM for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to start router VM for %s: %v", routerInfo.TargetName, err)) continue } // Wait for router to be running - log.Printf("Waiting for router VM to be running for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) + log.Printf("[kayhon] Waiting for router VM to reach 'running' status: Target=%s, VMID=%d", routerInfo.TargetName, routerInfo.VMID) err = cs.ProxmoxService.WaitForRunning(routerInfo.Node, routerInfo.VMID) if err != nil { + log.Printf("[kayhon] Router VM failed to reach 'running' status for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to start router VM for %s: %v", routerInfo.TargetName, err)) + } else { + log.Printf("[kayhon] Router VM is running: Target=%s, VMID=%d", routerInfo.TargetName, routerInfo.VMID) } } @@ -334,19 +404,26 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { }, ) - log.Printf("Configuring %d pod routers", len(clonedRouters)) + log.Printf("[kayhon] Step 12: Configuring %d pod routers", len(clonedRouters)) for _, routerInfo := range clonedRouters { // Double-check that router is still running before configuration + log.Printf("[kayhon] Verifying router is running before configuration: Target=%s, VMID=%d, Node=%s", + routerInfo.TargetName, routerInfo.VMID, routerInfo.Node) err = cs.ProxmoxService.WaitForRunning(routerInfo.Node, routerInfo.VMID) if err != nil { + log.Printf("[kayhon] Router not running before configuration for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("router not running before configuration for %s: %v", routerInfo.TargetName, err)) continue } - log.Printf("Configuring pod router for %s (Pod: %d, VMID: %d)", routerInfo.TargetName, routerInfo.PodNumber, routerInfo.VMID) + log.Printf("[kayhon] Configuring pod router: Target=%s, PodNumber=%d, VMID=%d, Node=%s, RouterType=%s", + routerInfo.TargetName, routerInfo.PodNumber, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType) err = cs.ProxmoxService.ConfigurePodRouter(routerInfo.PodNumber, routerInfo.Node, routerInfo.VMID, routerInfo.RouterType) if err != nil { + log.Printf("[kayhon] Failed to configure pod router for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to configure pod router for %s: %v", routerInfo.TargetName, err)) + } else { + log.Printf("[kayhon] Pod router configured successfully: Target=%s, VMID=%d, RouterType=%s", routerInfo.TargetName, routerInfo.VMID, routerInfo.RouterType) } } @@ -359,10 +436,15 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { ) // 12. Set permissions on the pool to the user/group + log.Printf("[kayhon] Step 13: Setting permissions for %d targets", len(req.Targets)) for _, target := range req.Targets { + log.Printf("[kayhon] Setting pool permission: Pool=%s, Target=%s, IsGroup=%v", target.PoolName, target.Name, target.IsGroup) err = cs.ProxmoxService.SetPoolPermission(target.PoolName, target.Name, target.IsGroup) if err != nil { + log.Printf("[kayhon] Failed to set pool permissions for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to update pool permissions for %s: %v", target.Name, err)) + } else { + log.Printf("[kayhon] Pool permissions set successfully for %s on pool %s", target.Name, target.PoolName) } } @@ -382,10 +464,15 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { // Handle errors and cleanup if necessary if len(errors) > 0 { + log.Printf("[kayhon] === CloneTemplate COMPLETED WITH ERRORS === Template=%s, ErrorCount=%d", req.Template, len(errors)) + for i, e := range errors { + log.Printf("[kayhon] Error %d: %s", i+1, e) + } cs.cleanupFailedClones(createdPools) return fmt.Errorf("bulk clone operation completed with errors: %v", errors) } + log.Printf("[kayhon] === CloneTemplate COMPLETED SUCCESSFULLY === Template=%s, Targets=%d", req.Template, len(req.Targets)) return nil } diff --git a/internal/proxmox/networking.go b/internal/proxmox/networking.go index ff0947b..0cca565 100644 --- a/internal/proxmox/networking.go +++ b/internal/proxmox/networking.go @@ -21,6 +21,8 @@ type RouterConfig struct { } func (s *ProxmoxService) GetRouterType(router VM) (string, error) { + log.Printf("[kayhon] GetRouterType: Checking router type for VM Name=%s, VMID=%d, Node=%s", router.Name, router.VMID, router.Node) + infoReq := tools.ProxmoxAPIRequest{ Method: "GET", Endpoint: fmt.Sprintf("/nodes/%s/qemu/%d/config", router.Node, router.VMID), @@ -28,26 +30,34 @@ func (s *ProxmoxService) GetRouterType(router VM) (string, error) { infoRsp, err := s.RequestHelper.MakeRequest(infoReq) if err != nil { + log.Printf("[kayhon] GetRouterType FAILED for VMID=%d: %v", router.VMID, err) return "", fmt.Errorf("request for router type failed: %v", err) } switch { case strings.Contains(string(infoRsp), "pfsense"): + log.Printf("[kayhon] GetRouterType: VMID=%d detected as pfsense", router.VMID) return "pfsense", nil case strings.Contains(string(infoRsp), "vyos"): + log.Printf("[kayhon] GetRouterType: VMID=%d detected as vyos", router.VMID) return "vyos", nil default: + log.Printf("[kayhon] GetRouterType: VMID=%d router type not defined in config response", router.VMID) return "", fmt.Errorf("router type not defined") } } // ConfigurePodRouter configures the pod router with proper networking settings func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int, routerType string) error { + log.Printf("[kayhon] ConfigurePodRouter START: PodNumber=%d, Node=%s, VMID=%d, RouterType=%s", podNumber, node, vmid, routerType) + config := RouterConfig{ WANScriptPath: s.Config.WANScriptPath, VIPScriptPath: s.Config.VIPScriptPath, VYOSScriptPath: s.Config.VYOSScriptPath, WANIPBase: s.Config.WANIPBase, } + log.Printf("[kayhon] ConfigurePodRouter config: WANScriptPath=%s, VIPScriptPath=%s, VYOSScriptPath=%s, WANIPBase=%s", + config.WANScriptPath, config.VIPScriptPath, config.VYOSScriptPath, config.WANIPBase) // Wait for router agent to be pingable statusReq := tools.ProxmoxAPIRequest{ @@ -60,12 +70,15 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int timeout := 5 * time.Minute startTime := time.Now() + log.Printf("[kayhon] ConfigurePodRouter: Waiting for QEMU agent to respond on VMID=%d", vmid) for { if time.Since(startTime) > timeout { + log.Printf("[kayhon] ConfigurePodRouter: QEMU agent timed out for VMID=%d after %s", vmid, timeout) return fmt.Errorf("router qemu agent timed out") } if _, err := s.RequestHelper.MakeRequest(statusReq); err == nil { + log.Printf("[kayhon] ConfigurePodRouter: QEMU agent responding on VMID=%d (elapsed: %s)", vmid, time.Since(startTime)) break // Agent is responding } @@ -74,13 +87,17 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int } // Clone depending on router type + log.Printf("[kayhon] ConfigurePodRouter: Applying configuration for routerType=%s on VMID=%d", routerType, vmid) switch routerType { case "pfsense": + wanIP := fmt.Sprintf("%s%d.1", config.WANIPBase, podNumber) + log.Printf("[kayhon] ConfigurePodRouter (pfsense): Setting WAN IP=%s on VMID=%d", wanIP, vmid) + // Configure router WAN IP to have correct third octet using qemu agent API call reqBody := map[string]any{ "command": []string{ config.WANScriptPath, - fmt.Sprintf("%s%d.1", config.WANIPBase, podNumber), + wanIP, }, } @@ -92,14 +109,19 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err := s.RequestHelper.MakeRequest(execReq) if err != nil { + log.Printf("[kayhon] ConfigurePodRouter (pfsense): WAN IP change FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make IP change request: %v", err) } + log.Printf("[kayhon] ConfigurePodRouter (pfsense): WAN IP set successfully on VMID=%d", vmid) // Send agent exec request to change VIP subnet + vipSubnet := fmt.Sprintf("%s%d.0", config.WANIPBase, podNumber) + log.Printf("[kayhon] ConfigurePodRouter (pfsense): Setting VIP subnet=%s on VMID=%d", vipSubnet, vmid) + vipReqBody := map[string]any{ "command": []string{ config.VIPScriptPath, - fmt.Sprintf("%s%d.0", config.WANIPBase, podNumber), + vipSubnet, }, } @@ -111,9 +133,15 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err = s.RequestHelper.MakeRequest(vipExecReq) if err != nil { + log.Printf("[kayhon] ConfigurePodRouter (pfsense): VIP change FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make VIP change request: %v", err) } + log.Printf("[kayhon] ConfigurePodRouter (pfsense): VIP subnet set successfully on VMID=%d", vmid) + case "vyos": + log.Printf("[kayhon] ConfigurePodRouter (vyos): Substituting THIRD_OCTET=%d, NETWORK_PREFIX=%s in %s on VMID=%d", + podNumber, config.WANIPBase, config.VYOSScriptPath, vmid) + reqBody := map[string]any{ "command": []string{ "sh", @@ -130,28 +158,36 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err := s.RequestHelper.MakeRequest(execReq) if err != nil { + log.Printf("[kayhon] ConfigurePodRouter (vyos): Config substitution FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make IP change request: %v", err) } + log.Printf("[kayhon] ConfigurePodRouter (vyos): Config substitution successful on VMID=%d", vmid) default: + log.Printf("[kayhon] ConfigurePodRouter: Invalid router type '%s' for VMID=%d", routerType, vmid) return fmt.Errorf("router type invalid") } + log.Printf("[kayhon] ConfigurePodRouter COMPLETE: PodNumber=%d, VMID=%d, RouterType=%s", podNumber, vmid, routerType) return nil } func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string) error { + log.Printf("[kayhon] SetPodVnet START: Pool=%s, VNet=%s", poolName, vnetName) + // Get all VMs in the pool vms, err := s.GetPoolVMs(poolName) if err != nil { + log.Printf("[kayhon] SetPodVnet: Failed to get pool VMs for pool %s: %v", poolName, err) return fmt.Errorf("failed to get pool VMs for pool %s: %w", poolName, err) } if len(vms) == 0 { + log.Printf("[kayhon] SetPodVnet: Pool %s contains no VMs", poolName) return fmt.Errorf("pool %s contains no VMs", poolName) } - log.Printf("Setting VNet %s for %d VMs in pool %s", vnetName, len(vms), poolName) + log.Printf("[kayhon] SetPodVnet: Setting VNet %s for %d VMs in pool %s", vnetName, len(vms), poolName) routerRegex := regexp.MustCompile(`(?i).*(router|pfsense|vyos).*`) var errors []string @@ -162,14 +198,17 @@ func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string) error { // Detect if VM is a router based on its name (lazy way but requires fewer API calls) if routerRegex.MatchString(vm.Name) { vnet = "net1" - log.Printf("Detected router VM %s (VMID: %d), using %s interface", vm.Name, vm.VmId, vnet) + log.Printf("[kayhon] SetPodVnet: Detected router VM %s (VMID=%d, Node=%s), using %s interface", vm.Name, vm.VmId, vm.NodeName, vnet) } else { - log.Printf("Setting VNet for VM %s (VMID: %d), using %s interface", vm.Name, vm.VmId, vnet) + log.Printf("[kayhon] SetPodVnet: Regular VM %s (VMID=%d, Node=%s), using %s interface", vm.Name, vm.VmId, vm.NodeName, vnet) } // Update VM network configuration + netConfig := fmt.Sprintf("virtio,bridge=%s,firewall=1", vnetName) + log.Printf("[kayhon] SetPodVnet: Updating VM config VMID=%d: %s=%s", vm.VmId, vnet, netConfig) + reqBody := map[string]string{ - vnet: fmt.Sprintf("virtio,bridge=%s,firewall=1", vnetName), + vnet: netConfig, } req := tools.ProxmoxAPIRequest{ @@ -181,18 +220,19 @@ func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string) error { _, err := s.RequestHelper.MakeRequest(req) if err != nil { errorMsg := fmt.Sprintf("failed to update network for VM %s (VMID: %d): %v", vm.Name, vm.VmId, err) - log.Printf("ERROR: %s", errorMsg) + log.Printf("[kayhon] SetPodVnet ERROR: %s", errorMsg) errors = append(errors, errorMsg) } else { - log.Printf("Successfully updated VNet for VM %s (VMID: %d) to %s", vm.Name, vm.VmId, vnetName) + log.Printf("[kayhon] SetPodVnet: Successfully updated VM config for VMID=%d: %s=%s", vm.VmId, vnet, netConfig) } } if len(errors) > 0 { + log.Printf("[kayhon] SetPodVnet COMPLETED WITH ERRORS: Pool=%s, VNet=%s, ErrorCount=%d", poolName, vnetName, len(errors)) return fmt.Errorf("VNet configuration completed with errors: %v", errors) } - log.Printf("Successfully configured VNet %s for all %d VMs in pool %s", vnetName, len(vms), poolName) + log.Printf("[kayhon] SetPodVnet COMPLETE: Successfully configured VNet %s for all %d VMs in pool %s", vnetName, len(vms), poolName) return nil } diff --git a/internal/proxmox/vms.go b/internal/proxmox/vms.go index 53d95bc..2a3a1e6 100644 --- a/internal/proxmox/vms.go +++ b/internal/proxmox/vms.go @@ -121,6 +121,9 @@ func (s *ProxmoxService) ConvertVMToTemplate(node string, vmID int) error { } func (s *ProxmoxService) CloneVM(req VMCloneRequest) error { + log.Printf("[kayhon] CloneVM: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s, Full=%d", + req.SourceVM.Name, req.SourceVM.VMID, req.SourceVM.Node, req.NewVMID, req.PoolName, req.TargetNode, req.Full) + // Clone VM cloneBody := map[string]any{ "newid": req.NewVMID, @@ -138,9 +141,11 @@ func (s *ProxmoxService) CloneVM(req VMCloneRequest) error { _, err := s.RequestHelper.MakeRequest(cloneReq) if err != nil { + log.Printf("[kayhon] CloneVM FAILED: SourceVMID=%d -> NewVMID=%d, error: %v", req.SourceVM.VMID, req.NewVMID, err) return fmt.Errorf("failed to initiate VM clone: %w", err) } + log.Printf("[kayhon] CloneVM initiated successfully: SourceVMID=%d -> NewVMID=%d", req.SourceVM.VMID, req.NewVMID) return nil } @@ -170,35 +175,39 @@ func (s *ProxmoxService) cloneVMWithUPID(req VMCloneRequest) (string, error) { func (s *ProxmoxService) WaitForDisk(node string, vmID int, maxWait time.Duration) error { start := time.Now() + log.Printf("[kayhon] WaitForDisk START: Node=%s, VMID=%d, MaxWait=%s", node, vmID, maxWait) for time.Since(start) < maxWait { time.Sleep(2 * time.Second) configResp, err := s.getVMConfig(node, vmID) if err != nil { + log.Printf("[kayhon] WaitForDisk: Failed to get VM config for VMID=%d: %v (elapsed: %s)", vmID, err, time.Since(start)) continue } - log.Printf("%+v", configResp) + log.Printf("[kayhon] WaitForDisk VM config for VMID=%d: Name=%s, HardDisk=%s, Lock=%s, Net0=%s, Net1=%s", + vmID, configResp.Name, configResp.HardDisk, configResp.Lock, configResp.Net0, configResp.Net1) if configResp.HardDisk != "" && configResp.Name != "" { - log.Printf("/nodes/%s/storage/%s/content?vmid=%d", s.Config.Nodes[0], s.Config.StorageID, vmID) + log.Printf("[kayhon] WaitForDisk: VM config has HardDisk and Name, checking storage content for VMID=%d", vmID) pendingReq := tools.ProxmoxAPIRequest{ Method: "GET", Endpoint: fmt.Sprintf("/nodes/%s/storage/%s/content?vmid=%d", s.Config.Nodes[0], s.Config.StorageID, vmID), } - log.Printf("%+v", pendingReq) - var diskResponse []PendingDiskResponse err := s.RequestHelper.MakeRequestAndUnmarshal(pendingReq, &diskResponse) if err != nil || len(diskResponse) == 0 { - log.Printf("Error retrieving pending disk info for VMID %d on node %s: %v", vmID, node, err) + log.Printf("[kayhon] WaitForDisk: Error or empty disk response for VMID=%d: err=%v, count=%d", vmID, err, len(diskResponse)) continue } - log.Printf("%+v", diskResponse) + log.Printf("[kayhon] WaitForDisk: Disk response for VMID=%d: %d disk(s)", vmID, len(diskResponse)) + for i, disk := range diskResponse { + log.Printf("[kayhon] Disk %d: Used=%d, Size=%d", i, disk.Used, disk.Size) + } // Iterate through all disks, if all have valid Used and Size (not 0) consider available allAvailable := true @@ -210,11 +219,16 @@ func (s *ProxmoxService) WaitForDisk(node string, vmID int, maxWait time.Duratio } if allAvailable { + log.Printf("[kayhon] WaitForDisk READY: VMID=%d, all disks available (elapsed: %s)", vmID, time.Since(start)) return nil // Disk is available } + log.Printf("[kayhon] WaitForDisk: Not all disks ready for VMID=%d, retrying...", vmID) + } else { + log.Printf("[kayhon] WaitForDisk: VM config incomplete for VMID=%d (HardDisk=%q, Name=%q), retrying...", vmID, configResp.HardDisk, configResp.Name) } } + log.Printf("[kayhon] WaitForDisk TIMEOUT: VMID=%d after %s", vmID, maxWait) return fmt.Errorf("timeout waiting for VM disks to become available") } @@ -264,23 +278,29 @@ func (s *ProxmoxService) GetNextVMIDs(num int) ([]int, error) { func (s *ProxmoxService) WaitForLock(node string, vmID int) error { timeout := 1 * time.Minute start := time.Now() + log.Printf("[kayhon] WaitForLock START: Node=%s, VMID=%d, Timeout=%s", node, vmID, timeout) for time.Since(start) < timeout { config, err := s.getVMConfig(node, vmID) if err != nil { + log.Printf("[kayhon] WaitForLock: Failed to get VM config for VMID=%d: %v", vmID, err) time.Sleep(5 * time.Second) continue } - log.Printf("VM %d lock status: '%s'", vmID, config.Lock) + log.Printf("[kayhon] WaitForLock VM config for VMID=%d: Name=%s, Lock=%s, HardDisk=%s, Net0=%s, Net1=%s", + vmID, config.Name, config.Lock, config.HardDisk, config.Net0, config.Net1) if config.Lock == "" { + log.Printf("[kayhon] WaitForLock CLEARED: VMID=%d (elapsed: %s)", vmID, time.Since(start)) return nil // No lock } + log.Printf("[kayhon] WaitForLock: VMID=%d still locked (lock=%s), waiting...", vmID, config.Lock) time.Sleep(5 * time.Second) } + log.Printf("[kayhon] WaitForLock TIMEOUT: VMID=%d after %s", vmID, timeout) return fmt.Errorf("timeout waiting for VM lock to be cleared") } @@ -309,21 +329,27 @@ func (s *ProxmoxService) vmAction(action string, node string, vmID int) error { func (s *ProxmoxService) waitForStatus(targetStatus string, node string, vmID int) error { timeout := 2 * time.Minute start := time.Now() + log.Printf("[kayhon] waitForStatus START: Node=%s, VMID=%d, TargetStatus=%s, Timeout=%s", node, vmID, targetStatus, timeout) for time.Since(start) < timeout { currentStatus, err := s.getVMStatus(node, vmID) if err != nil { + log.Printf("[kayhon] waitForStatus: Failed to get status for VMID=%d: %v", vmID, err) time.Sleep(5 * time.Second) continue } + log.Printf("[kayhon] waitForStatus: VMID=%d currentStatus=%s, targetStatus=%s", vmID, currentStatus, targetStatus) + if currentStatus == targetStatus { + log.Printf("[kayhon] waitForStatus REACHED: VMID=%d is now %s (elapsed: %s)", vmID, targetStatus, time.Since(start)) return nil } time.Sleep(5 * time.Second) } + log.Printf("[kayhon] waitForStatus TIMEOUT: VMID=%d never reached %s after %s", vmID, targetStatus, timeout) return fmt.Errorf("timeout waiting for VM to be %s", targetStatus) } @@ -356,9 +382,12 @@ func (s *ProxmoxService) getVMConfig(node string, VMID int) (*VirtualResourceCon var config VirtualResourceConfig if err := s.RequestHelper.MakeRequestAndUnmarshal(configReq, &config); err != nil { + log.Printf("[kayhon] getVMConfig FAILED: Node=%s, VMID=%d, error: %v", node, VMID, err) return nil, fmt.Errorf("failed to get VM config: %w", err) } + log.Printf("[kayhon] getVMConfig: Node=%s, VMID=%d -> Name=%s, HardDisk=%s, Lock=%s, Net0=%s, Net1=%s", + node, VMID, config.Name, config.HardDisk, config.Lock, config.Net0, config.Net1) return &config, nil } From 6f147af623afa5f3c560322a91c66b12a406f802 Mon Sep 17 00:00:00 2001 From: xdkaine <55013938+xdkaine@users.noreply.github.com> Date: Mon, 23 Feb 2026 16:32:11 -0800 Subject: [PATCH 2/4] Remove Regex for Router and moved to VMID --- internal/cloning/cloning_service.go | 2 +- internal/proxmox/networking.go | 14 ++++++-------- internal/proxmox/pools.go | 2 +- internal/proxmox/types.go | 2 +- 4 files changed, 9 insertions(+), 11 deletions(-) diff --git a/internal/cloning/cloning_service.go b/internal/cloning/cloning_service.go index 4f17aff..2bd45ee 100644 --- a/internal/cloning/cloning_service.go +++ b/internal/cloning/cloning_service.go @@ -352,7 +352,7 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { vnetName := fmt.Sprintf("kamino%d", target.PodNumber) log.Printf("[kayhon] Setting VNet %s for pool %s (target=%s, PodNumber=%d, VMIDs=%v)", vnetName, target.PoolName, target.Name, target.PodNumber, target.VMIDs) - err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName) + err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName, target.VMIDs[0]) if err != nil { log.Printf("[kayhon] Failed to update pod vnet for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to update pod vnet for %s: %v", target.Name, err)) diff --git a/internal/proxmox/networking.go b/internal/proxmox/networking.go index 0cca565..d07988b 100644 --- a/internal/proxmox/networking.go +++ b/internal/proxmox/networking.go @@ -4,7 +4,6 @@ import ( "fmt" "log" "math" - "regexp" "strings" "time" @@ -172,8 +171,8 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int return nil } -func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string) error { - log.Printf("[kayhon] SetPodVnet START: Pool=%s, VNet=%s", poolName, vnetName) +func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string, routerVMID int) error { + log.Printf("[kayhon] SetPodVnet START: Pool=%s, VNet=%s, RouterVMID=%d", poolName, vnetName, routerVMID) // Get all VMs in the pool vms, err := s.GetPoolVMs(poolName) @@ -189,18 +188,17 @@ func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string) error { log.Printf("[kayhon] SetPodVnet: Setting VNet %s for %d VMs in pool %s", vnetName, len(vms), poolName) - routerRegex := regexp.MustCompile(`(?i).*(router|pfsense|vyos).*`) var errors []string for _, vm := range vms { vnet := "net0" - // Detect if VM is a router based on its name (lazy way but requires fewer API calls) - if routerRegex.MatchString(vm.Name) { + // Identify the router by its VMID + if vm.VmId == routerVMID { vnet = "net1" - log.Printf("[kayhon] SetPodVnet: Detected router VM %s (VMID=%d, Node=%s), using %s interface", vm.Name, vm.VmId, vm.NodeName, vnet) + log.Printf("[kayhon] SetPodVnet: Router VM (VMID=%d, Node=%s), using %s interface", vm.VmId, vm.NodeName, vnet) } else { - log.Printf("[kayhon] SetPodVnet: Regular VM %s (VMID=%d, Node=%s), using %s interface", vm.Name, vm.VmId, vm.NodeName, vnet) + log.Printf("[kayhon] SetPodVnet: Regular VM (VMID=%d, Node=%s), using %s interface", vm.VmId, vm.NodeName, vnet) } // Update VM network configuration diff --git a/internal/proxmox/pools.go b/internal/proxmox/pools.go index d53513c..6b7780b 100644 --- a/internal/proxmox/pools.go +++ b/internal/proxmox/pools.go @@ -406,7 +406,7 @@ func (s *ProxmoxService) CreateTemplatePool(creator string, name string, addRout vnet := fmt.Sprintf("templ%d", templateID) log.Printf("Configuring VNet %s for pool %s", vnet, poolName) - err = s.SetPodVnet(poolName, vnet) + err = s.SetPodVnet(poolName, vnet, routerVMID) if err != nil { return fmt.Errorf("failed to set VNet for pool %s: %w", poolName, err) } diff --git a/internal/proxmox/types.go b/internal/proxmox/types.go index 6a98323..15ae039 100644 --- a/internal/proxmox/types.go +++ b/internal/proxmox/types.go @@ -77,7 +77,7 @@ type Service interface { // Networking GetRouterType(router VM) (string, error) ConfigurePodRouter(podNumber int, node string, vmid int, routerType string) error - SetPodVnet(poolName string, vnetName string) error + SetPodVnet(poolName string, vnetName string, routerVMID int) error GetUsedVNets() ([]VNet, error) CreateTemplatePool(creator string, name string, addRouter bool, vms []VM) error From b9243d0c08a84667da10686e892adca8155f7dd2 Mon Sep 17 00:00:00 2001 From: xdkaine <55013938+xdkaine@users.noreply.github.com> Date: Mon, 23 Feb 2026 17:00:31 -0800 Subject: [PATCH 3/4] Revert "added kayhon auditing logs" This reverts commit 53c87b214981962a0edf4b2a098e11040109dce7. --- internal/cloning/cloning_service.go | 123 ++++------------------------ internal/proxmox/networking.go | 58 ++----------- internal/proxmox/vms.go | 43 ++-------- 3 files changed, 34 insertions(+), 190 deletions(-) diff --git a/internal/cloning/cloning_service.go b/internal/cloning/cloning_service.go index 2bd45ee..c97a8b4 100644 --- a/internal/cloning/cloning_service.go +++ b/internal/cloning/cloning_service.go @@ -19,8 +19,6 @@ func LoadCloningConfig() (*Config, error) { if err := envconfig.Process("", &config); err != nil { return nil, fmt.Errorf("failed to process cloning configuration: %w", err) } - log.Printf("[kayhon] Loaded cloning config: RouterName=%s, RouterVMID=%d, RouterNode=%s, MinPodID=%d, MaxPodID=%d, CloneTimeout=%s, SDNApplyTimeout=%s, RouterWaitTimeout=%s", - config.RouterName, config.RouterVMID, config.RouterNode, config.MinPodID, config.MaxPodID, config.CloneTimeout, config.SDNApplyTimeout, config.RouterWaitTimeout) return &config, nil } @@ -51,9 +49,6 @@ func NewCloningService(proxmoxService proxmox.Service, db *sql.DB, ldapService l return nil, fmt.Errorf("incomplete cloning configuration") } - log.Printf("[kayhon] Initializing CloningService with config: RouterName=%s, RouterVMID=%d, RouterNode=%s", - config.RouterName, config.RouterVMID, config.RouterNode) - return &CloningService{ ProxmoxService: proxmoxService, DatabaseService: NewDatabaseService(db), @@ -67,21 +62,11 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { var createdPools []string var clonedRouters []RouterInfo - log.Printf("[kayhon] === CloneTemplate START === Template=%s, Targets=%d, CheckExisting=%v, StartingVMID=%d", - req.Template, len(req.Targets), req.CheckExistingDeployments, req.StartingVMID) - log.Printf("[kayhon] Current config: RouterName=%s, RouterVMID=%d, RouterNode=%s, MinPodID=%d, MaxPodID=%d", - cs.Config.RouterName, cs.Config.RouterVMID, cs.Config.RouterNode, cs.Config.MinPodID, cs.Config.MaxPodID) - // 1. Get the template pool and its VMs templatePool, err := cs.ProxmoxService.GetPoolVMs("kamino_template_" + req.Template) if err != nil { - log.Printf("[kayhon] Failed to get template pool 'kamino_template_%s': %v", req.Template, err) return fmt.Errorf("failed to get template pool: %w", err) } - log.Printf("[kayhon] Step 1: Got template pool 'kamino_template_%s' with %d VMs", req.Template, len(templatePool)) - for _, vm := range templatePool { - log.Printf("[kayhon] Template VM: Name=%s, VMID=%d, Node=%s, Status=%s", vm.Name, vm.VmId, vm.NodeName, vm.RunningStatus) - } // 2. Check if any template is already deployed (if requested) if req.CheckExistingDeployments { @@ -121,24 +106,15 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { // If no router was found in the template, use the default router template if router == nil { - log.Printf("[kayhon] Step 3: No router found in template pool, using default router: Name=%s, VMID=%d, Node=%s", - cs.Config.RouterName, cs.Config.RouterVMID, cs.Config.RouterNode) router = &proxmox.VM{ Name: cs.Config.RouterName, Node: cs.Config.RouterNode, VMID: cs.Config.RouterVMID, } - } else { - log.Printf("[kayhon] Step 3: Found router in template pool: Name=%s, VMID=%d, Node=%s", router.Name, router.VMID, router.Node) } // 4. Verify that the pool is not empty - log.Printf("[kayhon] Step 4: Template has %d non-router VMs", len(templateVMs)) - for _, vm := range templateVMs { - log.Printf("[kayhon] Non-router VM: Name=%s, VMID=%d, Node=%s", vm.Name, vm.VMID, vm.Node) - } if len(templateVMs) == 0 { - log.Printf("[kayhon] ERROR: Template pool %s contains no VMs", req.Template) return fmt.Errorf("template pool %s contains no VMs", req.Template) } @@ -148,15 +124,11 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { podIDs, podNumbers, err := cs.ProxmoxService.GetNextPodIDs(cs.Config.MinPodID, cs.Config.MaxPodID, len(req.Targets)) if err != nil { - log.Printf("[kayhon] Failed to get next pod IDs (range %d-%d, count %d): %v", cs.Config.MinPodID, cs.Config.MaxPodID, len(req.Targets), err) return fmt.Errorf("failed to get next pod IDs: %w", err) } - log.Printf("[kayhon] Step 5: Allocated PodIDs=%v, PodNumbers=%v", podIDs, podNumbers) // Lock the vmid allocation mutex to prevent race conditions during vmid allocation - log.Printf("[kayhon] Acquiring vmidMutex lock for VM ID allocation") cs.vmidMutex.Lock() - log.Printf("[kayhon] vmidMutex lock acquired") // Use StartingVMID from request if provided, otherwise get next available VMIDs var vmIDs []int @@ -169,11 +141,9 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { } else { vmIDs, err = cs.ProxmoxService.GetNextVMIDs(numVMs) if err != nil { - log.Printf("[kayhon] Failed to get next VM IDs (count %d): %v", numVMs, err) return fmt.Errorf("failed to get next VM IDs: %w", err) } } - log.Printf("[kayhon] Step 5: Allocated VMIDs=%v (total %d VMs)", vmIDs, numVMs) for i := range req.Targets { req.Targets[i].PoolName = fmt.Sprintf("%s_%s_%s", podIDs[i], req.Template, req.Targets[i].Name) @@ -186,18 +156,13 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { } // 6. Create new pool for each target - log.Printf("[kayhon] Step 6: Creating pools for %d targets", len(req.Targets)) for _, target := range req.Targets { - log.Printf("[kayhon] Creating pool: %s (Target=%s, PodID=%s, PodNumber=%d, VMIDs=%v)", - target.PoolName, target.Name, target.PodID, target.PodNumber, target.VMIDs) err = cs.ProxmoxService.CreateNewPool(target.PoolName) if err != nil { - log.Printf("[kayhon] Failed to create pool %s: %v", target.PoolName, err) cs.cleanupFailedClones(createdPools) return fmt.Errorf("failed to create new pool for %s: %w", target.Name, err) } createdPools = append(createdPools, target.PoolName) - log.Printf("[kayhon] Pool created successfully: %s", target.PoolName) } // 7. Clone targets to proxmox @@ -208,16 +173,13 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { }, ) - log.Printf("[kayhon] Step 7: Cloning VMs for %d targets", len(req.Targets)) for _, target := range req.Targets { // Find best node per target bestNode, err := cs.ProxmoxService.FindBestNode() if err != nil { - log.Printf("[kayhon] Failed to find best node for target %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to find best node for %s: %v", target.Name, err)) continue } - log.Printf("[kayhon] Best node for target %s: %s", target.Name, bestNode) // Clone router routerCloneReq := proxmox.VMCloneRequest{ @@ -227,15 +189,10 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { NewVMID: target.VMIDs[0], TargetNode: bestNode, } - log.Printf("[kayhon] Cloning router for target %s: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s", - target.Name, routerCloneReq.SourceVM.Name, routerCloneReq.SourceVM.VMID, routerCloneReq.SourceVM.Node, - routerCloneReq.NewVMID, routerCloneReq.PoolName, routerCloneReq.TargetNode) err = cs.ProxmoxService.CloneVM(routerCloneReq) if err != nil { - log.Printf("[kayhon] Failed to clone router VM for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to clone router VM for %s: %v", target.Name, err)) } else { - log.Printf("[kayhon] Router clone initiated successfully for target %s (NewVMID=%d)", target.Name, routerCloneReq.NewVMID) // Determine router type routerType, err := cs.ProxmoxService.GetRouterType(*router) if err != nil { @@ -261,103 +218,82 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { NewVMID: target.VMIDs[i+1], TargetNode: bestNode, } - log.Printf("[kayhon] Cloning VM %d/%d for target %s: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s", - i+1, len(templateVMs), target.Name, vm.Name, vm.VMID, vm.Node, vmCloneReq.NewVMID, vmCloneReq.PoolName, vmCloneReq.TargetNode) err := cs.ProxmoxService.CloneVM(vmCloneReq) if err != nil { - log.Printf("[kayhon] Failed to clone VM %s for %s: %v", vm.Name, target.Name, err) errors = append(errors, fmt.Sprintf("failed to clone VM %s for %s: %v", vm.Name, target.Name, err)) - } else { - log.Printf("[kayhon] VM clone initiated: %s -> NewVMID=%d for target %s", vm.Name, vmCloneReq.NewVMID, target.Name) } } } // 8. Wait for all VM clone operations to complete before configuring VNets - log.Printf("[kayhon] Step 8: Waiting for clone operations to complete for %d targets", len(req.Targets)) + log.Printf("Waiting for clone operations to complete for %d targets", len(req.Targets)) for _, target := range req.Targets { // Wait for all VMs in the pool to be properly cloned - log.Printf("[kayhon] Waiting for VMs in pool %s to be available (target: %s)", target.PoolName, target.Name) + log.Printf("Waiting for VMs in pool %s to be available", target.PoolName) time.Sleep(2 * time.Second) // First wait for all VMs to appear in the pool for retries := range 30 { poolVMs, err := cs.ProxmoxService.GetPoolVMs(target.PoolName) if err != nil { - log.Printf("[kayhon] Retry %d/30: Error getting pool VMs for %s: %v", retries+1, target.PoolName, err) time.Sleep(2 * time.Second) continue } if len(poolVMs) >= numVMsPerTarget { - log.Printf("[kayhon] Pool %s has %d VMs (expected %d) - all VMs present", target.PoolName, len(poolVMs), numVMsPerTarget) - for _, vm := range poolVMs { - log.Printf("[kayhon] Pool VM: Name=%s, VMID=%d, Node=%s, Status=%s", vm.Name, vm.VmId, vm.NodeName, vm.RunningStatus) - } + log.Printf("Pool %s has %d VMs (expected %d) - all VMs present", target.PoolName, len(poolVMs), numVMsPerTarget) break } - log.Printf("[kayhon] Pool %s has %d VMs, waiting for %d (retry %d/30)", target.PoolName, len(poolVMs), numVMsPerTarget, retries+1) + log.Printf("Pool %s has %d VMs, waiting for %d (retry %d/30)", target.PoolName, len(poolVMs), numVMsPerTarget, retries+1) time.Sleep(2 * time.Second) } // Wait for all VM locks to be released - log.Printf("[kayhon] Checking VM locks for pool %s", target.PoolName) + log.Printf("Waiting for all VM clone operations to complete for pool %s (checking locks)", target.PoolName) poolVMs, err := cs.ProxmoxService.GetPoolVMs(target.PoolName) if err != nil { - log.Printf("[kayhon] Failed to get pool VMs after waiting for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to get pool VMs after waiting for %s: %v", target.Name, err)) continue } for _, vm := range poolVMs { - log.Printf("[kayhon] Waiting for VM %d (%s) lock to be released on node %s", vm.VmId, vm.Name, vm.NodeName) + log.Printf("Waiting for VM %d (%s) lock to be released", vm.VmId, vm.Name) if err := cs.ProxmoxService.WaitForLock(vm.NodeName, vm.VmId); err != nil { - log.Printf("[kayhon] WARNING: Timeout waiting for VM %d (%s) lock: %v", vm.VmId, vm.Name, err) - } else { - log.Printf("[kayhon] VM %d (%s) lock released", vm.VmId, vm.Name) + log.Printf("Warning: timeout waiting for VM %d lock, continuing anyway: %v", vm.VmId, err) } } - log.Printf("[kayhon] All clone operations complete for pool %s (target: %s)", target.PoolName, target.Name) + log.Printf("All clone operations complete for pool %s", target.PoolName) } // Release the vmid allocation mutex now that all of the VMs are cloned on proxmox - log.Printf("[kayhon] Releasing vmidMutex lock") cs.vmidMutex.Unlock() - log.Printf("[kayhon] vmidMutex lock released") // 9. Wait for all router disks to be fully available before configuring VNets. // Proxmox clone is two-phase: the clone lock (Phase 1) releases before the storage // backend finishes writing the disk (Phase 2). If SetPodVnet runs before Phase 2 // completes, Proxmox's disk finalization can overwrite the net1 config change, // leaving the router connected to the wrong vnet. - log.Printf("[kayhon] Step 9: Waiting for router disks to be available before configuring VNets (timeout: %s)", cs.Config.RouterWaitTimeout) + log.Printf("Waiting for router disks to be available before configuring VNets") routerDiskReady := make(map[int]bool) for _, routerInfo := range clonedRouters { - log.Printf("[kayhon] Waiting for router disk: Target=%s, VMID=%d, Node=%s, RouterType=%s, PodNumber=%d", - routerInfo.TargetName, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType, routerInfo.PodNumber) + log.Printf("Waiting for router disk to be available for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) if err := cs.ProxmoxService.WaitForDisk(routerInfo.Node, routerInfo.VMID, cs.Config.RouterWaitTimeout); err != nil { - log.Printf("[kayhon] Router disk unavailable for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("router disk unavailable for %s: %v", routerInfo.TargetName, err)) } else { - log.Printf("[kayhon] Router disk ready for %s (VMID=%d)", routerInfo.TargetName, routerInfo.VMID) routerDiskReady[routerInfo.VMID] = true } } // 10. Configure VNet of all VMs - log.Printf("[kayhon] Step 10: Configuring VNets for %d targets", len(req.Targets)) + log.Printf("Configuring VNets for %d targets", len(req.Targets)) for _, target := range req.Targets { vnetName := fmt.Sprintf("kamino%d", target.PodNumber) - log.Printf("[kayhon] Setting VNet %s for pool %s (target=%s, PodNumber=%d, VMIDs=%v)", - vnetName, target.PoolName, target.Name, target.PodNumber, target.VMIDs) - err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName, target.VMIDs[0]) + log.Printf("Setting VNet %s for pool %s (target: %s)", vnetName, target.PoolName, target.Name) + err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName) if err != nil { - log.Printf("[kayhon] Failed to update pod vnet for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to update pod vnet for %s: %v", target.Name, err)) - } else { - log.Printf("[kayhon] VNet %s configured successfully for pool %s", vnetName, target.PoolName) } } @@ -368,31 +304,25 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { Progress: 25, }, ) - log.Printf("[kayhon] Step 11: Starting %d routers", len(clonedRouters)) + log.Printf("Starting %d routers", len(clonedRouters)) for _, routerInfo := range clonedRouters { if !routerDiskReady[routerInfo.VMID] { - log.Printf("[kayhon] Skipping router start for %s (VMID=%d) - disk not ready", routerInfo.TargetName, routerInfo.VMID) continue } // Start the router - log.Printf("[kayhon] Starting router VM: Target=%s, VMID=%d, Node=%s, RouterType=%s, PodNumber=%d", - routerInfo.TargetName, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType, routerInfo.PodNumber) + log.Printf("Starting router VM for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) err = cs.ProxmoxService.StartVM(routerInfo.Node, routerInfo.VMID) if err != nil { - log.Printf("[kayhon] Failed to start router VM for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to start router VM for %s: %v", routerInfo.TargetName, err)) continue } // Wait for router to be running - log.Printf("[kayhon] Waiting for router VM to reach 'running' status: Target=%s, VMID=%d", routerInfo.TargetName, routerInfo.VMID) + log.Printf("Waiting for router VM to be running for %s (VMID: %d)", routerInfo.TargetName, routerInfo.VMID) err = cs.ProxmoxService.WaitForRunning(routerInfo.Node, routerInfo.VMID) if err != nil { - log.Printf("[kayhon] Router VM failed to reach 'running' status for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to start router VM for %s: %v", routerInfo.TargetName, err)) - } else { - log.Printf("[kayhon] Router VM is running: Target=%s, VMID=%d", routerInfo.TargetName, routerInfo.VMID) } } @@ -404,26 +334,19 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { }, ) - log.Printf("[kayhon] Step 12: Configuring %d pod routers", len(clonedRouters)) + log.Printf("Configuring %d pod routers", len(clonedRouters)) for _, routerInfo := range clonedRouters { // Double-check that router is still running before configuration - log.Printf("[kayhon] Verifying router is running before configuration: Target=%s, VMID=%d, Node=%s", - routerInfo.TargetName, routerInfo.VMID, routerInfo.Node) err = cs.ProxmoxService.WaitForRunning(routerInfo.Node, routerInfo.VMID) if err != nil { - log.Printf("[kayhon] Router not running before configuration for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("router not running before configuration for %s: %v", routerInfo.TargetName, err)) continue } - log.Printf("[kayhon] Configuring pod router: Target=%s, PodNumber=%d, VMID=%d, Node=%s, RouterType=%s", - routerInfo.TargetName, routerInfo.PodNumber, routerInfo.VMID, routerInfo.Node, routerInfo.RouterType) + log.Printf("Configuring pod router for %s (Pod: %d, VMID: %d)", routerInfo.TargetName, routerInfo.PodNumber, routerInfo.VMID) err = cs.ProxmoxService.ConfigurePodRouter(routerInfo.PodNumber, routerInfo.Node, routerInfo.VMID, routerInfo.RouterType) if err != nil { - log.Printf("[kayhon] Failed to configure pod router for %s (VMID=%d): %v", routerInfo.TargetName, routerInfo.VMID, err) errors = append(errors, fmt.Sprintf("failed to configure pod router for %s: %v", routerInfo.TargetName, err)) - } else { - log.Printf("[kayhon] Pod router configured successfully: Target=%s, VMID=%d, RouterType=%s", routerInfo.TargetName, routerInfo.VMID, routerInfo.RouterType) } } @@ -436,15 +359,10 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { ) // 12. Set permissions on the pool to the user/group - log.Printf("[kayhon] Step 13: Setting permissions for %d targets", len(req.Targets)) for _, target := range req.Targets { - log.Printf("[kayhon] Setting pool permission: Pool=%s, Target=%s, IsGroup=%v", target.PoolName, target.Name, target.IsGroup) err = cs.ProxmoxService.SetPoolPermission(target.PoolName, target.Name, target.IsGroup) if err != nil { - log.Printf("[kayhon] Failed to set pool permissions for %s: %v", target.Name, err) errors = append(errors, fmt.Sprintf("failed to update pool permissions for %s: %v", target.Name, err)) - } else { - log.Printf("[kayhon] Pool permissions set successfully for %s on pool %s", target.Name, target.PoolName) } } @@ -464,15 +382,10 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { // Handle errors and cleanup if necessary if len(errors) > 0 { - log.Printf("[kayhon] === CloneTemplate COMPLETED WITH ERRORS === Template=%s, ErrorCount=%d", req.Template, len(errors)) - for i, e := range errors { - log.Printf("[kayhon] Error %d: %s", i+1, e) - } cs.cleanupFailedClones(createdPools) return fmt.Errorf("bulk clone operation completed with errors: %v", errors) } - log.Printf("[kayhon] === CloneTemplate COMPLETED SUCCESSFULLY === Template=%s, Targets=%d", req.Template, len(req.Targets)) return nil } diff --git a/internal/proxmox/networking.go b/internal/proxmox/networking.go index d07988b..9a809dd 100644 --- a/internal/proxmox/networking.go +++ b/internal/proxmox/networking.go @@ -20,8 +20,6 @@ type RouterConfig struct { } func (s *ProxmoxService) GetRouterType(router VM) (string, error) { - log.Printf("[kayhon] GetRouterType: Checking router type for VM Name=%s, VMID=%d, Node=%s", router.Name, router.VMID, router.Node) - infoReq := tools.ProxmoxAPIRequest{ Method: "GET", Endpoint: fmt.Sprintf("/nodes/%s/qemu/%d/config", router.Node, router.VMID), @@ -29,34 +27,26 @@ func (s *ProxmoxService) GetRouterType(router VM) (string, error) { infoRsp, err := s.RequestHelper.MakeRequest(infoReq) if err != nil { - log.Printf("[kayhon] GetRouterType FAILED for VMID=%d: %v", router.VMID, err) return "", fmt.Errorf("request for router type failed: %v", err) } switch { case strings.Contains(string(infoRsp), "pfsense"): - log.Printf("[kayhon] GetRouterType: VMID=%d detected as pfsense", router.VMID) return "pfsense", nil case strings.Contains(string(infoRsp), "vyos"): - log.Printf("[kayhon] GetRouterType: VMID=%d detected as vyos", router.VMID) return "vyos", nil default: - log.Printf("[kayhon] GetRouterType: VMID=%d router type not defined in config response", router.VMID) return "", fmt.Errorf("router type not defined") } } // ConfigurePodRouter configures the pod router with proper networking settings func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int, routerType string) error { - log.Printf("[kayhon] ConfigurePodRouter START: PodNumber=%d, Node=%s, VMID=%d, RouterType=%s", podNumber, node, vmid, routerType) - config := RouterConfig{ WANScriptPath: s.Config.WANScriptPath, VIPScriptPath: s.Config.VIPScriptPath, VYOSScriptPath: s.Config.VYOSScriptPath, WANIPBase: s.Config.WANIPBase, } - log.Printf("[kayhon] ConfigurePodRouter config: WANScriptPath=%s, VIPScriptPath=%s, VYOSScriptPath=%s, WANIPBase=%s", - config.WANScriptPath, config.VIPScriptPath, config.VYOSScriptPath, config.WANIPBase) // Wait for router agent to be pingable statusReq := tools.ProxmoxAPIRequest{ @@ -69,15 +59,12 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int timeout := 5 * time.Minute startTime := time.Now() - log.Printf("[kayhon] ConfigurePodRouter: Waiting for QEMU agent to respond on VMID=%d", vmid) for { if time.Since(startTime) > timeout { - log.Printf("[kayhon] ConfigurePodRouter: QEMU agent timed out for VMID=%d after %s", vmid, timeout) return fmt.Errorf("router qemu agent timed out") } if _, err := s.RequestHelper.MakeRequest(statusReq); err == nil { - log.Printf("[kayhon] ConfigurePodRouter: QEMU agent responding on VMID=%d (elapsed: %s)", vmid, time.Since(startTime)) break // Agent is responding } @@ -86,17 +73,13 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int } // Clone depending on router type - log.Printf("[kayhon] ConfigurePodRouter: Applying configuration for routerType=%s on VMID=%d", routerType, vmid) switch routerType { case "pfsense": - wanIP := fmt.Sprintf("%s%d.1", config.WANIPBase, podNumber) - log.Printf("[kayhon] ConfigurePodRouter (pfsense): Setting WAN IP=%s on VMID=%d", wanIP, vmid) - // Configure router WAN IP to have correct third octet using qemu agent API call reqBody := map[string]any{ "command": []string{ config.WANScriptPath, - wanIP, + fmt.Sprintf("%s%d.1", config.WANIPBase, podNumber), }, } @@ -108,19 +91,14 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err := s.RequestHelper.MakeRequest(execReq) if err != nil { - log.Printf("[kayhon] ConfigurePodRouter (pfsense): WAN IP change FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make IP change request: %v", err) } - log.Printf("[kayhon] ConfigurePodRouter (pfsense): WAN IP set successfully on VMID=%d", vmid) // Send agent exec request to change VIP subnet - vipSubnet := fmt.Sprintf("%s%d.0", config.WANIPBase, podNumber) - log.Printf("[kayhon] ConfigurePodRouter (pfsense): Setting VIP subnet=%s on VMID=%d", vipSubnet, vmid) - vipReqBody := map[string]any{ "command": []string{ config.VIPScriptPath, - vipSubnet, + fmt.Sprintf("%s%d.0", config.WANIPBase, podNumber), }, } @@ -132,15 +110,9 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err = s.RequestHelper.MakeRequest(vipExecReq) if err != nil { - log.Printf("[kayhon] ConfigurePodRouter (pfsense): VIP change FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make VIP change request: %v", err) } - log.Printf("[kayhon] ConfigurePodRouter (pfsense): VIP subnet set successfully on VMID=%d", vmid) - case "vyos": - log.Printf("[kayhon] ConfigurePodRouter (vyos): Substituting THIRD_OCTET=%d, NETWORK_PREFIX=%s in %s on VMID=%d", - podNumber, config.WANIPBase, config.VYOSScriptPath, vmid) - reqBody := map[string]any{ "command": []string{ "sh", @@ -157,36 +129,28 @@ func (s *ProxmoxService) ConfigurePodRouter(podNumber int, node string, vmid int _, err := s.RequestHelper.MakeRequest(execReq) if err != nil { - log.Printf("[kayhon] ConfigurePodRouter (vyos): Config substitution FAILED for VMID=%d: %v", vmid, err) return fmt.Errorf("failed to make IP change request: %v", err) } - log.Printf("[kayhon] ConfigurePodRouter (vyos): Config substitution successful on VMID=%d", vmid) default: - log.Printf("[kayhon] ConfigurePodRouter: Invalid router type '%s' for VMID=%d", routerType, vmid) return fmt.Errorf("router type invalid") } - log.Printf("[kayhon] ConfigurePodRouter COMPLETE: PodNumber=%d, VMID=%d, RouterType=%s", podNumber, vmid, routerType) return nil } func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string, routerVMID int) error { - log.Printf("[kayhon] SetPodVnet START: Pool=%s, VNet=%s, RouterVMID=%d", poolName, vnetName, routerVMID) - // Get all VMs in the pool vms, err := s.GetPoolVMs(poolName) if err != nil { - log.Printf("[kayhon] SetPodVnet: Failed to get pool VMs for pool %s: %v", poolName, err) return fmt.Errorf("failed to get pool VMs for pool %s: %w", poolName, err) } if len(vms) == 0 { - log.Printf("[kayhon] SetPodVnet: Pool %s contains no VMs", poolName) return fmt.Errorf("pool %s contains no VMs", poolName) } - log.Printf("[kayhon] SetPodVnet: Setting VNet %s for %d VMs in pool %s", vnetName, len(vms), poolName) + log.Printf("Setting VNet %s for %d VMs in pool %s", vnetName, len(vms), poolName) var errors []string @@ -196,17 +160,14 @@ func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string, routerVMID // Identify the router by its VMID if vm.VmId == routerVMID { vnet = "net1" - log.Printf("[kayhon] SetPodVnet: Router VM (VMID=%d, Node=%s), using %s interface", vm.VmId, vm.NodeName, vnet) + log.Printf("Detected router VM %s (VMID: %d), using %s interface", vm.Name, vm.VmId, vnet) } else { - log.Printf("[kayhon] SetPodVnet: Regular VM (VMID=%d, Node=%s), using %s interface", vm.VmId, vm.NodeName, vnet) + log.Printf("Setting VNet for VM %s (VMID: %d), using %s interface", vm.Name, vm.VmId, vnet) } // Update VM network configuration - netConfig := fmt.Sprintf("virtio,bridge=%s,firewall=1", vnetName) - log.Printf("[kayhon] SetPodVnet: Updating VM config VMID=%d: %s=%s", vm.VmId, vnet, netConfig) - reqBody := map[string]string{ - vnet: netConfig, + vnet: fmt.Sprintf("virtio,bridge=%s,firewall=1", vnetName), } req := tools.ProxmoxAPIRequest{ @@ -218,19 +179,18 @@ func (s *ProxmoxService) SetPodVnet(poolName string, vnetName string, routerVMID _, err := s.RequestHelper.MakeRequest(req) if err != nil { errorMsg := fmt.Sprintf("failed to update network for VM %s (VMID: %d): %v", vm.Name, vm.VmId, err) - log.Printf("[kayhon] SetPodVnet ERROR: %s", errorMsg) + log.Printf("ERROR: %s", errorMsg) errors = append(errors, errorMsg) } else { - log.Printf("[kayhon] SetPodVnet: Successfully updated VM config for VMID=%d: %s=%s", vm.VmId, vnet, netConfig) + log.Printf("Successfully updated VNet for VM %s (VMID: %d) to %s", vm.Name, vm.VmId, vnetName) } } if len(errors) > 0 { - log.Printf("[kayhon] SetPodVnet COMPLETED WITH ERRORS: Pool=%s, VNet=%s, ErrorCount=%d", poolName, vnetName, len(errors)) return fmt.Errorf("VNet configuration completed with errors: %v", errors) } - log.Printf("[kayhon] SetPodVnet COMPLETE: Successfully configured VNet %s for all %d VMs in pool %s", vnetName, len(vms), poolName) + log.Printf("Successfully configured VNet %s for all %d VMs in pool %s", vnetName, len(vms), poolName) return nil } diff --git a/internal/proxmox/vms.go b/internal/proxmox/vms.go index 2a3a1e6..53d95bc 100644 --- a/internal/proxmox/vms.go +++ b/internal/proxmox/vms.go @@ -121,9 +121,6 @@ func (s *ProxmoxService) ConvertVMToTemplate(node string, vmID int) error { } func (s *ProxmoxService) CloneVM(req VMCloneRequest) error { - log.Printf("[kayhon] CloneVM: SourceVM={Name=%s, VMID=%d, Node=%s}, NewVMID=%d, Pool=%s, TargetNode=%s, Full=%d", - req.SourceVM.Name, req.SourceVM.VMID, req.SourceVM.Node, req.NewVMID, req.PoolName, req.TargetNode, req.Full) - // Clone VM cloneBody := map[string]any{ "newid": req.NewVMID, @@ -141,11 +138,9 @@ func (s *ProxmoxService) CloneVM(req VMCloneRequest) error { _, err := s.RequestHelper.MakeRequest(cloneReq) if err != nil { - log.Printf("[kayhon] CloneVM FAILED: SourceVMID=%d -> NewVMID=%d, error: %v", req.SourceVM.VMID, req.NewVMID, err) return fmt.Errorf("failed to initiate VM clone: %w", err) } - log.Printf("[kayhon] CloneVM initiated successfully: SourceVMID=%d -> NewVMID=%d", req.SourceVM.VMID, req.NewVMID) return nil } @@ -175,39 +170,35 @@ func (s *ProxmoxService) cloneVMWithUPID(req VMCloneRequest) (string, error) { func (s *ProxmoxService) WaitForDisk(node string, vmID int, maxWait time.Duration) error { start := time.Now() - log.Printf("[kayhon] WaitForDisk START: Node=%s, VMID=%d, MaxWait=%s", node, vmID, maxWait) for time.Since(start) < maxWait { time.Sleep(2 * time.Second) configResp, err := s.getVMConfig(node, vmID) if err != nil { - log.Printf("[kayhon] WaitForDisk: Failed to get VM config for VMID=%d: %v (elapsed: %s)", vmID, err, time.Since(start)) continue } - log.Printf("[kayhon] WaitForDisk VM config for VMID=%d: Name=%s, HardDisk=%s, Lock=%s, Net0=%s, Net1=%s", - vmID, configResp.Name, configResp.HardDisk, configResp.Lock, configResp.Net0, configResp.Net1) + log.Printf("%+v", configResp) if configResp.HardDisk != "" && configResp.Name != "" { - log.Printf("[kayhon] WaitForDisk: VM config has HardDisk and Name, checking storage content for VMID=%d", vmID) + log.Printf("/nodes/%s/storage/%s/content?vmid=%d", s.Config.Nodes[0], s.Config.StorageID, vmID) pendingReq := tools.ProxmoxAPIRequest{ Method: "GET", Endpoint: fmt.Sprintf("/nodes/%s/storage/%s/content?vmid=%d", s.Config.Nodes[0], s.Config.StorageID, vmID), } + log.Printf("%+v", pendingReq) + var diskResponse []PendingDiskResponse err := s.RequestHelper.MakeRequestAndUnmarshal(pendingReq, &diskResponse) if err != nil || len(diskResponse) == 0 { - log.Printf("[kayhon] WaitForDisk: Error or empty disk response for VMID=%d: err=%v, count=%d", vmID, err, len(diskResponse)) + log.Printf("Error retrieving pending disk info for VMID %d on node %s: %v", vmID, node, err) continue } - log.Printf("[kayhon] WaitForDisk: Disk response for VMID=%d: %d disk(s)", vmID, len(diskResponse)) - for i, disk := range diskResponse { - log.Printf("[kayhon] Disk %d: Used=%d, Size=%d", i, disk.Used, disk.Size) - } + log.Printf("%+v", diskResponse) // Iterate through all disks, if all have valid Used and Size (not 0) consider available allAvailable := true @@ -219,16 +210,11 @@ func (s *ProxmoxService) WaitForDisk(node string, vmID int, maxWait time.Duratio } if allAvailable { - log.Printf("[kayhon] WaitForDisk READY: VMID=%d, all disks available (elapsed: %s)", vmID, time.Since(start)) return nil // Disk is available } - log.Printf("[kayhon] WaitForDisk: Not all disks ready for VMID=%d, retrying...", vmID) - } else { - log.Printf("[kayhon] WaitForDisk: VM config incomplete for VMID=%d (HardDisk=%q, Name=%q), retrying...", vmID, configResp.HardDisk, configResp.Name) } } - log.Printf("[kayhon] WaitForDisk TIMEOUT: VMID=%d after %s", vmID, maxWait) return fmt.Errorf("timeout waiting for VM disks to become available") } @@ -278,29 +264,23 @@ func (s *ProxmoxService) GetNextVMIDs(num int) ([]int, error) { func (s *ProxmoxService) WaitForLock(node string, vmID int) error { timeout := 1 * time.Minute start := time.Now() - log.Printf("[kayhon] WaitForLock START: Node=%s, VMID=%d, Timeout=%s", node, vmID, timeout) for time.Since(start) < timeout { config, err := s.getVMConfig(node, vmID) if err != nil { - log.Printf("[kayhon] WaitForLock: Failed to get VM config for VMID=%d: %v", vmID, err) time.Sleep(5 * time.Second) continue } - log.Printf("[kayhon] WaitForLock VM config for VMID=%d: Name=%s, Lock=%s, HardDisk=%s, Net0=%s, Net1=%s", - vmID, config.Name, config.Lock, config.HardDisk, config.Net0, config.Net1) + log.Printf("VM %d lock status: '%s'", vmID, config.Lock) if config.Lock == "" { - log.Printf("[kayhon] WaitForLock CLEARED: VMID=%d (elapsed: %s)", vmID, time.Since(start)) return nil // No lock } - log.Printf("[kayhon] WaitForLock: VMID=%d still locked (lock=%s), waiting...", vmID, config.Lock) time.Sleep(5 * time.Second) } - log.Printf("[kayhon] WaitForLock TIMEOUT: VMID=%d after %s", vmID, timeout) return fmt.Errorf("timeout waiting for VM lock to be cleared") } @@ -329,27 +309,21 @@ func (s *ProxmoxService) vmAction(action string, node string, vmID int) error { func (s *ProxmoxService) waitForStatus(targetStatus string, node string, vmID int) error { timeout := 2 * time.Minute start := time.Now() - log.Printf("[kayhon] waitForStatus START: Node=%s, VMID=%d, TargetStatus=%s, Timeout=%s", node, vmID, targetStatus, timeout) for time.Since(start) < timeout { currentStatus, err := s.getVMStatus(node, vmID) if err != nil { - log.Printf("[kayhon] waitForStatus: Failed to get status for VMID=%d: %v", vmID, err) time.Sleep(5 * time.Second) continue } - log.Printf("[kayhon] waitForStatus: VMID=%d currentStatus=%s, targetStatus=%s", vmID, currentStatus, targetStatus) - if currentStatus == targetStatus { - log.Printf("[kayhon] waitForStatus REACHED: VMID=%d is now %s (elapsed: %s)", vmID, targetStatus, time.Since(start)) return nil } time.Sleep(5 * time.Second) } - log.Printf("[kayhon] waitForStatus TIMEOUT: VMID=%d never reached %s after %s", vmID, targetStatus, timeout) return fmt.Errorf("timeout waiting for VM to be %s", targetStatus) } @@ -382,12 +356,9 @@ func (s *ProxmoxService) getVMConfig(node string, VMID int) (*VirtualResourceCon var config VirtualResourceConfig if err := s.RequestHelper.MakeRequestAndUnmarshal(configReq, &config); err != nil { - log.Printf("[kayhon] getVMConfig FAILED: Node=%s, VMID=%d, error: %v", node, VMID, err) return nil, fmt.Errorf("failed to get VM config: %w", err) } - log.Printf("[kayhon] getVMConfig: Node=%s, VMID=%d -> Name=%s, HardDisk=%s, Lock=%s, Net0=%s, Net1=%s", - node, VMID, config.Name, config.HardDisk, config.Lock, config.Net0, config.Net1) return &config, nil } From 1a25174d67be88a143d49831c39b663d9e7b33b9 Mon Sep 17 00:00:00 2001 From: xdkaine <55013938+xdkaine@users.noreply.github.com> Date: Mon, 23 Feb 2026 17:03:31 -0800 Subject: [PATCH 4/4] missing argument in setpodvnet --- internal/cloning/cloning_service.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/cloning/cloning_service.go b/internal/cloning/cloning_service.go index c97a8b4..be31fd6 100644 --- a/internal/cloning/cloning_service.go +++ b/internal/cloning/cloning_service.go @@ -291,7 +291,7 @@ func (cs *CloningService) CloneTemplate(req CloneRequest) error { for _, target := range req.Targets { vnetName := fmt.Sprintf("kamino%d", target.PodNumber) log.Printf("Setting VNet %s for pool %s (target: %s)", vnetName, target.PoolName, target.Name) - err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName) + err = cs.ProxmoxService.SetPodVnet(target.PoolName, vnetName, target.VMIDs[0]) if err != nil { errors = append(errors, fmt.Sprintf("failed to update pod vnet for %s: %v", target.Name, err)) }