Simplify CNI logging config (#51074)

* Fix #50958 Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io> * Relnote Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io> * Fixup Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io> * Fix tests Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io> * 2 scopes - plugin and agent Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io> --------- Signed-off-by: Benjamin Leggett <benjamin.leggett@solo.io>
istio · May 21, 2024 · 901a523 · 901a523
1 parent a21114d
commit 901a523
Show file tree

Hide file tree

Showing 33 changed files with 68 additions and 60 deletions.
diff --git a/cni/pkg/cmd/root.go b/cni/pkg/cmd/root.go
@@ -34,13 +34,14 @@ import (
 	"istio.io/istio/pkg/collateral"
 	"istio.io/istio/pkg/ctrlz"
 	"istio.io/istio/pkg/env"
-	"istio.io/istio/pkg/log"
+	istiolog "istio.io/istio/pkg/log"
 	"istio.io/istio/pkg/version"
 	iptables "istio.io/istio/tools/istio-iptables/pkg/constants"
 )
 
 var (
-	logOptions   = log.DefaultOptions()
+	logOptions   = istiolog.DefaultOptions()
+	log          = istiolog.RegisterScope(constants.CNIAgentLogScope, "CNI agent")
 	ctrlzOptions = func() *ctrlz.Options {
 		o := ctrlz.DefaultOptions()
 		o.EnablePprof = true
@@ -53,7 +54,7 @@ var rootCmd = &cobra.Command{
 	Short:        "Install and configure Istio CNI plugin on a node, detect and repair pod which is broken by race condition.",
 	SilenceUsage: true,
 	PreRunE: func(c *cobra.Command, args []string) error {
-		if err := log.Configure(logOptions); err != nil {
+		if err := istiolog.Configure(logOptions); err != nil {
 			log.Errorf("Failed to configure log %v", err)
 		}
 		return nil
@@ -75,7 +76,7 @@ var rootCmd = &cobra.Command{
 		monitoring.SetupMonitoring(cfg.InstallConfig.MonitoringPort, "/metrics", ctx.Done())
 
 		// Start UDS log server
-		udsLogger := udsLog.NewUDSLogger()
+		udsLogger := udsLog.NewUDSLogger(log.GetOutputLevel())
 		if err = udsLogger.StartUDSLogServer(cfg.InstallConfig.LogUDSAddress, ctx.Done()); err != nil {
 			log.Errorf("Failed to start up UDS Log Server: %v", err)
 			return
@@ -243,7 +244,8 @@ func constructConfig() (*config.Config, error) {
 		CNIConfName:      viper.GetString(constants.CNIConfName),
 		ChainedCNIPlugin: viper.GetBool(constants.ChainedCNIPlugin),
 
-		LogLevel:              viper.GetString(constants.LogLevel),
+		// make plugin (which runs out-of-process) inherit our current log level
+		PluginLogLevel:        istiolog.LevelToString(istiolog.FindScope(constants.CNIAgentLogScope).GetOutputLevel()),
 		KubeconfigFilename:    viper.GetString(constants.KubeconfigFilename),
 		KubeconfigMode:        viper.GetInt(constants.KubeconfigMode),
 		KubeCAFile:            viper.GetString(constants.KubeCAFile),

diff --git a/cni/pkg/config/config.go b/cni/pkg/config/config.go
@@ -35,8 +35,9 @@ type InstallConfig struct {
 	// Whether to install CNI plugin as a chained or standalone
 	ChainedCNIPlugin bool
 
-	// Logging level
-	LogLevel string
+	// Logging level for the CNI plugin
+	// Since it runs out-of-process, it has to be separately configured
+	PluginLogLevel string
 	// Name of the kubeconfig file used by the CNI plugin
 	KubeconfigFilename string
 	// The file mode to set when creating the kubeconfig file
@@ -128,7 +129,7 @@ func (c InstallConfig) String() string {
 	b.WriteString("CNIConfName: " + c.CNIConfName + "\n")
 	b.WriteString("ChainedCNIPlugin: " + fmt.Sprint(c.ChainedCNIPlugin) + "\n")
 
-	b.WriteString("LogLevel: " + c.LogLevel + "\n")
+	b.WriteString("PluginLogLevel: " + c.PluginLogLevel + "\n")
 	b.WriteString("KubeconfigFilename: " + c.KubeconfigFilename + "\n")
 	b.WriteString("KubeconfigMode: " + fmt.Sprintf("%#o", c.KubeconfigMode) + "\n")
 	b.WriteString("KubeCAFile: " + c.KubeCAFile + "\n")

diff --git a/cni/pkg/constants/constants.go b/cni/pkg/constants/constants.go
@@ -56,9 +56,10 @@ const (
 // Internal constants
 const (
 	DefaultKubeconfigMode = 0o600
-
-	CNIAddEventPath = "/cmdadd"
-	UDSLogPath      = "/log"
+	CNIAgentLogScope      = "cni-agent"
+	CNIPluginLogScope     = "cni-plugin"
+	CNIAddEventPath       = "/cmdadd"
+	UDSLogPath            = "/log"
 
 	// K8s liveness and readiness endpoints
 	LivenessEndpoint   = "/healthz"

diff --git a/cni/pkg/install/cniconfig.go b/cni/pkg/install/cniconfig.go
@@ -33,7 +33,7 @@ import (
 
 func createCNIConfigFile(ctx context.Context, cfg *config.InstallConfig) (string, error) {
 	pluginConfig := plugin.Config{
-		LogLevel:        cfg.LogLevel,
+		PluginLogLevel:  cfg.PluginLogLevel,
 		LogUDSAddress:   cfg.LogUDSAddress,
 		CNIEventAddress: cfg.CNIEventAddress,
 		AmbientEnabled:  cfg.AmbientEnabled,

diff --git a/cni/pkg/install/cniconfig_test.go b/cni/pkg/install/cniconfig_test.go
@@ -365,7 +365,7 @@ const (
   "cniVersion": "0.3.1",
   "name": "istio-cni",
   "type": "istio-cni",
-  "log_level": "__LOG_LEVEL__",
+  "plugin_log_level": "__LOG_LEVEL__",
   "kubernetes": {
       "kubeconfig": "__KUBECONFIG_FILENAME__",
       "cni_bin_dir": "/path/cni/bin"
@@ -449,14 +449,14 @@ func TestCreateCNIConfigFile(t *testing.T) {
 		cfgFile := config.InstallConfig{
 			CNIConfName:        c.specifiedConfName,
 			ChainedCNIPlugin:   c.chainedCNIPlugin,
-			LogLevel:           "debug",
+			PluginLogLevel:     "debug",
 			KubeconfigFilename: kubeconfigFilename,
 		}
 
 		cfg := config.InstallConfig{
 			CNIConfName:        c.specifiedConfName,
 			ChainedCNIPlugin:   c.chainedCNIPlugin,
-			LogLevel:           "debug",
+			PluginLogLevel:     "debug",
 			KubeconfigFilename: kubeconfigFilename,
 		}
 		test := func(cfg config.InstallConfig) func(t *testing.T) {

diff --git a/cni/pkg/install/install.go b/cni/pkg/install/install.go
@@ -22,14 +22,14 @@ import (
 	"sync/atomic"
 
 	"istio.io/istio/cni/pkg/config"
+	"istio.io/istio/cni/pkg/constants"
 	"istio.io/istio/cni/pkg/util"
 	"istio.io/istio/pkg/file"
 	"istio.io/istio/pkg/log"
 	"istio.io/istio/pkg/util/sets"
 )
 
-// TODO this should share parent scope, in practice it isn't useful to hide it within its own granular scope.
-var installLog = log.RegisterScope("install", "CNI install")
+var installLog = log.FindScope(constants.CNIAgentLogScope).WithLabels("plugin-install")
 
 type Installer struct {
 	cfg                *config.InstallConfig

diff --git a/cni/pkg/install/testdata/bridge.conf.golden b/cni/pkg/install/testdata/bridge.conf.golden
@@ -28,9 +28,9 @@
         ],
         "kubeconfig": "/path/to/kubeconfig"
       },
-      "log_level": "debug",
       "log_uds_address": "",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/pkg/install/testdata/istio-cni-prefixed.conf b/cni/pkg/install/testdata/istio-cni-prefixed.conf
@@ -2,7 +2,7 @@
   "cniVersion": "0.3.1",
   "name": "istio-cni",
   "type": "prefix-istio-cni",
-  "log_level": "debug",
+  "plugin_log_level": "debug",
   "kubernetes": {
       "kubeconfig": "/path/to/kubeconfig",
       "cni_bin_dir": "/path/cni/bin"

diff --git a/cni/pkg/install/testdata/istio-cni.conf b/cni/pkg/install/testdata/istio-cni.conf
@@ -4,7 +4,7 @@
   "type": "istio-cni",
   "ipam": {},
   "dns": {},
-  "log_level": "debug",
+  "plugin_log_level": "debug",
   "log_uds_address": "",
   "cni_event_address": "",
   "ambient_enabled": false,

diff --git a/cni/pkg/install/testdata/istio-cni.conf.template b/cni/pkg/install/testdata/istio-cni.conf.template
@@ -2,7 +2,7 @@
   "cniVersion": "0.3.1",
   "name": "istio-cni",
   "type": "istio-cni",
-  "log_level": "__LOG_LEVEL__",
+  "plugin_log_level": "__LOG_LEVEL__",
   "kubernetes": {
       "kubeconfig": "__KUBECONFIG_FILENAME__",
       "cni_bin_dir": "/path/cni/bin"

diff --git a/cni/pkg/install/testdata/list-with-istio.conflist b/cni/pkg/install/testdata/list-with-istio.conflist
@@ -32,8 +32,8 @@
         "cni_bin_dir": "/path/cni/bin",
         "kubeconfig": "/path/to/kubeconfig"
       },
-      "log_level": "debug",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/pkg/install/testdata/list-with-istio.conflist.golden b/cni/pkg/install/testdata/list-with-istio.conflist.golden
@@ -38,9 +38,9 @@
         ],
         "kubeconfig": "/path/to/kubeconfig"
       },
-      "log_level": "debug",
       "log_uds_address": "",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/pkg/install/testdata/list.conflist.golden b/cni/pkg/install/testdata/list.conflist.golden
@@ -38,9 +38,9 @@
         ],
         "kubeconfig": "/path/to/kubeconfig"
       },
-      "log_level": "debug",
       "log_uds_address": "",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/pkg/iptables/iptables.go b/cni/pkg/iptables/iptables.go
@@ -20,6 +20,7 @@ import (
 	"net/netip"
 	"strings"
 
+	"istio.io/istio/cni/pkg/constants"
 	"istio.io/istio/cni/pkg/ipset"
 	istiolog "istio.io/istio/pkg/log"
 	"istio.io/istio/tools/istio-iptables/pkg/builder"
@@ -48,7 +49,7 @@ const (
 	ProbeIPSet                  = "istio-inpod-probes"
 )
 
-var log = istiolog.RegisterScope("iptables", "iptables helper")
+var log = istiolog.RegisterScope(constants.CNIAgentLogScope, "").WithLabels("iptables")
 
 type Config struct {
 	RestoreFormat bool `json:"RESTORE_FORMAT"`

diff --git a/cni/pkg/log/uds.go b/cni/pkg/log/uds.go
@@ -29,7 +29,7 @@ import (
 	"istio.io/istio/pkg/uds"
 )
 
-var pluginLog = log.RegisterScope("cni", "CNI network plugin")
+var pluginLog = log.RegisterScope(constants.CNIPluginLogScope, "CNI network plugin (forwarded logs)")
 
 type UDSLogger struct {
 	mu            sync.Mutex
@@ -42,14 +42,15 @@ type cniLog struct {
 	Msg   string    `json:"msg"`
 }
 
-func NewUDSLogger() *UDSLogger {
+func NewUDSLogger(level log.Level) *UDSLogger {
 	l := &UDSLogger{}
 	mux := http.NewServeMux()
 	mux.HandleFunc(constants.UDSLogPath, l.handleLog)
 	loggingServer := &http.Server{
 		Handler: mux,
 	}
 	l.loggingServer = loggingServer
+	pluginLog.SetOutputLevel(level)
 	return l
 }
 

diff --git a/cni/pkg/log/uds_test.go b/cni/pkg/log/uds_test.go
@@ -30,8 +30,7 @@ func TestUDSLog(t *testing.T) {
 	// Start UDS log server
 	udsSockDir := t.TempDir()
 	udsSock := filepath.Join(udsSockDir, "cni.sock")
-	logger := NewUDSLogger()
-	pluginLog.SetOutputLevel(log.DebugLevel) // this will be configured by global.logging.level
+	logger := NewUDSLogger(log.DebugLevel)
 	stop := make(chan struct{})
 	defer close(stop)
 	assert.NoError(t, logger.StartUDSLogServer(udsSock, stop))

diff --git a/cni/pkg/nodeagent/net.go b/cni/pkg/nodeagent/net.go
@@ -24,6 +24,7 @@ import (
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/types"
 
+	"istio.io/istio/cni/pkg/constants"
 	"istio.io/istio/cni/pkg/ipset"
 	"istio.io/istio/cni/pkg/iptables"
 	"istio.io/istio/cni/pkg/util"
@@ -33,7 +34,7 @@ import (
 	dep "istio.io/istio/tools/istio-iptables/pkg/dependencies"
 )
 
-var log = istiolog.RegisterScope("ambient", "ambient controller")
+var log = istiolog.FindScope(constants.CNIAgentLogScope).WithLabels("server")
 
 // Adapts CNI to ztunnel server. decoupled from k8s for easier integration testing.
 type NetServer struct {

diff --git a/cni/pkg/plugin/plugin.go b/cni/pkg/plugin/plugin.go
@@ -65,7 +65,7 @@ type Config struct {
 	types.NetConf
 
 	// Add plugin-specific flags here
-	LogLevel        string     `json:"log_level"`
+	PluginLogLevel  string     `json:"plugin_log_level"`
 	LogUDSAddress   string     `json:"log_uds_address"`
 	CNIEventAddress string     `json:"cni_event_address"`
 	AmbientEnabled  bool       `json:"ambient_enabled"`
@@ -112,20 +112,6 @@ func parseConfig(stdin []byte) (*Config, error) {
 	return &conf, nil
 }
 
-func getLogLevel(logLevel string) log.Level {
-	switch logLevel {
-	case "debug":
-		return log.DebugLevel
-	case "warn":
-		return log.WarnLevel
-	case "error":
-		return log.ErrorLevel
-	case "info":
-		return log.InfoLevel
-	}
-	return log.InfoLevel
-}
-
 func GetLoggingOptions(udsAddress string) *log.Options {
 	loggingOptions := log.DefaultOptions()
 	loggingOptions.OutputPaths = []string{"stderr"}
@@ -316,7 +302,7 @@ func setupLogging(conf *Config) {
 			log.Error("Failed to configure istio-cni with UDS log")
 		}
 	}
-	log.FindScope("default").SetOutputLevel(getLogLevel(conf.LogLevel))
+	log.RegisterScope(constants.CNIPluginLogScope, "CNI plugin").SetOutputLevel(log.StringToLevel(conf.PluginLogLevel))
 }
 
 func pluginResponse(conf *Config) error {

diff --git a/cni/pkg/plugin/plugin_test.go b/cni/pkg/plugin/plugin_test.go
@@ -76,7 +76,7 @@ var mockConfTmpl = `{
         "routes": []
 
     },
-    "log_level": "debug",
+    "plugin_log_level": "debug",
     "cni_event_address": "%s",
     "ambient_enabled": %t,
     "kubernetes": {

diff --git a/cni/pkg/repair/repair.go b/cni/pkg/repair/repair.go
@@ -18,11 +18,12 @@ import (
 	"context"
 
 	"istio.io/istio/cni/pkg/config"
+	"istio.io/istio/cni/pkg/constants"
 	"istio.io/istio/pkg/kube"
 	"istio.io/istio/pkg/log"
 )
 
-var repairLog = log.RegisterScope("repair", "CNI race condition repair")
+var repairLog = log.FindScope(constants.CNIAgentLogScope).WithLabels("repair")
 
 func StartRepair(ctx context.Context, cfg config.RepairConfig) {
 	if !cfg.Enabled {

diff --git a/cni/test/install_cni.go b/cni/test/install_cni.go
@@ -271,7 +271,7 @@ func doTest(t *testing.T, chainedCNIPlugin bool, wd, preConfFile, resultFileName
 			KubeconfigFilename:    "ZZZ-istio-cni-kubeconfig",
 			CNINetDir:             "/etc/cni/net.d",
 			ChainedCNIPlugin:      chainedCNIPlugin,
-			LogLevel:              "debug",
+			PluginLogLevel:        "debug",
 			ExcludeNamespaces:     "istio-system",
 			KubeconfigMode:        constants.DefaultKubeconfigMode,
 			CNIConfName:           envPreconf,

diff --git a/cni/test/testdata/expected/10-calico.conflist-istioconfig b/cni/test/testdata/expected/10-calico.conflist-istioconfig
@@ -10,8 +10,8 @@
       "kubernetes": {
         "kubeconfig": "/etc/cni/net.d/calico-kubeconfig"
       },
-      "log_level": "info",
       "mtu": 1500,
+      "plugin_log_level": "info",
       "policy": {
         "type": "k8s"
       },
@@ -35,9 +35,9 @@
         ],
         "kubeconfig": "/etc/cni/net.d/ZZZ-istio-cni-kubeconfig"
       },
-      "log_level": "debug",
       "log_uds_address": "",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/test/testdata/expected/YYY-istio-cni.conf b/cni/test/testdata/expected/YYY-istio-cni.conf
@@ -4,7 +4,7 @@
   "type": "istio-cni",
   "ipam": {},
   "dns": {},
-  "log_level": "debug",
+  "plugin_log_level": "debug",
   "log_uds_address": "",
   "cni_event_address": "/tmp/cnieventfoo",
   "ambient_enabled": false,

diff --git a/cni/test/testdata/expected/minikube_cni.conflist.expected b/cni/test/testdata/expected/minikube_cni.conflist.expected
@@ -32,9 +32,9 @@
         ],
         "kubeconfig": "/etc/cni/net.d/ZZZ-istio-cni-kubeconfig"
       },
-      "log_level": "debug",
       "log_uds_address": "",
       "name": "istio-cni",
+      "plugin_log_level": "debug",
       "type": "istio-cni"
     }
   ]

diff --git a/cni/test/testdata/pre/calico.conflist b/cni/test/testdata/pre/calico.conflist
@@ -10,8 +10,8 @@
       "kubernetes": {
         "kubeconfig": "/etc/cni/net.d/calico-kubeconfig"
       },
-      "log_level": "info",
       "mtu": 1500,
+      "plugin_log_level": "info",
       "policy": {
         "type": "k8s"
       },