Reduce logging for the NVIDIA Container runtime

This change moves most of the logging for the NVIDIA Container runtime
from Info to Debug or Trace -- especially in the case where no
modifications are requried.

This removes execessive logging.

Signed-off-by: Evan Lezar <elezar@nvidia.com>

CHANGELOG.md

@@ -8,6 +8,7 @@
 * Ensure that `nvidia-ctk cdi transform` creates specs with world-readable permissions.
 * Remove provenance information from published images.
 * Fix bug in processing of `--log=` argument of `nvidia-container-runtime`.
+* Reduce verbosity of logging in the NVIDIA Container Runtime especially for non-`create` commands.
 
 ## v1.15.0
 

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_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")
-	} else {
-		r.logger.Infof("No modification of OCI specification required")
+		r.logger.Debugf("Applied required modification to OCI specification")
 	}
 
-	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"
 )
 
@@ -66,23 +66,18 @@ func (r rt) Run(argv []string) (rerr error) {
 	if r.modeOverride != "" {
 		cfg.NVIDIAContainerRuntimeConfig.Mode = r.modeOverride
 	}
-	cfg.NVIDIACTKConfig.Path = config.ResolveNVIDIACTKPath(r.logger, cfg.NVIDIACTKConfig.Path)
-	cfg.NVIDIAContainerRuntimeHookConfig.Path = config.ResolveNVIDIAContainerRuntimeHookPath(r.logger, cfg.NVIDIAContainerRuntimeHookConfig.Path)
-
-	// Print the config to the output.
-	configJSON, err := json.MarshalIndent(cfg, "", "  ")
-	if err == nil {
-		r.logger.Infof("Running with config:\n%v", string(configJSON))
-	} else {
-		r.logger.Infof("Running with config:\n%+v", cfg)
-	}
+	cfg.NVIDIACTKConfig.Path = config.ResolveNVIDIACTKPath(&logger.NullLogger{}, cfg.NVIDIACTKConfig.Path)
+	cfg.NVIDIAContainerRuntimeHookConfig.Path = config.ResolveNVIDIAContainerRuntimeHookPath(&logger.NullLogger{}, cfg.NVIDIAContainerRuntimeHookConfig.Path)
+
+	// Log the config at Trace to allow for debugging if required.
+	r.logger.Tracef("Running with config: %+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,