From 697988e7e4bad50a480f8e5a3d7511910a3a6b21 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Christoph=20B=C3=B6hmwalder?= Date: Tue, 19 Dec 2023 16:29:19 +0100 Subject: [PATCH] cmd: log less on info level Currently, virter logs the same 8 (ish) lines every time a VM is started, and another few when it is removed. This is redundant information in almost all cases, so it really belongs in the Debug level. --- cmd/config.go | 2 +- internal/virter/dhcp.go | 4 ++-- internal/virter/vm.go | 30 +++++++++++++++--------------- 3 files changed, 18 insertions(+), 18 deletions(-) diff --git a/cmd/config.go b/cmd/config.go index 456f994..1196a32 100644 --- a/cmd/config.go +++ b/cmd/config.go @@ -149,7 +149,7 @@ func initConfig() { if newPath == "" { newPath = filepath.Join(configPath(), "virter.toml") } - log.Print("Config file does not exist, creating default: ", newPath) + log.Info("Config file does not exist, creating default: ", newPath) err := writeDefaultConfig(newPath) if err != nil { diff --git a/internal/virter/dhcp.go b/internal/virter/dhcp.go index 5fbd6e7..6f8cf1d 100644 --- a/internal/virter/dhcp.go +++ b/internal/virter/dhcp.go @@ -31,7 +31,7 @@ func (v *Virter) AddDHCPHost(mac string, id uint) error { return fmt.Errorf("failed to compute IP for network: %w", err) } - log.Printf("Add DHCP entry from %v to %v", mac, ip) + log.WithField("from", mac).WithField("to", ip).Debug("Add DHCP entry") err = v.patchedNetworkUpdate( v.provisionNetwork, libvirt.NetworkUpdateCommandAddLast, @@ -213,7 +213,7 @@ func (v *Virter) removeDomainDHCP(domain libvirt.Domain, removeDHCPEntries bool) func (v *Virter) removeDHCPEntries(network libvirt.Network, mac string, ips []string) error { for _, ip := range ips { - log.Printf("Remove DHCP entry from %v to %v", mac, ip) + log.WithField("from", mac).WithField("to", ip).Debug("Remove DHCP entry") err := v.patchedNetworkUpdate( network, libvirt.NetworkUpdateCommandDelete, diff --git a/internal/virter/vm.go b/internal/virter/vm.go index f454ffc..cf6bafd 100644 --- a/internal/virter/vm.go +++ b/internal/virter/vm.go @@ -130,7 +130,7 @@ func (v *Virter) VMRun(vmConfig VMConfig) error { } // end checks - log.Print("Create host key") + log.Debug("Create host key") hostkey, err := sshkeys.NewRSAHostKey() if err != nil { return fmt.Errorf("could not create new host key: %w", err) @@ -148,26 +148,26 @@ func (v *Virter) VMRun(vmConfig VMConfig) error { log.Debugf("Using domain XML: %s", vmXML) - log.Print("Define VM") + log.Debug("Define VM") d, err := v.libvirt.DomainDefineXML(vmXML) if err != nil { return fmt.Errorf("could not define domain: %w", err) } - log.Print("Create boot volume") + log.Debug("Create boot volume") _, err = v.ImageSpawn(vmConfig.Name, v.provisionStoragePool, vmConfig.Image, vmConfig.BootCapacityKiB) if err != nil { return err } - log.Print("Create cloud-init volume") + log.Debug("Create cloud-init volume") _, err = v.createCIData(vmConfig, hostkey) if err != nil { return err } for _, d := range vmConfig.Disks { - log.Printf("Create volume '%s'", d.GetName()) + log.WithField("name", d.GetName()).Debug("Create volume") pool, err := v.lookupPool(d.GetPool()) if err != nil { return fmt.Errorf("failed to lookup libvirt pool %s: %w", d.GetPool(), err) @@ -188,7 +188,7 @@ func (v *Virter) VMRun(vmConfig VMConfig) error { } } - log.Print("Start VM") + log.Debug("Start VM") err = v.libvirt.DomainCreate(d) if err != nil { return fmt.Errorf("could not create (start) domain: %w", err) @@ -245,7 +245,7 @@ func (v *Virter) WaitVmReady(ctx context.Context, shellClientBuilder ShellClient return nil } - log.Print("Wait for VM to get ready") + log.Debug("Wait for VM to get ready") // Using ActualTime breaks the expectation of the unit tests // that this code does not sleep, but we work around that by @@ -254,7 +254,7 @@ func (v *Virter) WaitVmReady(ctx context.Context, shellClientBuilder ShellClient return fmt.Errorf("VM not ready: %w", err) } - log.Print("Successfully connected to ready VM") + log.Debug("Successfully connected to ready VM") return nil } @@ -283,7 +283,7 @@ func (v *Virter) VMRm(vmName string, removeDHCPEntries bool, removeBoot bool) er // it is active (running). And only if it is persistent, otherwise the // domain is gone and we cannot query what resources it depended on. if active > 0 && persistent > 0 { - log.Print("Stop VM") + log.Debug("Stop VM") err = v.libvirt.DomainDestroy(domain) if err != nil { return fmt.Errorf("could not destroy domain: %w", err) @@ -318,14 +318,14 @@ func (v *Virter) VMRm(vmName string, removeDHCPEntries bool, removeBoot bool) er } if persistent > 0 { - log.Print("Undefine VM") + log.Debug("Undefine VM") err = v.libvirt.DomainUndefineFlags(domain, libvirt.DomainUndefineNvram) if err != nil { return fmt.Errorf("could not undefine domain: %w", err) } } else if active > 0 { // Stop the VM if we did not stop it previously. - log.Print("Stop VM") + log.Debug("Stop VM") err = v.libvirt.DomainDestroy(domain) if err != nil { return fmt.Errorf("could not destroy domain: %w", err) @@ -370,7 +370,7 @@ func (v *Virter) rmSnapshots(domain libvirt.Domain) error { } for _, snapshot := range snapshots { - log.Printf("Delete snapshot %v", snapshot.Name) + log.WithField("name", snapshot.Name).Debug("Delete snapshot") err = v.libvirt.DomainSnapshotDelete(snapshot, 0) if err != nil { return fmt.Errorf("could not delete snapshot: %w", err) @@ -443,14 +443,14 @@ func (v *Virter) vmShutdown(ctx context.Context, afterNotifier AfterNotifier, sh } if active != 0 { - log.Printf("Shut down VM") + log.Debug("Shut down VM") err = v.libvirt.DomainShutdown(domain) if err != nil { return fmt.Errorf("could not shut down domain: %w", err) } - log.Printf("Wait for VM to stop") + log.Debug("Wait for VM to stop") } timeout := afterNotifier.After(shutdownTimeout) @@ -703,7 +703,7 @@ func (v *Virter) VMExecRsync(ctx context.Context, copier netcopy.NetworkCopier, g, ctx := errgroup.WithContext(ctx) for _, vmName := range vmNames { vmName := vmName - log.Printf(`Copying files via rsync: %s to %s on %s`, rsyncStep.Source, rsyncStep.Dest, vmName) + log.Debugf(`Copying files via rsync: %s to %s on %s`, rsyncStep.Source, rsyncStep.Dest, vmName) g.Go(func() error { dest := fmt.Sprintf("%s:%s", vmName, rsyncStep.Dest) return v.VMExecCopy(ctx, copier, files, dest)