From f3242465e8931ac2edb7fc7d4f8ad6408fceca18 Mon Sep 17 00:00:00 2001 From: Miguel Duarte Barroso Date: Thu, 17 Aug 2023 15:24:06 +0200 Subject: [PATCH 1/2] logging: use the RFC3399Nano timestamp format The old format - RFC3339 - does not have enough precision - we need to see milliseconds (at least) to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage. Signed-off-by: Miguel Duarte Barroso --- pkg/logging/logging.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 5d1b59305..a321f7862 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -40,7 +40,7 @@ var loggingStderr bool var loggingFp *os.File var loggingLevel Level -const defaultTimestampFormat = time.RFC3339 +const defaultTimestampFormat = time.RFC3339Nano func (l Level) String() string { switch l { From 55ab6807285db5f3775319863f1bd6b0e8262899 Mon Sep 17 00:00:00 2001 From: Miguel Duarte Barroso Date: Thu, 17 Aug 2023 15:50:05 +0200 Subject: [PATCH 2/2] logging: add logging to measure the CNI processing times We were missing a clear log indicating the IPAM CNI process is finishing. Now, it should be possible to understand how long a request takes from the logs. Signed-off-by: Miguel Duarte Barroso --- cmd/whereabouts.go | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/cmd/whereabouts.go b/cmd/whereabouts.go index 0e84ee91c..4e4b8c6cd 100644 --- a/cmd/whereabouts.go +++ b/cmd/whereabouts.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "net" + "time" "github.com/containernetworking/cni/pkg/skel" cnitypes "github.com/containernetworking/cni/pkg/types" @@ -18,18 +19,24 @@ import ( ) func main() { + var startTime time.Time skel.PluginMain(func(args *skel.CmdArgs) error { ipamConf, confVersion, err := config.LoadIPAMConfig(args.StdinData, args.Args) if err != nil { logging.Errorf("IPAM configuration load failed: %s", err) return err } - logging.Debugf("ADD - IPAM configuration successfully read: %+v", *ipamConf) + + startTime = time.Now() + logging.Debugf("ADD - IPAM plugin start. Config: %+v", *ipamConf) ipam, err := kubernetes.NewKubernetesIPAM(args.ContainerID, *ipamConf) if err != nil { return logging.Errorf("failed to create Kubernetes IPAM manager: %v", err) } - defer func() { safeCloseKubernetesBackendConnection(ipam) }() + defer func() { + safeCloseKubernetesBackendConnection(ipam) + logging.Debugf("ADD - IPAM plugin finished. Took: %q Config: %+v", time.Since(startTime).String(), *ipamConf) + }() return cmdAdd(args, ipam, confVersion) }, cmdCheck, @@ -39,13 +46,17 @@ func main() { logging.Errorf("IPAM configuration load failed: %s", err) return err } - logging.Debugf("DEL - IPAM configuration successfully read: %+v", *ipamConf) + startTime = time.Now() + logging.Debugf("DEL - IPAM plugin start. Config: %+v", *ipamConf) ipam, err := kubernetes.NewKubernetesIPAM(args.ContainerID, *ipamConf) if err != nil { return logging.Errorf("IPAM client initialization error: %v", err) } - defer func() { safeCloseKubernetesBackendConnection(ipam) }() + defer func() { + safeCloseKubernetesBackendConnection(ipam) + logging.Debugf("DEL - IPAM plugin finished. Took: %q Config: %+v", time.Since(startTime).String(), *ipamConf) + }() return cmdDel(args, ipam) }, cniversion.All,