Improve logging usage

The structured logger is good for producing comprehensive logs, however it is not that good for being used directly in the code. Let's introduce some changes that: - Make the code shorter, so it's easier to read. - Make the logging lines shorter, so the logging messages can be read without horizontal scrolling. - Reduce the chain of method calls so one can see easily also code other than logging in editors highlighting method calls. - Reduce code duplication. To not make logging too messy, methods for setting message levels are turned into terminal methods (and their formatting argument variants are introduced). Those methods are almost always used, so they can be used as such rather than using extra Msg method call. In rare cases when we don't want to use typical logging patterns, new Level method can be used. `logging' package is renamed to `log' and `Log' instance of DefaultLogger() is created to make log lines significantly shorter.
gilwoong-kang · Oct 23, 2017 · 0bf2021 · 0bf2021
1 parent 4e3ac72
commit 0bf2021
Show file tree

Hide file tree

Showing 43 changed files with 345 additions and 325 deletions.
diff --git a/cmd/virt-api/virt-api.go b/cmd/virt-api/virt-api.go
@@ -35,7 +35,7 @@ import (
 	"kubevirt.io/kubevirt/pkg/api/v1"
 	"kubevirt.io/kubevirt/pkg/healthz"
 	"kubevirt.io/kubevirt/pkg/kubecli"
-	"kubevirt.io/kubevirt/pkg/logging"
+	klog "kubevirt.io/kubevirt/pkg/log"
 	mime "kubevirt.io/kubevirt/pkg/rest"
 	"kubevirt.io/kubevirt/pkg/rest/endpoints"
 	"kubevirt.io/kubevirt/pkg/rest/filter"
@@ -153,7 +153,7 @@ func addInfoToSwaggerObject(swo *openapispec.Swagger) {
 }
 
 func main() {
-	logging.InitializeLogging("virt-api")
+	klog.InitializeLogging("virt-api")
 	swaggerui := flag.String("swagger-ui", "third_party/swagger-ui", "swagger-ui location")
 	host := flag.String("listen", "0.0.0.0", "Address and port where to listen on")
 	port := flag.Int("port", 8183, "Port to listen on")

diff --git a/cmd/virt-handler/virt-handler.go b/cmd/virt-handler/virt-handler.go
@@ -43,7 +43,7 @@ import (
 	configdisk "kubevirt.io/kubevirt/pkg/config-disk"
 	"kubevirt.io/kubevirt/pkg/controller"
 	"kubevirt.io/kubevirt/pkg/kubecli"
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 	registrydisk "kubevirt.io/kubevirt/pkg/registry-disk"
 	"kubevirt.io/kubevirt/pkg/service"
 	"kubevirt.io/kubevirt/pkg/virt-handler"
@@ -87,8 +87,8 @@ func newVirtHandlerApp(host *string, port *int, hostOverride *string, libvirtUri
 }
 
 func (app *virtHandlerApp) Run() {
-	log := logging.DefaultLogger()
-	log.Info().V(1).Log("hostname", app.HostOverride)
+	logger := log.Log
+	logger.V(1).Level(log.INFO).Log("hostname", app.HostOverride)
 
 	err := cloudinit.SetLocalDirectory(app.EphemeralDiskDir + "/cloud-init-data")
 	if err != nil {
@@ -103,7 +103,7 @@ func (app *virtHandlerApp) Run() {
 		for {
 			if res := libvirt.EventRunDefaultImpl(); res != nil {
 				// Report the error somehow or break the loop.
-				log.Error().Reason(res).Msg("Listening to libvirt events failed.")
+				logger.Reason(res).Error("Listening to libvirt events failed.")
 			}
 		}
 	}()
@@ -220,7 +220,7 @@ func (app *virtHandlerApp) Run() {
 }
 
 func main() {
-	logging.InitializeLogging("virt-handler")
+	log.InitializeLogging("virt-handler")
 	libvirt.EventRegisterDefaultImpl()
 	libvirtUri := flag.String("libvirt-uri", "qemu:///system", "Libvirt connection string.")
 	host := flag.String("listen", "0.0.0.0", "Address where to listen on")

diff --git a/cmd/virt-launcher/virt-launcher.go b/cmd/virt-launcher/virt-launcher.go
@@ -28,7 +28,7 @@ import (
 
 	"github.com/spf13/pflag"
 
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 	"kubevirt.io/kubevirt/pkg/virt-handler/virtwrap/isolation"
 	virtlauncher "kubevirt.io/kubevirt/pkg/virt-launcher"
 	watchdog "kubevirt.io/kubevirt/pkg/watchdog"
@@ -43,34 +43,34 @@ func markReady(readinessFile string) {
 		panic(err)
 	}
 	f.Close()
-	logging.DefaultLogger().Info().Msgf("Marked as ready")
+	log.Log.Info("Marked as ready")
 }
 
 func createSocket(virtShareDir string, namespace string, name string) net.Listener {
 	sockFile := isolation.SocketFromNamespaceName(virtShareDir, namespace, name)
 
 	err := os.MkdirAll(filepath.Dir(sockFile), 0755)
 	if err != nil {
-		logging.DefaultLogger().Reason(err).Error().Msgf("Could not create directory for socket.")
+		log.Log.Reason(err).Error("Could not create directory for socket.")
 		panic(err)
 	}
 
 	if err := os.RemoveAll(sockFile); err != nil {
-		logging.DefaultLogger().Reason(err).Error().Msgf("Could not clean up old socket for cgroup detection")
+		log.Log.Reason(err).Error("Could not clean up old socket for cgroup detection")
 		panic(err)
 	}
 	socket, err := net.Listen("unix", sockFile)
 
 	if err != nil {
-		logging.DefaultLogger().Reason(err).Error().Msgf("Could not create socket for cgroup detection.")
+		log.Log.Reason(err).Error("Could not create socket for cgroup detection.")
 		panic(err)
 	}
 
 	return socket
 }
 
 func main() {
-	logging.InitializeLogging("virt-launcher")
+	log.InitializeLogging("virt-launcher")
 	qemuTimeout := flag.Duration("qemu-timeout", defaultStartTimeout, "Amount of time to wait for qemu")
 	virtShareDir := flag.String("kubevirt-share-dir", "/var/run/kubevirt", "Shared directory between virt-handler and virt-launcher")
 	name := flag.String("name", "", "Name of the VM")
@@ -94,7 +94,7 @@ func main() {
 		panic(err)
 	}
 
-	logging.DefaultLogger().Info().Msgf("Watchdog file created at %s", watchdogFile)
+	log.Log.Infof("Watchdog file created at %s", watchdogFile)
 
 	stopChan := make(chan struct{})
 	defer close(stopChan)

diff --git a/cmd/virt-manifest/virt-manifest.go b/cmd/virt-manifest/virt-manifest.go
@@ -28,7 +28,7 @@ import (
 	"github.com/emicklei/go-restful"
 	"github.com/spf13/pflag"
 
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 	"kubevirt.io/kubevirt/pkg/service"
 	"kubevirt.io/kubevirt/pkg/virt-handler/virtwrap/cli"
 	"kubevirt.io/kubevirt/pkg/virt-manifest/rest"
@@ -47,36 +47,36 @@ func newVirtManifestApp(host *string, port *int, libvirtUri *string) *virtManife
 }
 
 func (app *virtManifestApp) Run() {
-	log := logging.DefaultLogger()
-	log.Info().Msg("Starting virt-manifest server")
+	logger := log.Log
+	logger.Info("Starting virt-manifest server")
 
-	log.Info().Msg("Connecting to libvirt")
+	logger.Info("Connecting to libvirt")
 
 	domainConn, err := cli.NewConnection(app.LibvirtUri, "", "", 60*time.Second)
 	if err != nil {
-		log.Error().Reason(err).Msg("cannot connect to libvirt")
+		logger.Reason(err).Error("cannot connect to libvirt")
 		panic(fmt.Sprintf("failed to connect to libvirt: %v", err))
 	}
 	defer domainConn.Close()
 
-	log.Info().Msg("Connected to libvirt")
+	logger.Info("Connected to libvirt")
 
 	ws, err := rest.ManifestService(domainConn)
 	if err != nil {
-		log.Error().Reason(err).Msg("Unable to create REST server.")
+		logger.Reason(err).Error("Unable to create REST server.")
 	}
 
 	restful.DefaultContainer.Add(ws)
 	server := &http.Server{Addr: app.Service.Address(), Handler: restful.DefaultContainer}
-	log.Info().Msg("Listening for client connections")
+	logger.Info("Listening for client connections")
 
 	if err := server.ListenAndServe(); err != nil {
-		log.Error().Reason(err).Msg("Unable to start web server.")
+		logger.Reason(err).Error("Unable to start web server.")
 	}
 }
 
 func main() {
-	logging.InitializeLogging("virt-manifest")
+	log.InitializeLogging("virt-manifest")
 	libvirtUri := flag.String("libvirt-uri", "qemu:///system", "Libvirt connection string.")
 	listen := flag.String("listen", "0.0.0.0", "Address where to listen on")
 	port := flag.Int("port", 8186, "Port to listen on")

diff --git a/pkg/cloud-init/cloud-init.go b/pkg/cloud-init/cloud-init.go
@@ -35,7 +35,7 @@ import (
 	"kubevirt.io/kubevirt/pkg/api/v1"
 	diskutils "kubevirt.io/kubevirt/pkg/ephemeral-disk-utils"
 	"kubevirt.io/kubevirt/pkg/kubecli"
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 	"kubevirt.io/kubevirt/pkg/precond"
 )
 
@@ -68,7 +68,7 @@ func defaultIsoFunc(isoOutFile string, inFiles []string) error {
 
 	err := cmd.Start()
 	if err != nil {
-		logging.DefaultLogger().V(2).Error().Reason(err).Msg(fmt.Sprintf("genisoimage cmd failed to start while generating iso file %s", isoOutFile))
+		log.Log.V(2).Reason(err).Errorf("genisoimage cmd failed to start while generating iso file %s", isoOutFile)
 		return err
 	}
 
@@ -80,11 +80,11 @@ func defaultIsoFunc(isoOutFile string, inFiles []string) error {
 	for {
 		select {
 		case <-timeout:
-			logging.DefaultLogger().V(2).Error().Msg(fmt.Sprintf("Timed out generating cloud-init iso at path %s", isoOutFile))
+			log.Log.V(2).Errorf("Timed out generating cloud-init iso at path %s", isoOutFile)
 			cmd.Process.Kill()
 		case err := <-done:
 			if err != nil {
-				logging.DefaultLogger().V(2).Error().Reason(err).Msg(fmt.Sprintf("genisoimage returned non-zero exit code while generating iso file %s", isoOutFile))
+				log.Log.V(2).Reason(err).Errorf("genisoimage returned non-zero exit code while generating iso file %s", isoOutFile)
 				return err
 			}
 			return nil
@@ -280,7 +280,7 @@ func GenerateLocalData(domain string, namespace string, spec *v1.CloudInitSpec)
 	domainBasePath := GetDomainBasePath(domain, namespace)
 	err = os.MkdirAll(domainBasePath, 0755)
 	if err != nil {
-		logging.DefaultLogger().V(2).Error().Reason(err).Msg(fmt.Sprintf("unable to create cloud-init base path %s", domainBasePath))
+		log.Log.V(2).Reason(err).Errorf("unable to create cloud-init base path %s", domainBasePath)
 		return err
 	}
 
@@ -343,12 +343,12 @@ func GenerateLocalData(domain string, namespace string, spec *v1.CloudInitSpec)
 			err = os.Rename(isoStaging, iso)
 			if err != nil {
 				// This error is not something we need to block iso creation for.
-				logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("Cloud-init failed to rename file %s to %s", isoStaging, iso))
+				log.Log.Reason(err).Errorf("Cloud-init failed to rename file %s to %s", isoStaging, iso)
 				return err
 			}
 		}
 
-		logging.DefaultLogger().V(2).Info().Msg(fmt.Sprintf("generated nocloud iso file %s", iso))
+		log.Log.V(2).Infof("generated nocloud iso file %s", iso)
 	}
 	return nil
 }

diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go
@@ -35,7 +35,7 @@ import (
 	"fmt"
 
 	"kubevirt.io/kubevirt/pkg/api/v1"
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 )
 
 const (
@@ -71,7 +71,7 @@ func NewListWatchFromClient(c cache.Getter, resource string, namespace string, f
 
 func HandlePanic() {
 	if r := recover(); r != nil {
-		logging.DefaultLogger().Critical().Log("stacktrace", debug.Stack(), "msg", r)
+		log.Log.Level(log.CRITICAL).Log("stacktrace", debug.Stack(), "msg", r)
 	}
 }
 
@@ -161,14 +161,14 @@ func Dequeue(s cache.Store, w workqueue.RateLimitingInterface, dispatch Controll
 func (c *Controller) Run(threadiness int, stopCh chan struct{}) {
 	defer HandlePanic()
 	defer c.queue.ShutDown()
-	logging.DefaultLogger().Info().Msg("Starting controller.")
+	log.Log.Info("Starting controller.")
 
 	for i := 0; i < threadiness; i++ {
 		go wait.Until(c.runWorker, time.Second, stopCh)
 	}
 
 	<-stopCh
-	logging.DefaultLogger().Info().Msg("Stopping controller.")
+	log.Log.Info("Stopping controller.")
 }
 
 func (c *Controller) StartInformer(stopCh chan struct{}) {

diff --git a/pkg/controller/virtinformers.go b/pkg/controller/virtinformers.go
@@ -33,7 +33,7 @@ import (
 	"kubevirt.io/kubevirt/pkg/kubecli"
 
 	kubev1 "kubevirt.io/kubevirt/pkg/api/v1"
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 )
 
 type newSharedInformer func() cache.SharedIndexInformer
@@ -83,10 +83,10 @@ func (f *kubeInformerFactory) Start(stopCh <-chan struct{}) {
 	for name, informer := range f.informers {
 		if f.startedInformers[name] {
 			// skip informers that have already started.
-			logging.DefaultLogger().Info().Msgf("SKIPPING informer %s", name)
+			log.Log.Infof("SKIPPING informer %s", name)
 			continue
 		}
-		logging.DefaultLogger().Info().Msgf("STARTING informer %s", name)
+		log.Log.Infof("STARTING informer %s", name)
 		go informer.Run(stopCh)
 		f.startedInformers[name] = true
 	}

diff --git a/pkg/ephemeral-disk-utils/utils.go b/pkg/ephemeral-disk-utils/utils.go
@@ -22,7 +22,6 @@ package ephemeraldiskutils
 import (
 	"bytes"
 	"crypto/md5"
-	"fmt"
 	"io"
 	"os"
 	"os/user"
@@ -31,15 +30,15 @@ import (
 	"strings"
 
 	"kubevirt.io/kubevirt/pkg/api/v1"
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 )
 
 func RemoveFile(path string) error {
 	err := os.Remove(path)
 	if err != nil && os.IsNotExist(err) {
 		return nil
 	} else if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("failed to remove cloud-init temporary data file %s", path))
+		log.Log.Reason(err).Errorf("failed to remove cloud-init temporary data file %s", path)
 		return err
 	}
 	return nil
@@ -77,19 +76,19 @@ func Md5CheckSum(filePath string) ([]byte, error) {
 func SetFileOwnership(username string, file string) error {
 	usrObj, err := user.Lookup(username)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("unable to look up username %s", username))
+		log.Log.Reason(err).Errorf("unable to look up username %s", username)
 		return err
 	}
 
 	uid, err := strconv.Atoi(usrObj.Uid)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("unable to find uid for username %s", username))
+		log.Log.Reason(err).Errorf("unable to find uid for username %s", username)
 		return err
 	}
 
 	gid, err := strconv.Atoi(usrObj.Gid)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("unable to find gid for username %s", username))
+		log.Log.Reason(err).Errorf("unable to find gid for username %s", username)
 		return err
 	}
 
@@ -99,28 +98,28 @@ func SetFileOwnership(username string, file string) error {
 func FilesAreEqual(path1 string, path2 string) (bool, error) {
 	exists, err := FileExists(path1)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("unexpected error encountered while attempting to determine if %s exists", path1))
+		log.Log.Reason(err).Errorf("unexpected error encountered while attempting to determine if %s exists", path1)
 		return false, err
 	} else if exists == false {
 		return false, nil
 	}
 
 	exists, err = FileExists(path2)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("unexpected error encountered while attempting to determine if %s exists", path2))
+		log.Log.Reason(err).Errorf("unexpected error encountered while attempting to determine if %s exists", path2)
 		return false, err
 	} else if exists == false {
 		return false, nil
 	}
 
 	sum1, err := Md5CheckSum(path1)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("calculating md5 checksum failed for %s", path1))
+		log.Log.Reason(err).Errorf("calculating md5 checksum failed for %s", path1)
 		return false, err
 	}
 	sum2, err := Md5CheckSum(path2)
 	if err != nil {
-		logging.DefaultLogger().Error().Reason(err).Msg(fmt.Sprintf("calculating md5 checksum failed for %s", path2))
+		log.Log.Reason(err).Errorf("calculating md5 checksum failed for %s", path2)
 		return false, err
 	}
 

diff --git a/pkg/inotify-informer/inotify.go b/pkg/inotify-informer/inotify.go
@@ -32,7 +32,7 @@ import (
 	"k8s.io/apimachinery/pkg/watch"
 	"k8s.io/client-go/tools/cache"
 
-	"kubevirt.io/kubevirt/pkg/logging"
+	"kubevirt.io/kubevirt/pkg/log"
 	"kubevirt.io/kubevirt/pkg/virt-handler/virtwrap/api"
 )
 
@@ -128,7 +128,7 @@ func (d *DirectoryListWatcher) startBackground() error {
 				if sendEvent {
 					namespace, name, err := splitFileNamespaceName(event.Name)
 					if err != nil {
-						logging.DefaultLogger().Error().Reason(err).Msg("Invalid content detected, ignoring and continuing.")
+						log.Log.Reason(err).Error("Invalid content detected, ignoring and continuing.")
 						continue
 					}
 					d.eventChan <- watch.Event{Type: e, Object: api.NewMinimalDomainWithNS(namespace, name)}
@@ -172,7 +172,7 @@ func (d *DirectoryListWatcher) List(options v1.ListOptions) (runtime.Object, err
 	for _, file := range files {
 		namespace, name, err := splitFileNamespaceName(file.Name())
 		if err != nil {
-			logging.DefaultLogger().Error().Reason(err).Msg("Invalid content detected, ignoring and continuing.")
+			log.Log.Reason(err).Error("Invalid content detected, ignoring and continuing.")
 			continue
 		}
 		domainList.Items = append(domainList.Items, *api.NewMinimalDomainWithNS(namespace, name))