Merge pull request #560 from elezar/reduce-logging

Reduce logging verbosity in NVIDIA Container Runtime

internal/logger/api.go

@@ -24,4 +24,5 @@ type Interface interface {
 	Infof(string, ...interface{})
 	Warning(...interface{})
 	Warningf(string, ...interface{})
+	Tracef(string, ...interface{})
 }

internal/logger/lib.go

@@ -45,3 +45,6 @@ func (l *NullLogger) Warning(...interface{}) {}
 
 // Warningf is a no-op for the null logger
 func (l *NullLogger) Warningf(string, ...interface{}) {}
+
+// Tracef is a no-op for the null logger
+func (l *NullLogger) Tracef(string, ...interface{}) {}

internal/oci/runtime.go

@@ -16,10 +16,11 @@
 
 package oci
 
-//go:generate moq -stub -out runtime_mock.go . Runtime
-
 // Runtime is an interface for a runtime shim. The Exec method accepts a list
 // of command line arguments, and returns an error / nil.
+//
+//go:generate moq -rm -stub -out runtime_mock.go . Runtime
 type Runtime interface {
 	Exec([]string) error
+	String() string
 }

internal/oci/runtime_low_level.go

@@ -31,8 +31,6 @@ func NewLowLevelRuntime(logger logger.Interface, candidates []string) (Runtime,
 	if err != nil {
 		return nil, fmt.Errorf("error locating runtime: %v", err)
 	}
-
-	logger.Infof("Using low-level runtime %v", runtimePath)
 	return NewRuntimeForPath(logger, runtimePath)
 }
 
@@ -45,13 +43,12 @@ func findRuntime(logger logger.Interface, candidates []string) (string, error) {
 
 	locator := lookup.NewExecutableLocator(logger, "/")
 	for _, candidate := range candidates {
-		logger.Debugf("Looking for runtime binary '%v'", candidate)
+		logger.Tracef("Looking for runtime binary '%v'", candidate)
 		targets, err := locator.Locate(candidate)
 		if err == nil && len(targets) > 0 {
-			logger.Debugf("Found runtime binary '%v'", targets)
+			logger.Tracef("Found runtime binary '%v'", targets)
 			return targets[0], nil
 		}
-		logger.Debugf("Runtime binary '%v' not found: %v (targets=%v)", candidate, err, targets)
 	}
 
 	return "", fmt.Errorf("no runtime binary found from candidate list: %v", candidates)

internal/oci/runtime_mock.go

@@ -20,6 +20,9 @@ var _ Runtime = &RuntimeMock{}
 //			ExecFunc: func(strings []string) error {
 //				panic("mock out the Exec method")
 //			},
+//			StringFunc: func() string {
+//				panic("mock out the String method")
+//			},
 //		}
 //
 //		// use mockedRuntime in code that requires Runtime
@@ -30,6 +33,9 @@ type RuntimeMock struct {
 	// ExecFunc mocks the Exec method.
 	ExecFunc func(strings []string) error
 
+	// StringFunc mocks the String method.
+	StringFunc func() string
+
 	// calls tracks calls to the methods.
 	calls struct {
 		// Exec holds details about calls to the Exec method.
@@ -37,8 +43,12 @@ type RuntimeMock struct {
 			// Strings is the strings argument value.
 			Strings []string
 		}
+		// String holds details about calls to the String method.
+		String []struct {
+		}
 	}
-	lockExec sync.RWMutex
+	lockExec   sync.RWMutex
+	lockString sync.RWMutex
 }
 
 // Exec calls ExecFunc.
@@ -75,3 +85,33 @@ func (mock *RuntimeMock) ExecCalls() []struct {
 	mock.lockExec.RUnlock()
 	return calls
 }
+
+// String calls StringFunc.
+func (mock *RuntimeMock) String() string {
+	callInfo := struct {
+	}{}
+	mock.lockString.Lock()
+	mock.calls.String = append(mock.calls.String, callInfo)
+	mock.lockString.Unlock()
+	if mock.StringFunc == nil {
+		var (
+			sOut string
+		)
+		return sOut
+	}
+	return mock.StringFunc()
+}
+
+// StringCalls gets all the calls that were made to String.
+// Check the length with:
+//
+//	len(mockedRuntime.StringCalls())
+func (mock *RuntimeMock) StringCalls() []struct {
+} {
+	var calls []struct {
+	}
+	mock.lockString.RLock()
+	calls = mock.calls.String
+	mock.lockString.RUnlock()
+	return calls
+}

internal/oci/runtime_modifier.go

@@ -35,7 +35,7 @@ var _ Runtime = (*modifyingRuntimeWrapper)(nil)
 // before invoking the wrapped runtime. If the modifier is nil, the input runtime is returned.
 func NewModifyingRuntimeWrapper(logger logger.Interface, runtime Runtime, spec Spec, modifier SpecModifier) Runtime {
 	if modifier == nil {
-		logger.Infof("Using low-level runtime with no modification")
+		logger.Tracef("Using low-level runtime with no modification")
 		return runtime
 	}
 
@@ -52,16 +52,15 @@ func NewModifyingRuntimeWrapper(logger logger.Interface, runtime Runtime, spec S
 // into the wrapped runtime.
 func (r *modifyingRuntimeWrapper) Exec(args []string) error {
 	if HasCreateSubcommand(args) {
+		r.logger.Debugf("Create command detected; applying OCI specification modifications")
 		err := r.modify()
 		if err != nil {
-			return fmt.Errorf("could not apply required modification to OCI specification: %v", err)
+			return fmt.Errorf("could not apply required modification to OCI specification: %w", err)
 		}
-		r.logger.Infof("Applied required modification to OCI specification")
+		r.logger.Debugf("Applied required modification to OCI specification")
-	} else {
-		r.logger.Infof("No modification of OCI specification required")
 	}
 
-	r.logger.Infof("Forwarding command to runtime")
+	r.logger.Debugf("Forwarding command to runtime %v", r.runtime.String())
 	return r.runtime.Exec(args)
 }
 
@@ -83,3 +82,8 @@ func (r *modifyingRuntimeWrapper) modify() error {
 	}
 	return nil
 }
+
+// String returns a string representation of the runtime.
+func (r *modifyingRuntimeWrapper) String() string {
+	return fmt.Sprintf("modify on-create and forward to %s", r.runtime.String())
+}

internal/oci/runtime_path.go

@@ -63,3 +63,8 @@ func (s pathRuntime) Exec(args []string) error {
 
 	return s.execRuntime.Exec(runtimeArgs)
 }
+
+// String returns the path to the specified runtime as the string representation.
+func (s pathRuntime) String() string {
+	return s.path
+}

internal/oci/runtime_syscall_exec.go

@@ -37,3 +37,7 @@ func (r syscallExec) Exec(args []string) error {
 	// err is nil or not.
 	return fmt.Errorf("unexpected return from exec '%v'", args[0])
 }
+
+func (r syscallExec) String() string {
+	return "exec"
+}

internal/runtime/runtime.go

@@ -17,7 +17,6 @@
 package runtime
 
 import (
-	"encoding/json"
 	"errors"
 	"fmt"
 	"strings"
@@ -26,6 +25,7 @@ import (
 
 	"github.com/NVIDIA/nvidia-container-toolkit/internal/config"
 	"github.com/NVIDIA/nvidia-container-toolkit/internal/info"
+	"github.com/NVIDIA/nvidia-container-toolkit/internal/logger"
 	"github.com/NVIDIA/nvidia-container-toolkit/internal/lookup/root"
 )
 
@@ -67,23 +67,18 @@ func (r rt) Run(argv []string) (rerr error) {
 		cfg.NVIDIAContainerRuntimeConfig.Mode = r.modeOverride
 	}
 	//nolint:staticcheck  // TODO(elezar): We should swith the nvidia-container-runtime from using nvidia-ctk to using nvidia-cdi-hook.
-	cfg.NVIDIACTKConfig.Path = config.ResolveNVIDIACTKPath(r.logger, cfg.NVIDIACTKConfig.Path)
+	cfg.NVIDIACTKConfig.Path = config.ResolveNVIDIACTKPath(&logger.NullLogger{}, cfg.NVIDIACTKConfig.Path)
-	cfg.NVIDIAContainerRuntimeHookConfig.Path = config.ResolveNVIDIAContainerRuntimeHookPath(r.logger, cfg.NVIDIAContainerRuntimeHookConfig.Path)
+	cfg.NVIDIAContainerRuntimeHookConfig.Path = config.ResolveNVIDIAContainerRuntimeHookPath(&logger.NullLogger{}, cfg.NVIDIAContainerRuntimeHookConfig.Path)
 
-	// Print the config to the output.
+	// Log the config at Trace to allow for debugging if required.
-	configJSON, err := json.MarshalIndent(cfg, "", "  ")
+	r.logger.Tracef("Running with config: %+v", cfg)
-	if err == nil {
-		r.logger.Infof("Running with config:\n%v", string(configJSON))
-	} else {
-		r.logger.Infof("Running with config:\n%+v", cfg)
-	}
 
 	driver := root.New(
 		root.WithLogger(r.logger),
 		root.WithDriverRoot(cfg.NVIDIAContainerCLIConfig.Root),
 	)
 
-	r.logger.Debugf("Command line arguments: %v", argv)
+	r.logger.Tracef("Command line arguments: %v", argv)
 	runtime, err := newNVIDIAContainerRuntime(r.logger, cfg, argv, driver)
 	if err != nil {
 		return fmt.Errorf("failed to create NVIDIA Container Runtime: %v", err)

internal/runtime/runtime_factory.go

@@ -35,8 +35,9 @@ func newNVIDIAContainerRuntime(logger logger.Interface, cfg *config.Config, argv
 		return nil, fmt.Errorf("error constructing low-level runtime: %v", err)
 	}
 
+	logger.Tracef("Using low-level runtime %v", lowLevelRuntime.String())
 	if !oci.HasCreateSubcommand(argv) {
-		logger.Debugf("Skipping modifier for non-create subcommand")
+		logger.Tracef("Skipping modifier for non-create subcommand")
 		return lowLevelRuntime, nil
 	}
 
@@ -50,7 +51,7 @@ func newNVIDIAContainerRuntime(logger logger.Interface, cfg *config.Config, argv
 		return nil, fmt.Errorf("failed to construct OCI spec modifier: %v", err)
 	}
 
-	// Create the wrapping runtime with the specified modifier
+	// Create the wrapping runtime with the specified modifier.
 	r := oci.NewModifyingRuntimeWrapper(
 		logger,
 		lowLevelRuntime,