diff --git a/Makefile b/Makefile index 4f1453f78..fb20358d9 100644 --- a/Makefile +++ b/Makefile @@ -14,6 +14,7 @@ BASE=$(GOPATH)/src/$(REPO_PATH) GOFILES = $(shell find . -name *.go | grep -vE "(\/vendor\/)|(_test.go)") PKGS = $(or $(PKG),$(shell cd $(BASE) && env GOPATH=$(GOPATH) $(GO) list ./... | grep -v "^$(PACKAGE)/vendor/")) TESTPKGS = $(shell env GOPATH=$(GOPATH) $(GO) list -f '{{ if or .TestGoFiles .XTestGoFiles }}{{ .ImportPath }}{{ end }}' $(PKGS)) +IMAGE_BUILDER ?= docker export GOPATH export GOBIN @@ -136,7 +137,7 @@ fmt: ; $(info Running gofmt...) @ ## Run gofmt on all source files # To pass proxy for Docker invoke it as 'make image HTTP_POXY=http://192.168.0.1:8080' .PHONY: image image: | $(BASE) ; $(info Building Docker image...) @ ## Build SR-IOV CNI docker image - @docker build -t $(TAG) -f $(DOCKERFILE) $(CURDIR) $(DOCKERARGS) + @$(IMAGE_BUILDER) build -t $(TAG) -f $(DOCKERFILE) $(CURDIR) $(DOCKERARGS) # Misc diff --git a/cmd/sriov/main.go b/cmd/sriov/main.go index e785a5e00..e844d5074 100644 --- a/cmd/sriov/main.go +++ b/cmd/sriov/main.go @@ -13,6 +13,7 @@ import ( "github.com/containernetworking/plugins/pkg/ipam" "github.com/containernetworking/plugins/pkg/ns" "github.com/k8snetworkplumbingwg/sriov-cni/pkg/config" + "github.com/k8snetworkplumbingwg/sriov-cni/pkg/logging" "github.com/k8snetworkplumbingwg/sriov-cni/pkg/sriov" "github.com/k8snetworkplumbingwg/sriov-cni/pkg/utils" "github.com/vishvananda/netlink" @@ -43,6 +44,13 @@ func getEnvArgs(envArgsString string) (*envArgs, error) { } func cmdAdd(args *skel.CmdArgs) error { + if err := config.SetLogging(args.StdinData, args.ContainerID, args.Netns, args.IfName); err != nil { + return err + } + logging.Debug("function called", + "func", "cmdAdd", + "args.Path", args.Path, "args.StdinData", string(args.StdinData), "args.Args", args.Args) + netConf, err := config.LoadConf(args.StdinData) if err != nil { return fmt.Errorf("SRIOV-CNI failed to load netconf: %v", err) @@ -179,12 +187,20 @@ func cmdAdd(args *skel.CmdArgs) error { } // Cache NetConf for CmdDel + logging.Debug("Cache NetConf for CmdDel", + "func", "cmdAdd", + "config.DefaultCNIDir", config.DefaultCNIDir, + "netConf", netConf) if err = utils.SaveNetConf(args.ContainerID, config.DefaultCNIDir, args.IfName, netConf); err != nil { return fmt.Errorf("error saving NetConf %q", err) } + // Mark the pci address as in use. + logging.Debug("Mark the PCI address as in use", + "func", "cmdAdd", + "config.DefaultCNIDir", config.DefaultCNIDir, + "netConf.DeviceID", netConf.DeviceID) allocator := utils.NewPCIAllocator(config.DefaultCNIDir) - // Mark the pci address as in used if err = allocator.SaveAllocatedPCI(netConf.DeviceID, args.Netns); err != nil { return fmt.Errorf("error saving the pci allocation for vf pci address %s: %v", netConf.DeviceID, err) } @@ -193,6 +209,13 @@ func cmdAdd(args *skel.CmdArgs) error { } func cmdDel(args *skel.CmdArgs) error { + if err := config.SetLogging(args.StdinData, args.ContainerID, args.Netns, args.IfName); err != nil { + return err + } + logging.Debug("function called", + "func", "cmdDel", + "args.Path", args.Path, "args.StdinData", string(args.StdinData), "args.Args", args.Args) + netConf, cRefPath, err := config.LoadConfFromCache(args) if err != nil { // If cmdDel() fails, cached netconf is cleaned up by @@ -202,6 +225,9 @@ func cmdDel(args *skel.CmdArgs) error { // Return nil when LoadConfFromCache fails since the rest // of cmdDel() code relies on netconf as input argument // and there is no meaning to continue. + logging.Error("Cannot load config file from cache", + "func", "cmdDel", + "err", err) return nil } @@ -261,6 +287,10 @@ func cmdDel(args *skel.CmdArgs) error { } // Mark the pci address as released + logging.Debug("Mark the PCI address as released", + "func", "cmdDel", + "config.DefaultCNIDir", config.DefaultCNIDir, + "netConf.DeviceID", netConf.DeviceID) allocator := utils.NewPCIAllocator(config.DefaultCNIDir) if err = allocator.DeleteAllocatedPCI(netConf.DeviceID); err != nil { return fmt.Errorf("error cleaning the pci allocation for vf pci address %s: %v", netConf.DeviceID, err) diff --git a/docs/configuration-reference.md b/docs/configuration-reference.md index c3bbdbc44..7f7904956 100644 --- a/docs/configuration-reference.md +++ b/docs/configuration-reference.md @@ -18,6 +18,9 @@ The SR-IOV CNI configures networks through a CNI spec configuration object. In a * `min_tx_rate` (int, optional): change the allowed minimum transmit bandwidth, in Mbps, for the VF. Setting this to 0 disables rate limiting. The min_tx_rate value should be <= max_tx_rate. Support of this feature depends on NICs and drivers. * `max_tx_rate` (int, optional): change the allowed maximum transmit bandwidth, in Mbps, for the VF. Setting this to 0 disables rate limiting. +* `logLevel` (string, optional): either of panic, error, warning, info, debug with a default of info. +* `logFile` (string, optional): path to file for log output. By default, this will log to stderr. Logging to stderr +means that the logs will show up in crio logs (in the journal in most configurations) and in multus pod logs. An SR-IOV CNI config with each field filled out looks like: @@ -36,7 +39,9 @@ An SR-IOV CNI config with each field filled out looks like: "max_tx_rate": 200, "spoofchk": "off", "trust": "on", - "link_state": "enable" + "link_state": "enable", + "logLevel": "debug", + "logFile": "/tmp/sriov.log" } ``` diff --git a/go.mod b/go.mod index 1cdd76ba8..e507d5657 100644 --- a/go.mod +++ b/go.mod @@ -5,6 +5,7 @@ go 1.20 require ( github.com/containernetworking/cni v1.1.2 github.com/containernetworking/plugins v1.2.0 + github.com/k8snetworkplumbingwg/cni-log v0.0.0-20230801160229-b6e062c9e0f2 github.com/onsi/ginkgo/v2 v2.9.2 github.com/onsi/gomega v1.27.5 github.com/stretchr/testify v1.6.1 @@ -26,6 +27,8 @@ require ( golang.org/x/sys v0.12.0 // indirect golang.org/x/text v0.8.0 // indirect golang.org/x/tools v0.7.0 // indirect + gopkg.in/natefinch/lumberjack.v2 v2.0.0 // indirect + gopkg.in/yaml.v2 v2.4.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 4579fdd08..eaa1aa5ad 100644 --- a/go.sum +++ b/go.sum @@ -1,3 +1,4 @@ +github.com/BurntSushi/toml v1.1.0 h1:ksErzDEI1khOiGPgpwuI7x2ebx/uXQNw7xJpn9Eq1+I= github.com/chzyer/logex v1.1.10/go.mod h1:+Ywpsq7O8HXn0nuIou7OrIPyXbp3wmkHB+jjWRnGsAI= github.com/chzyer/readline v0.0.0-20180603132655-2972be24d48e/go.mod h1:nSuG5e5PlCu98SY8svDHJxuZscDgtXS6KTTbou5AhLI= github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU= @@ -25,6 +26,10 @@ github.com/google/pprof v0.0.0-20210407192527-94a9f03dee38/go.mod h1:kpwsk12EmLe github.com/google/pprof v0.0.0-20230323073829-e72429f035bd h1:r8yyd+DJDmsUhGrRBxH5Pj7KeFK5l+Y3FsgT8keqKtk= github.com/google/pprof v0.0.0-20230323073829-e72429f035bd/go.mod h1:79YE0hCXdHag9sBkw2o+N/YnZtTkXi0UT9Nnixa5eYk= github.com/ianlancetaylor/demangle v0.0.0-20200824232613-28f6c0f3b639/go.mod h1:aSSvb/t6k1mPoxDqO4vJh6VOCGPwU4O0C2/Eqndh1Sc= +github.com/k8snetworkplumbingwg/cni-log v0.0.0-20230725074452-455465349b0d h1:fXp43GgMdHBigXEnKrsFqlan6+JSTOwAquzmXaKmzkA= +github.com/k8snetworkplumbingwg/cni-log v0.0.0-20230725074452-455465349b0d/go.mod h1:/x45AlZDoJVSSV4ECDb5TcHLzrVRDllsCMDzMrtHKwk= +github.com/k8snetworkplumbingwg/cni-log v0.0.0-20230801160229-b6e062c9e0f2 h1:KB8UPZQwLge4Abuk9tNmvzffdCJgqXSN341BX98QTHg= +github.com/k8snetworkplumbingwg/cni-log v0.0.0-20230801160229-b6e062c9e0f2/go.mod h1:/x45AlZDoJVSSV4ECDb5TcHLzrVRDllsCMDzMrtHKwk= github.com/nxadm/tail v1.4.8 h1:nPr65rt6Y5JFSKQO7qToXr7pePgD6Gwiw05lkbyAQTE= github.com/onsi/ginkgo v1.16.5 h1:8xi0RTUf59SOSfEtZMvwTvXYMzG4gV23XVHOZiXNtnE= github.com/onsi/ginkgo/v2 v2.9.2 h1:BA2GMJOtfGAfagzYtrAlufIP0lq6QERkFmHLMLPwFSU= @@ -96,7 +101,11 @@ google.golang.org/protobuf v1.28.0 h1:w43yiav+6bVFTBQFZX0r7ipe9JQ1QsbMgHwbBziscL google.golang.org/protobuf v1.28.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/natefinch/lumberjack.v2 v2.0.0 h1:1Lc07Kr7qY4U2YPouBjpCLxpiyxIVoxqXgkXLknAOE8= +gopkg.in/natefinch/lumberjack.v2 v2.0.0/go.mod h1:l0ndWWf7gzL7RNwBG7wST/UCcT4T24xpD6X8LsfU/+k= gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 h1:uRGJdciOHaEIrze2W8Q3AKkepLTh2hOroT7a+7czfdQ= +gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY= +gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/pkg/config/config.go b/pkg/config/config.go index 025d64e0d..361fbbba8 100644 --- a/pkg/config/config.go +++ b/pkg/config/config.go @@ -7,6 +7,7 @@ import ( "strings" "github.com/containernetworking/cni/pkg/skel" + "github.com/k8snetworkplumbingwg/sriov-cni/pkg/logging" sriovtypes "github.com/k8snetworkplumbingwg/sriov-cni/pkg/types" "github.com/k8snetworkplumbingwg/sriov-cni/pkg/utils" ) @@ -16,6 +17,17 @@ var ( DefaultCNIDir = "/var/lib/cni/sriov" ) +// SetLogging sets global logging parameters. +func SetLogging(stdinData []byte, containerID, netns, ifName string) error { + n := &sriovtypes.NetConf{} + if err := json.Unmarshal(stdinData, n); err != nil { + return fmt.Errorf("SetLogging(): failed to load netconf: %v", err) + } + + logging.Init(n.LogLevel, n.LogFile, containerID, netns, ifName) + return nil +} + // LoadConf parses and validates stdin netconf and returns NetConf object func LoadConf(bytes []byte) (*sriovtypes.NetConf, error) { n := &sriovtypes.NetConf{} @@ -36,11 +48,15 @@ func LoadConf(bytes []byte) (*sriovtypes.NetConf, error) { return nil, fmt.Errorf("LoadConf(): VF pci addr is required") } - allocator := utils.NewPCIAllocator(DefaultCNIDir) // Check if the device is already allocated. // This is to prevent issues where kubelet request to delete a pod and in the same time a new pod using the same // vf is started. we can have an issue where the cmdDel of the old pod is called AFTER the cmdAdd of the new one // This will block the new pod creation until the cmdDel is done. + logging.Debug("Check if the device is already allocated", + "func", "LoadConf", + "DefaultCNIDir", DefaultCNIDir, + "n.DeviceID", n.DeviceID) + allocator := utils.NewPCIAllocator(DefaultCNIDir) isAllocated, err := allocator.IsAllocated(n.DeviceID) if err != nil { return n, err diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go new file mode 100644 index 000000000..4d5e81fc4 --- /dev/null +++ b/pkg/logging/logging.go @@ -0,0 +1,93 @@ +// package logging is a small wrapper around github.com/k8snetworkplumbingwg/cni-log + +package logging + +import ( + cnilog "github.com/k8snetworkplumbingwg/cni-log" +) + +const ( + labelCNIName = "cniName" + labelContainerID = "containerID" + labelNetNS = "netns" + labelIFName = "ifname" + cniName = "sriov-cni" +) + +var ( + logLevelDefault = cnilog.InfoLevel + containerID = "" + netNS = "" + ifName = "" +) + +// Init initializes logging with the requested parameters in this order: log level, log file, container ID, +// network namespace and interface name. +func Init(logLevel, logFile, containerIdentification, networkNamespace, interfaceName string) { + setLogLevel(logLevel) + setLogFile(logFile) + containerID = containerIdentification + netNS = networkNamespace + ifName = interfaceName +} + +// setLogLevel sets the log level to either verbose, debug, info, warn, error or panic. If an invalid string is +// provided, it uses error. +func setLogLevel(l string) { + ll := cnilog.StringToLevel(l) + if ll == cnilog.InvalidLevel { + ll = logLevelDefault + } + cnilog.SetLogLevel(ll) +} + +// setLogFile sets the log file for logging. If the empty string is provided, it uses stderr. +func setLogFile(fileName string) { + if fileName == "" { + cnilog.SetLogStderr(true) + cnilog.SetLogFile("") + return + } + cnilog.SetLogFile(fileName) + cnilog.SetLogStderr(false) +} + +// Debug provides structured logging for log level >= debug. +func Debug(msg string, args ...interface{}) { + cnilog.DebugStructured(msg, prependArgs(args)...) +} + +// Info provides structured logging for log level >= info. +func Info(msg string, args ...interface{}) { + cnilog.InfoStructured(msg, prependArgs(args)...) +} + +// Warning provides structured logging for log level >= warning. +func Warning(msg string, args ...interface{}) { + cnilog.WarningStructured(msg, prependArgs(args)...) +} + +// Error provides structured logging for log level >= error. +func Error(msg string, args ...interface{}) { + _ = cnilog.ErrorStructured(msg, prependArgs(args)...) +} + +// Panic provides structured logging for log level >= panic. +func Panic(msg string, args ...interface{}) { + cnilog.PanicStructured(msg, prependArgs(args)...) +} + +// prependArgs prepends cniName, containerID, netNS and ifName to the args of every log message. +func prependArgs(args []interface{}) []interface{} { + if ifName != "" { + args = append([]interface{}{labelIFName, ifName}, args...) + } + if netNS != "" { + args = append([]interface{}{labelNetNS, netNS}, args...) + } + if containerID != "" { + args = append([]interface{}{labelContainerID, containerID}, args...) + } + args = append([]interface{}{labelCNIName, cniName}, args...) + return args +} diff --git a/pkg/logging/logging_suite_test.go b/pkg/logging/logging_suite_test.go new file mode 100644 index 000000000..6f85b94ef --- /dev/null +++ b/pkg/logging/logging_suite_test.go @@ -0,0 +1,19 @@ +package logging + +import ( + "testing" + + g "github.com/onsi/ginkgo/v2" + o "github.com/onsi/gomega" +) + +func TestConfig(t *testing.T) { + o.RegisterFailHandler(g.Fail) + g.RunSpecs(t, "Logging Suite") +} + +var _ = g.BeforeSuite(func() { +}) + +var _ = g.AfterSuite(func() { +}) diff --git a/pkg/logging/logging_test.go b/pkg/logging/logging_test.go new file mode 100644 index 000000000..495690c28 --- /dev/null +++ b/pkg/logging/logging_test.go @@ -0,0 +1,230 @@ +package logging + +import ( + "fmt" + "io" + "os" + + g "github.com/onsi/ginkgo/v2" + o "github.com/onsi/gomega" +) + +var _ = g.Describe("Logging", func() { + var origStderr *os.File + var stderrFile *os.File + + g.BeforeEach(func() { + var err error + stderrFile, err = os.CreateTemp("", "") + o.Expect(err).NotTo(o.HaveOccurred()) + origStderr = os.Stderr + os.Stderr = stderrFile + }) + + g.AfterEach(func() { + os.Stderr = origStderr + o.Expect(stderrFile.Close()).To(o.Succeed()) + o.Expect(os.RemoveAll(stderrFile.Name())).To(o.Succeed()) + }) + + g.Context("log argument prepender", func() { + g.When("none of netns, containerID, ifName are specified", func() { + g.BeforeEach(func() { + Init("", "", "", "", "") + }) + + g.It("should only prepend the cniName", func() { + Panic("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring(fmt.Sprintf(`%s="%s"`, labelCNIName, cniName))) + o.Expect(out).ShouldNot(o.ContainSubstring(labelContainerID)) + o.Expect(out).ShouldNot(o.ContainSubstring(labelNetNS)) + o.Expect(out).ShouldNot(o.ContainSubstring(labelIFName)) + }) + }) + + g.When("netns, containerID and ifName are specified", func() { + const ( + testContainerID = "test-containerid" + testNetNS = "test-netns" + testIFName = "test-ifname" + ) + + g.BeforeEach(func() { + Init("", "", testContainerID, testNetNS, testIFName) + }) + + g.It("should log cniName, netns, containerID and ifName", func() { + Panic("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring(fmt.Sprintf(`%s="%s"`, labelCNIName, cniName))) + o.Expect(out).Should(o.ContainSubstring(fmt.Sprintf(`%s="%s"`, labelContainerID, testContainerID))) + o.Expect(out).Should(o.ContainSubstring(fmt.Sprintf(`%s="%s"`, labelNetNS, testNetNS))) + o.Expect(out).Should(o.ContainSubstring(fmt.Sprintf(`%s="%s"`, labelIFName, testIFName))) + }) + }) + }) + + g.Context("log levels", func() { + g.When("the defaults are used", func() { + g.BeforeEach(func() { + Init("", "", "", "", "") + }) + + g.It("panic messages are logged to stderr", func() { + Panic("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("info messages are logged to stderr and look as expected", func() { + Info("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring(`msg="test message"`)) + o.Expect(out).Should(o.ContainSubstring(`a="b"`)) + o.Expect(out).Should(o.ContainSubstring(`level="info"`)) + }) + + g.It("debug messages are not logged to stderr", func() { + Debug("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).ShouldNot(o.ContainSubstring("test message")) + }) + }) + + g.When("the log level is raised to warning", func() { + g.BeforeEach(func() { + Init("warning", "", "", "", "") + }) + + g.It("panic messages are logged to stderr", func() { + Panic("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("error messages are logged to stderr", func() { + Error("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("warning messages are logged to stderr", func() { + Warning("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("info messages are not logged to stderr", func() { + Info("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).ShouldNot(o.ContainSubstring("test message")) + }) + }) + + g.When("the log level is set to an invalid value", func() { + g.BeforeEach(func() { + Init("I'm invalid", "", "", "", "") + }) + + g.It("panic messages are logged to stderr", func() { + Panic("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("info messages are logged to stderr", func() { + Info("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + + g.It("debug messages are not logged to stderr", func() { + Debug("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).ShouldNot(o.ContainSubstring("test message")) + }) + }) + }) + + g.Context("log files", func() { + var logFile *os.File + + g.BeforeEach(func() { + var err error + logFile, err = os.CreateTemp("", "") + o.Expect(err).NotTo(o.HaveOccurred()) + }) + + g.AfterEach(func() { + o.Expect(logFile.Close()).To(o.Succeed()) + o.Expect(os.RemoveAll(logFile.Name())).To(o.Succeed()) + }) + + g.When("the log file is set", func() { + g.BeforeEach(func() { + Init("", logFile.Name(), "", "", "") + }) + + g.It("error messages are logged to log file but not to stderr", func() { + Error("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(logFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + + _, _ = stderrFile.Seek(0, 0) + out, err = io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).ShouldNot(o.ContainSubstring("test message")) + }) + }) + + g.When("the log file is set and then unset", func() { + g.BeforeEach(func() { + // TODO: This triggers a data race in github.com/k8snetworkplumbingwg/cni-log; fix the datarace in the + // logging component and then remove the skip. + g.Skip("https://github.com/k8snetworkplumbingwg/cni-log/issues/15") + Init("", logFile.Name(), "", "", "") + setLogFile("") + }) + + g.It("logs to stderr but not to file", func() { + Error("test message", "a", "b") + _, _ = stderrFile.Seek(0, 0) + out, err := io.ReadAll(logFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).ShouldNot(o.ContainSubstring("test message")) + + _, _ = stderrFile.Seek(0, 0) + out, err = io.ReadAll(stderrFile) + o.Expect(err).NotTo(o.HaveOccurred()) + o.Expect(out).Should(o.ContainSubstring("test message")) + }) + }) + }) +}) diff --git a/pkg/sriov/sriov.go b/pkg/sriov/sriov.go index 5f39d40a8..f34e233e4 100644 --- a/pkg/sriov/sriov.go +++ b/pkg/sriov/sriov.go @@ -2,8 +2,10 @@ package sriov import ( "fmt" + "github.com/containernetworking/plugins/pkg/ns" + "github.com/k8snetworkplumbingwg/sriov-cni/pkg/logging" sriovtypes "github.com/k8snetworkplumbingwg/sriov-cni/pkg/types" "github.com/k8snetworkplumbingwg/sriov-cni/pkg/utils" "github.com/vishvananda/netlink" @@ -69,11 +71,18 @@ func (s *sriovManager) SetupVF(conf *sriovtypes.NetConf, podifName string, netns tempName := fmt.Sprintf("%s%d", "temp_", linkObj.Attrs().Index) // 1. Set link down + logging.Debug("1. Set link down", + "func", "SetupVF", + "linkObj", linkObj) if err := s.nLink.LinkSetDown(linkObj); err != nil { return fmt.Errorf("failed to down vf device %q: %v", linkName, err) } // 2. Set temp name + logging.Debug("2. Set temp name", + "func", "SetupVF", + "linkObj", linkObj, + "tempName", tempName) if err := s.nLink.LinkSetName(linkObj, tempName); err != nil { return fmt.Errorf("error setting temp IF name %s for %s", tempName, linkName) } @@ -82,6 +91,11 @@ func (s *sriovManager) SetupVF(conf *sriovtypes.NetConf, podifName string, netns conf.OrigVfState.EffectiveMAC = linkObj.Attrs().HardwareAddr.String() // 3. Set MAC address if conf.MAC != "" { + logging.Debug("3. Set MAC address", + "func", "SetupVF", + "s.nLink", s.nLink, + "tempName", tempName, + "conf.MAC", conf.MAC) err = utils.SetVFEffectiveMAC(s.nLink, tempName, conf.MAC) if err != nil { return fmt.Errorf("failed to set netlink MAC address to %s: %v", conf.MAC, err) @@ -89,21 +103,35 @@ func (s *sriovManager) SetupVF(conf *sriovtypes.NetConf, podifName string, netns } // 4. Change netns + logging.Debug("4. Change netns", + "func", "SetupVF", + "linkObj", linkObj, + "netns.Fd()", int(netns.Fd())) if err := s.nLink.LinkSetNsFd(linkObj, int(netns.Fd())); err != nil { return fmt.Errorf("failed to move IF %s to netns: %q", tempName, err) } if err := netns.Do(func(_ ns.NetNS) error { // 5. Set Pod IF name + logging.Debug("5. Set Pod IF name", + "func", "SetupVF", + "linkObj", linkObj, + "podifName", podifName) if err := s.nLink.LinkSetName(linkObj, podifName); err != nil { return fmt.Errorf("error setting container interface name %s for %s", linkName, tempName) } // 6. Enable IPv4 ARP notify and IPv6 Network Discovery notify // Error is ignored here because enabling this feature is only a performance enhancement. + logging.Debug("6. Enable IPv4 ARP notify and IPv6 Network Discovery notify", + "func", "SetupVF", + "podifName", podifName) _ = s.utils.EnableArpAndNdiscNotify(podifName) // 7. Bring IF up in Pod netns + logging.Debug("7. Bring IF up in Pod netns", + "func", "SetupVF", + "linkObj", linkObj) if err := s.nLink.LinkSetUp(linkObj); err != nil { return fmt.Errorf("error bringing interface up in container ns: %q", err) } @@ -125,17 +153,27 @@ func (s *sriovManager) ReleaseVF(conf *sriovtypes.NetConf, podifName string, net return netns.Do(func(_ ns.NetNS) error { // get VF device + logging.Debug("Get VF device", + "func", "ReleaseVF", + "podifName", podifName) linkObj, err := s.nLink.LinkByName(podifName) if err != nil { return fmt.Errorf("failed to get netlink device with name %s: %q", podifName, err) } // shutdown VF device + logging.Debug("Shutdown VF device", + "func", "ReleaseVF", + "linkObj", linkObj) if err = s.nLink.LinkSetDown(linkObj); err != nil { return fmt.Errorf("failed to set link %s down: %q", podifName, err) } // rename VF device + logging.Debug("Rename VF device", + "func", "ReleaseVF", + "linkObj", linkObj, + "conf.OrigVfState.HostIFName", conf.OrigVfState.HostIFName) err = s.nLink.LinkSetName(linkObj, conf.OrigVfState.HostIFName) if err != nil { return fmt.Errorf("failed to rename link %s to host name %s: %q", podifName, conf.OrigVfState.HostIFName, err) @@ -143,6 +181,11 @@ func (s *sriovManager) ReleaseVF(conf *sriovtypes.NetConf, podifName string, net if conf.MAC != "" { // reset effective MAC address + logging.Debug("Reset effective MAC address", + "func", "ReleaseVF", + "s.nLink", s.nLink, + "conf.OrigVfState.HostIFName", conf.OrigVfState.HostIFName, + "conf.OrigVfState.EffectiveMAC", conf.OrigVfState.EffectiveMAC) err = utils.SetVFEffectiveMAC(s.nLink, conf.OrigVfState.HostIFName, conf.OrigVfState.EffectiveMAC) if err != nil { return fmt.Errorf("failed to restore original effective netlink MAC address %s: %v", conf.OrigVfState.EffectiveMAC, err) @@ -150,6 +193,10 @@ func (s *sriovManager) ReleaseVF(conf *sriovtypes.NetConf, podifName string, net } // move VF device to init netns + logging.Debug("Move VF device to init netns", + "func", "ReleaseVF", + "linkObj", linkObj, + "initns.Fd()", int(initns.Fd())) if err = s.nLink.LinkSetNsFd(linkObj, int(initns.Fd())); err != nil { return fmt.Errorf("failed to move interface %s to init netns: %v", conf.OrigVfState.HostIFName, err) } diff --git a/pkg/types/types.go b/pkg/types/types.go index ab279f42b..c8724f714 100644 --- a/pkg/types/types.go +++ b/pkg/types/types.go @@ -60,4 +60,6 @@ type NetConf struct { RuntimeConfig struct { Mac string `json:"mac,omitempty"` } `json:"runtimeConfig,omitempty"` + LogLevel string `json:"logLevel,omitempty"` + LogFile string `json:"logFile,omitempty"` } diff --git a/pkg/utils/pci_allocator.go b/pkg/utils/pci_allocator.go index 1dd7201ce..3bf6ff054 100644 --- a/pkg/utils/pci_allocator.go +++ b/pkg/utils/pci_allocator.go @@ -2,9 +2,11 @@ package utils import ( "fmt" - "github.com/containernetworking/plugins/pkg/ns" "os" "path/filepath" + + "github.com/containernetworking/plugins/pkg/ns" + "github.com/k8snetworkplumbingwg/sriov-cni/pkg/logging" ) type PCIAllocation interface { @@ -73,6 +75,9 @@ func (p *PCIAllocator) IsAllocated(pciAddress string) (bool, error) { // we release the PCI address networkNamespace, err := ns.GetNS(string(dat)) if err != nil { + logging.Debug("Mark the PCI address as released", + "func", "IsAllocated", + "pciAddress", pciAddress) err = p.DeleteAllocatedPCI(pciAddress) if err != nil { return false, fmt.Errorf("error deleting the pci allocation for vf pci address %s: %v", pciAddress, err)