Merge pull request #67 from s1061123/dev/add_verbose_info

Bug 1835033: Logging improvement (UID, net-attach-def) / Backport to 4.4

doc/configuration.md

@@ -117,6 +117,8 @@ You may configure the logging level by using the `LogLevel` option in your CNI c
 
 The functionality provided by the `namespaceIsolation` configuration option enables a mode where Multus only allows pods to access custom resources (the `NetworkAttachmentDefinitions`) within the namespace where that pod resides. In other words, the `NetworkAttachmentDefinitions` are isolated to usage within the namespace in which they're created. 
 
+**NOTE**: The default namespace is special in this scenario. Even with namespace isolation enabled, any pod, in any namespace is allowed to refer to `NetworkAttachmentDefinitions` in the default namespace. This allows you to create commonly used unprivileged `NetworkAttachmentDefinitions` without having to put them in all namespaces. For example, if you had a `NetworkAttachmentDefinition` named `foo` the default namespace, you may reference it in an annotation with: `default/foo`.
+
 For example, if a pod is created in the namespace called `development`, Multus will not allow networks to be attached when defined by custom resources created in a different namespace, say in the `default` network.
 
 Consider the situation where you have a system that has users of different privilege levels -- as an example, a platform which has two administrators: a Senior Administrator and a Junior Administrator. The Senior Administrator may have access to all namespaces, and some network configurations as used by Multus are considered to be privileged in that they allow access to some protected resources available on the network. However, the Junior Administrator has access to only a subset of namespaces, and therefore it should be assumed that the Junior Administrator cannot create pods in their limited subset of namespaces. The `namespaceIsolation` feature provides for this isolation, allowing pods created in given namespaces to only access custom resources in the same namespace as the pod.

k8sclient/k8sclient.go

@@ -454,22 +454,22 @@ func GetK8sArgs(args *skel.CmdArgs) (*types.K8sArgs, error) {
 
 // TryLoadPodDelegates attempts to load Kubernetes-defined delegates and add them to the Multus config.
 // Returns the number of Kubernetes-defined delegates added or an error.
-func TryLoadPodDelegates(k8sArgs *types.K8sArgs, conf *types.NetConf, kubeClient KubeClient) (int, *ClientInfo, error) {
+func TryLoadPodDelegates(k8sArgs *types.K8sArgs, conf *types.NetConf, kubeClient KubeClient) (int, *v1.Pod, *ClientInfo, error) {
 	var err error
 	clientInfo := &ClientInfo{}
 
 	logging.Debugf("TryLoadPodDelegates: %v, %v, %v", k8sArgs, conf, kubeClient)
 	kubeClient, err = GetK8sClient(conf.Kubeconfig, kubeClient)
 	if err != nil {
-		return 0, nil, err
+		return 0, nil, nil, err
 	}
 
 	if kubeClient == nil {
 		if len(conf.Delegates) == 0 {
 			// No available kube client and no delegates, we can't do anything
-			return 0, nil, logging.Errorf("TryLoadPodDelegates: must have either Kubernetes config or delegates")
+			return 0, nil, nil, logging.Errorf("TryLoadPodDelegates: must have either Kubernetes config or delegates")
 		}
-		return 0, nil, nil
+		return 0, nil, nil, nil
 	}
 
 	setKubeClientInfo(clientInfo, kubeClient, k8sArgs)
@@ -477,12 +477,12 @@ func TryLoadPodDelegates(k8sArgs *types.K8sArgs, conf *types.NetConf, kubeClient
 	pod, err := kubeClient.GetPod(string(k8sArgs.K8S_POD_NAMESPACE), string(k8sArgs.K8S_POD_NAME))
 	if err != nil {
 		logging.Debugf("TryLoadPodDelegates: Err in loading K8s cluster default network from pod annotation: %v, use cached delegates", err)
-		return 0, nil, nil
+		return 0, nil, nil, nil
 	}
 
 	delegate, err := tryLoadK8sPodDefaultNetwork(kubeClient, pod, conf)
 	if err != nil {
-		return 0, nil, logging.Errorf("TryLoadPodDelegates: error in loading K8s cluster default network from pod annotation: %v", err)
+		return 0, nil, nil, logging.Errorf("TryLoadPodDelegates: error in loading K8s cluster default network from pod annotation: %v", err)
 	}
 	if delegate != nil {
 		logging.Debugf("TryLoadPodDelegates: Overwrite the cluster default network with %v from pod annotations", delegate)
@@ -496,13 +496,13 @@ func TryLoadPodDelegates(k8sArgs *types.K8sArgs, conf *types.NetConf, kubeClient
 
 		if err != nil {
 			if _, ok := err.(*NoK8sNetworkError); ok {
-				return 0, clientInfo, nil
+				return 0, nil, clientInfo, nil
 			}
-			return 0, nil, logging.Errorf("TryLoadPodDelegates: error in getting k8s network from pod: %v", err)
+			return 0, nil, nil, logging.Errorf("TryLoadPodDelegates: error in getting k8s network from pod: %v", err)
 		}
 
 		if err = conf.AddDelegates(delegates); err != nil {
-			return 0, nil, err
+			return 0, nil, nil, err
 		}
 
 		// Check gatewayRequest is configured in delegates
@@ -519,10 +519,10 @@ func TryLoadPodDelegates(k8sArgs *types.K8sArgs, conf *types.NetConf, kubeClient
 			types.CheckGatewayConfig(conf.Delegates)
 		}
 
-		return len(delegates), clientInfo, nil
+		return len(delegates), pod, clientInfo, nil
 	}
 
-	return 0, clientInfo, nil
+	return 0, pod, clientInfo, nil
 }
 
 // GetK8sClient gets client info from kubeconfig
@@ -603,7 +603,10 @@ func GetNetworkDelegates(k8sclient KubeClient, pod *v1.Pod, networks []*types.Ne
 		// In the case that this is a mismatch when namespaceisolation is enabled, this should be an error.
 		if confnamespaceIsolation {
 			if defaultNamespace != net.Namespace {
-				return nil, logging.Errorf("GetNetworkDelegates: namespace isolation enabled, annotation violates permission, pod is in namespace %v but refers to target namespace %v", defaultNamespace, net.Namespace)
+				// There is an exception however, we always allow a reference to the default namespace.
+				if net.Namespace != "default" {
+					return nil, logging.Errorf("GetNetworkDelegates: namespace isolation enabled, annotation violates permission, pod is in namespace %v but refers to target namespace %v", defaultNamespace, net.Namespace)
+				}
 			}
 		}
 

k8sclient/k8sclient_test.go

@@ -580,7 +580,7 @@ var _ = Describe("k8sclient operations", func() {
 		Expect(netConf.Delegates[0].Conf.Name).To(Equal("net2"))
 		Expect(netConf.Delegates[0].Conf.Type).To(Equal("mynet2"))
 
-		numK8sDelegates, _, err := TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
+		numK8sDelegates, _, _, err := TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
 		Expect(err).NotTo(HaveOccurred())
 		Expect(numK8sDelegates).To(Equal(0))
 		Expect(netConf.Delegates[0].Conf.Name).To(Equal("net1"))
@@ -617,7 +617,7 @@ var _ = Describe("k8sclient operations", func() {
 		Expect(err).To(HaveOccurred())
 
 		netConf.ConfDir = "badfilepath"
-		_, _, err = TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
+		_, _, _, err = TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
 		Expect(err).To(HaveOccurred())
 	})
 
@@ -650,7 +650,7 @@ var _ = Describe("k8sclient operations", func() {
 		k8sArgs, err := GetK8sArgs(args)
 		Expect(err).NotTo(HaveOccurred())
 
-		numK8sDelegates, _, err := TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
+		numK8sDelegates, _, _, err := TryLoadPodDelegates(k8sArgs, netConf, kubeClient)
 		Expect(err).NotTo(HaveOccurred())
 		Expect(numK8sDelegates).To(Equal(0))
 		Expect(netConf.Delegates[0].Conf.Name).To(Equal("net1"))
@@ -685,7 +685,7 @@ var _ = Describe("k8sclient operations", func() {
 		k8sArgs, err := GetK8sArgs(args)
 		Expect(err).NotTo(HaveOccurred())
 
-		_, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
+		_, _, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
 		Expect(err).To(HaveOccurred())
 	})
 
@@ -717,12 +717,12 @@ var _ = Describe("k8sclient operations", func() {
 		k8sArgs, err := GetK8sArgs(args)
 		Expect(err).NotTo(HaveOccurred())
 
-		_, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
+		_, _, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
 		Expect(err).NotTo(HaveOccurred())
 
 		// additionally, we expect the test to fail with no delegates, as at least one is always required.
 		netConf.Delegates = nil
-		_, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
+		_, _, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
 		Expect(err).To(HaveOccurred())
 	})
 
@@ -780,7 +780,7 @@ users:
 		k8sArgs, err := GetK8sArgs(args)
 		Expect(err).NotTo(HaveOccurred())
 
-		_, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
+		_, _, _, err = TryLoadPodDelegates(k8sArgs, netConf, nil)
 		Expect(err).NotTo(HaveOccurred())
 	})
 

multus/multus.go

@@ -41,6 +41,7 @@ import (
 	"github.com/intel/multus-cni/netutils"
 	"github.com/intel/multus-cni/types"
 	"github.com/vishvananda/netlink"
+	v1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/util/wait"
 )
 
@@ -221,7 +222,7 @@ func conflistDel(rt *libcni.RuntimeConf, rawnetconflist []byte, binDir string, e
 	return err
 }
 
-func delegateAdd(exec invoke.Exec, ifName string, delegate *types.DelegateNetConf, rt *libcni.RuntimeConf, binDir string, cniArgs string) (cnitypes.Result, error) {
+func delegateAdd(exec invoke.Exec, pod *v1.Pod, ifName string, delegate *types.DelegateNetConf, rt *libcni.RuntimeConf, binDir string, cniArgs string) (cnitypes.Result, error) {
 	logging.Debugf("delegateAdd: %v, %s, %v, %v, %s", exec, ifName, delegate, rt, binDir)
 	if os.Setenv("CNI_IFNAME", ifName) != nil {
 		return nil, logging.Errorf("delegateAdd: error setting envionment variable CNI_IFNAME")
@@ -286,21 +287,25 @@ func delegateAdd(exec invoke.Exec, ifName string, delegate *types.DelegateNetCon
 
 	if logging.GetLoggingLevel() >= logging.VerboseLevel {
 		data, _ := json.Marshal(result)
-		var confName string
+		var cniConfName string
 		if delegate.ConfListPlugin {
-			confName = delegate.ConfList.Name
+			cniConfName = delegate.ConfList.Name
 		} else {
-			confName = delegate.Conf.Name
+			cniConfName = delegate.Conf.Name
 		}
 
-		logging.Verbosef("Add: %s:%s:%s:%s %s", rt.Args[1][1], rt.Args[2][1], confName, rt.IfName, string(data))
+		podUID := "unknownUID"
+		if pod != nil {
+			podUID = string(pod.ObjectMeta.UID)
+		}
+		logging.Verbosef("Add: %s:%s:%s:%s(%s):%s %s", rt.Args[1][1], rt.Args[2][1], podUID, delegate.Name, cniConfName, rt.IfName, string(data))
 	}
 
 	return result, nil
 }
 
-func delegateDel(exec invoke.Exec, ifName string, delegateConf *types.DelegateNetConf, rt *libcni.RuntimeConf, binDir string) error {
-	logging.Debugf("delegateDel: %v, %s, %v, %v, %s", exec, ifName, delegateConf, rt, binDir)
+func delegateDel(exec invoke.Exec, pod *v1.Pod, ifName string, delegateConf *types.DelegateNetConf, rt *libcni.RuntimeConf, binDir string) error {
+	logging.Debugf("delegateDel: %v, %v, %s, %v, %v, %s", exec, pod, ifName, delegateConf, rt, binDir)
 	if os.Setenv("CNI_IFNAME", ifName) != nil {
 		return logging.Errorf("delegateDel: error setting envionment variable CNI_IFNAME")
 	}
@@ -312,7 +317,11 @@ func delegateDel(exec invoke.Exec, ifName string, delegateConf *types.DelegateNe
 		} else {
 			confName = delegateConf.Conf.Name
 		}
-		logging.Verbosef("Del: %s:%s:%s:%s %s", rt.Args[1][1], rt.Args[2][1], confName, rt.IfName, string(delegateConf.Bytes))
+		podUID := "unknownUID"
+		if pod != nil {
+			podUID = string(pod.ObjectMeta.UID)
+		}
+		logging.Verbosef("Del: %s:%s:%s:%s:%s %s", rt.Args[1][1], rt.Args[2][1], podUID, confName, rt.IfName, string(delegateConf.Bytes))
 	}
 
 	var err error
@@ -331,8 +340,8 @@ func delegateDel(exec invoke.Exec, ifName string, delegateConf *types.DelegateNe
 	return err
 }
 
-func delPlugins(exec invoke.Exec, argIfname string, delegates []*types.DelegateNetConf, lastIdx int, rt *libcni.RuntimeConf, binDir string) error {
-	logging.Debugf("delPlugins: %v, %s, %v, %d, %v, %s", exec, argIfname, delegates, lastIdx, rt, binDir)
+func delPlugins(exec invoke.Exec, pod *v1.Pod, argIfname string, delegates []*types.DelegateNetConf, lastIdx int, rt *libcni.RuntimeConf, binDir string) error {
+	logging.Debugf("delPlugins: %v, %v, %s, %v, %d, %v, %s", exec, pod, argIfname, delegates, lastIdx, rt, binDir)
 	if os.Setenv("CNI_COMMAND", "DEL") != nil {
 		return logging.Errorf("delPlugins: error setting envionment variable CNI_COMMAND to a value of DEL")
 	}
@@ -342,7 +351,7 @@ func delPlugins(exec invoke.Exec, argIfname string, delegates []*types.DelegateN
 		ifName := getIfname(delegates[idx], argIfname, idx)
 		rt.IfName = ifName
 		// Attempt to delete all but do not error out, instead, collect all errors.
-		if err := delegateDel(exec, ifName, delegates[idx], rt, binDir); err != nil {
+		if err := delegateDel(exec, pod, ifName, delegates[idx], rt, binDir); err != nil {
 			errorstrings = append(errorstrings, err.Error())
 		}
 	}
@@ -394,7 +403,7 @@ func cmdAdd(args *skel.CmdArgs, exec invoke.Exec, kubeClient k8s.KubeClient) (cn
 		n.Delegates[0].MasterPlugin = true
 	}
 
-	_, kc, err := k8s.TryLoadPodDelegates(k8sArgs, n, kubeClient)
+	_, pod, kc, err := k8s.TryLoadPodDelegates(k8sArgs, n, kubeClient)
 	if err != nil {
 		return nil, cmdErr(k8sArgs, "error loading k8s delegates k8s args: %v", err)
 	}
@@ -412,7 +421,7 @@ func cmdAdd(args *skel.CmdArgs, exec invoke.Exec, kubeClient k8s.KubeClient) (cn
 
 		runtimeConfig := types.MergeCNIRuntimeConfig(n.RuntimeConfig, delegate)
 		rt := types.CreateCNIRuntimeConf(args, k8sArgs, ifName, runtimeConfig)
-		tmpResult, err = delegateAdd(exec, ifName, delegate, rt, n.BinDir, cniArgs)
+		tmpResult, err = delegateAdd(exec, pod, ifName, delegate, rt, n.BinDir, cniArgs)
 		if err != nil {
 			// If the add failed, tear down all networks we already added
 			netName := delegate.Conf.Name
@@ -420,7 +429,7 @@ func cmdAdd(args *skel.CmdArgs, exec invoke.Exec, kubeClient k8s.KubeClient) (cn
 				netName = delegate.ConfList.Name
 			}
 			// Ignore errors; DEL must be idempotent anyway
-			_ = delPlugins(exec, args.IfName, n.Delegates, idx, rt, n.BinDir)
+			_ = delPlugins(exec, nil, args.IfName, n.Delegates, idx, rt, n.BinDir)
 			return nil, cmdErr(k8sArgs, "error adding container to network %q: %v", netName, err)
 		}
 
@@ -553,7 +562,7 @@ func cmdDel(args *skel.CmdArgs, exec invoke.Exec, kubeClient k8s.KubeClient) err
 			}
 
 			// Get pod annotation and so on
-			_, _, err := k8s.TryLoadPodDelegates(k8sArgs, in, kubeClient)
+			_, _, _, err := k8s.TryLoadPodDelegates(k8sArgs, in, kubeClient)
 			if err != nil {
 				if len(in.Delegates) == 0 {
 					// No delegate available so send error
@@ -603,8 +612,16 @@ func cmdDel(args *skel.CmdArgs, exec invoke.Exec, kubeClient k8s.KubeClient) err
 		}
 	}
 
+	kubeClient, err = k8s.GetK8sClient(in.Kubeconfig, kubeClient)
+	var pod *v1.Pod
+	if kubeClient != nil {
+		podName := string(k8sArgs.K8S_POD_NAME)
+		podNamespace := string(k8sArgs.K8S_POD_NAMESPACE)
+		pod, _ = kubeClient.GetPod(podNamespace, podName)
+	}
+
 	rt := types.CreateCNIRuntimeConf(args, k8sArgs, "", in.RuntimeConfig)
-	return delPlugins(exec, args.IfName, in.Delegates, len(in.Delegates)-1, rt, in.BinDir)
+	return delPlugins(exec, pod, args.IfName, in.Delegates, len(in.Delegates)-1, rt, in.BinDir)
 }
 
 func main() {

multus/multus_test.go

@@ -1169,7 +1169,7 @@ var _ = Describe("multus operations", func() {
 		_, err = cmdAdd(args, fExec, nil)
 		Expect(fExec.addIndex).To(Equal(2))
 		Expect(fExec.delIndex).To(Equal(2))
-		Expect(err).To(MatchError("Multus: error adding pod to network \"other1\": delegateAdd: error invoking DelegateAdd - \"other-plugin\": error in getting result from AddNetwork: expected plugin failure"))
+		Expect(err).To(MatchError("Multus: [/]: error adding container to network \"other1\": delegateAdd: error invoking DelegateAdd - \"other-plugin\": error in getting result from AddNetwork: expected plugin failure"))
 
 		// Cleanup default network file.
 		if _, errStat := os.Stat(configPath); errStat == nil {
@@ -1805,7 +1805,7 @@ var _ = Describe("multus operations", func() {
 		err = cmdDel(args, fExec, fKubeClient)
 		Expect(err).NotTo(HaveOccurred())
 		Expect(fExec.delIndex).To(Equal(len(fExec.plugins)))
-		Expect(fKubeClient.PodCount).To(Equal(3))
+		Expect(fKubeClient.PodCount).To(Equal(4))
 		Expect(fKubeClient.NetCount).To(Equal(1))
 	})
 
@@ -1886,7 +1886,7 @@ var _ = Describe("multus operations", func() {
 		err = cmdDel(args, fExec, fKubeClient)
 		Expect(err).NotTo(HaveOccurred())
 		Expect(fExec.delIndex).To(Equal(len(fExec.plugins)))
-		Expect(fKubeClient.PodCount).To(Equal(4))
+		Expect(fKubeClient.PodCount).To(Equal(5))
 		Expect(fKubeClient.NetCount).To(Equal(2))
 	})
 

testing/testing.go

@@ -149,6 +149,7 @@ func NewFakePod(name string, netAnnotation string, defaultNetAnnotation string)
 		ObjectMeta: metav1.ObjectMeta{
 			Name:      name,
 			Namespace: "test",
+			UID:       "testUID",
 		},
 		Spec: v1.PodSpec{
 			Containers: []v1.Container{

types/conf.go

@@ -97,6 +97,9 @@ func LoadDelegateNetConf(bytes []byte, net *NetworkSelectionElement, deviceID st
 	}
 
 	if net != nil {
+		if net.Name != "" {
+			delegateConf.Name = net.Name
+		}
 		if net.InterfaceRequest != "" {
 			delegateConf.IfnameRequest = net.InterfaceRequest
 		}
@@ -160,6 +163,7 @@ func CreateCNIRuntimeConf(args *skel.CmdArgs, k8sArgs *K8sArgs, ifName string, r
 		ContainerID: args.ContainerID,
 		NetNS:       args.Netns,
 		IfName:      ifName,
+		// NOTE: Verbose logging depends on this order, so please keep Args order.
 		Args: [][2]string{
 			{"IgnoreUnknown", string("true")},
 			{"K8S_POD_NAMESPACE", string(k8sArgs.K8S_POD_NAMESPACE)},

types/conf_test.go

@@ -368,17 +368,17 @@ var _ = Describe("config operations", func() {
     "args1": "val1"
 }`
 		type bridgeNetConf struct {
-			Name     string `json:"name"`
-			Type     string `json:"type"`
-			Args     struct {
+			Name string `json:"name"`
+			Type string `json:"type"`
+			Args struct {
 				CNI map[string]string `json:"cni"`
 			} `json:"args"`
 		}
 
-                err := json.Unmarshal([]byte(cniArgs), &args)
+		err := json.Unmarshal([]byte(cniArgs), &args)
 		Expect(err).NotTo(HaveOccurred())
-                net := &NetworkSelectionElement{
-			Name: "test-elem",
+		net := &NetworkSelectionElement{
+			Name:    "test-elem",
 			CNIArgs: &args,
 		}
 		delegateNetConf, err := LoadDelegateNetConf([]byte(conf), net, "")
@@ -404,17 +404,17 @@ var _ = Describe("config operations", func() {
     "args1": "val1a"
 }`
 		type bridgeNetConf struct {
-			Name     string `json:"name"`
-			Type     string `json:"type"`
-			Args     struct {
+			Name string `json:"name"`
+			Type string `json:"type"`
+			Args struct {
 				CNI map[string]string `json:"cni"`
 			} `json:"args"`
 		}
 
-                err := json.Unmarshal([]byte(cniArgs), &args)
+		err := json.Unmarshal([]byte(cniArgs), &args)
 		Expect(err).NotTo(HaveOccurred())
-                net := &NetworkSelectionElement{
-			Name: "test-elem",
+		net := &NetworkSelectionElement{
+			Name:    "test-elem",
 			CNIArgs: &args,
 		}
 		delegateNetConf, err := LoadDelegateNetConf([]byte(conf), net, "")
@@ -439,20 +439,20 @@ var _ = Describe("config operations", func() {
     "args1": "val1"
 }`
 		type bridgeNetConf struct {
-			Type     string `json:"type"`
-			Args     struct {
+			Type string `json:"type"`
+			Args struct {
 				CNI map[string]string `json:"cni"`
 			} `json:"args"`
 		}
 		type bridgeNetConfList struct {
-			Name     string `json:"name"`
+			Name    string           `json:"name"`
 			Plugins []*bridgeNetConf `json:"plugins"`
 		}
 
-                err := json.Unmarshal([]byte(cniArgs), &args)
+		err := json.Unmarshal([]byte(cniArgs), &args)
 		Expect(err).NotTo(HaveOccurred())
-                net := &NetworkSelectionElement{
-			Name: "test-elem",
+		net := &NetworkSelectionElement{
+			Name:    "test-elem",
 			CNIArgs: &args,
 		}
 		delegateNetConf, err := LoadDelegateNetConf([]byte(conf), net, "")

types/types.go

@@ -94,6 +94,7 @@ type NetworkStatus struct {
 type DelegateNetConf struct {
 	Conf                types.NetConf
 	ConfList            types.NetConfList
+	Name                string
 	IfnameRequest       string          `json:"ifnameRequest,omitempty"`
 	MacRequest          string          `json:"macRequest,omitempty"`
 	IPRequest           []string        `json:"ipRequest,omitempty"`