Use structured logging in ipam

Author: Lars Ekman

cmd/ipam/main.go

@@ -26,15 +26,16 @@ import (
 	"strings"
 	"syscall"
 
+	"github.com/go-logr/logr"
 	"github.com/kelseyhightower/envconfig"
 	ipamAPI "github.com/nordix/meridio/api/ipam/v1"
 	"github.com/nordix/meridio/pkg/health"
 	"github.com/nordix/meridio/pkg/health/connection"
 	"github.com/nordix/meridio/pkg/health/probe"
 	"github.com/nordix/meridio/pkg/ipam"
 	"github.com/nordix/meridio/pkg/ipam/types"
+	"github.com/nordix/meridio/pkg/log"
 	"github.com/nordix/meridio/pkg/security/credentials"
-	"github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
 	grpcHealth "google.golang.org/grpc/health"
 	"google.golang.org/grpc/health/grpc_health_v1"
@@ -63,11 +64,16 @@ func main() {
 		os.Exit(0)
 	}
 
-	logrus.SetOutput(os.Stdout)
-	logrus.SetLevel(logrus.DebugLevel)
+	var config Config
+	err := envconfig.Process("ipam", &config)
+	if err != nil {
+		panic(err)
+	}
+	logger := log.New("Meridio-ipam", config.LogLevel)
+	logger.Info("Configuration read", "config", config)
 
 	ctx, cancel := signal.NotifyContext(
-		context.Background(),
+		logr.NewContext(context.Background(), logger),
 		os.Interrupt,
 		syscall.SIGHUP,
 		syscall.SIGTERM,
@@ -78,25 +84,9 @@ func main() {
 	// create and start health server
 	ctx = health.CreateChecker(ctx)
 	if err := health.RegisterReadinesSubservices(ctx, health.IPAMReadinessServices...); err != nil {
-		logrus.Warnf("%v", err)
+		logger.Error(err, "RegisterReadinesSubservices")
 	}
 
-	var config Config
-	err := envconfig.Process("ipam", &config)
-	if err != nil {
-		logrus.Fatalf("%v", err)
-	}
-	logrus.Infof("rootConf: %+v", config)
-
-	logrus.SetLevel(func() logrus.Level {
-
-		l, err := logrus.ParseLevel(config.LogLevel)
-		if err != nil {
-			logrus.Fatalf("invalid log level %s", config.LogLevel)
-		}
-		return l
-	}())
-
 	// connect NSP
 	conn, err := grpc.DialContext(
 		ctx,
@@ -108,13 +98,13 @@ func main() {
 			grpc.WaitForReady(true),
 		))
 	if err != nil {
-		logrus.Fatalf("Dial NSP err: %v", err)
+		log.Fatal(logger, "Dial NSP err", "error", err)
 	}
 	defer conn.Close()
 
 	// monitor status of NSP connection and adjust probe status accordingly
 	if err := connection.Monitor(ctx, health.NSPCliSvc, conn); err != nil {
-		logrus.Warnf("NSP connection state monitor err: %v", err)
+		logger.Error(err, "NSP connection state monitor")
 	}
 
 	prefixLengths := make(map[ipamAPI.IPFamily]*types.PrefixLengths)
@@ -133,9 +123,10 @@ func main() {
 	}
 
 	// cteate IPAM server
-	ipamServer, err := ipam.NewServer(config.Datasource, config.TrenchName, conn, cidrs, prefixLengths)
+	ipamServer, err := ipam.NewServer(
+		ctx, config.Datasource, config.TrenchName, conn, cidrs, prefixLengths)
 	if err != nil {
-		logrus.Fatalf("Unable to create ipam server: %v", err)
+		logger.Error(err, "Unable to create ipam server")
 	}
 
 	server := grpc.NewServer(grpc.Creds(
@@ -145,17 +136,17 @@ func main() {
 	healthServer := grpcHealth.NewServer()
 	grpc_health_v1.RegisterHealthServer(server, healthServer)
 
-	logrus.Infof("IPAM Service: Start the service (port: %v)", config.Port)
+	logger.Info("Start the service", "port", config.Port)
 	listener, err := net.Listen("tcp", fmt.Sprintf("[::]:%d", config.Port))
 	if err != nil {
-		logrus.Fatalf("IPAM Service: failed to listen: %v", err)
+		log.Fatal(logger, "Failed to listen", "error", err)
 	}
 
 	// internal probe checking health of IPAM server
 	probe.CreateAndRunGRPCHealthProbe(ctx, health.IPAMSvc, probe.WithAddress(fmt.Sprintf(":%d", config.Port)), probe.WithSpiffe())
 
 	if err := startServer(ctx, server, listener); err != nil {
-		logrus.Errorf("IPAM Service: failed to serve: %v", err)
+		logger.Error(err, "IPAM Service: failed to serve: %v")
 	}
 }
 

deployments/helm/templates/ipam.yaml

@@ -56,6 +56,8 @@ spec:
               value: "{{ .Values.subnetPool.nodePrefixLength.ipv6 }}"
             - name: IPAM_IP_FAMILY
               value: "{{ .Values.ipFamily }}"
+            - name: LOG_FORMAT
+              value: "ADP"
           securityContext:
             runAsNonRoot: true
             readOnlyRootFilesystem: true

pkg/health/checker.go

@@ -26,7 +26,7 @@ import (
 	"path"
 	"sync"
 
-	"github.com/sirupsen/logrus"
+	"github.com/nordix/meridio/pkg/log"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/health"
 	"google.golang.org/grpc/health/grpc_health_v1"
@@ -57,7 +57,10 @@ func (c *Checker) RegisterServices(probeSvc string, services ...string) {
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	logrus.Debugf("Health server: Register subservices for probeSvc=%v, services=%v", probeSvc, services)
+	logger := log.FromContextOrDefault(c.ctx)
+	logger.V(1).Info(
+		"Health server: Register subservices", "probeSvc", probeSvc,
+		"services", services)
 
 	components, ok := c.subServices[probeSvc]
 	if !ok {
@@ -79,7 +82,6 @@ func (c *Checker) RegisterServices(probeSvc string, services ...string) {
 // Re-implements Check() function of grpc_health_v1.HealthServer interface
 // in order to log if a probe service is about to fail.
 func (c *Checker) Check(ctx context.Context, in *grpc_health_v1.HealthCheckRequest) (*grpc_health_v1.HealthCheckResponse, error) {
-	//logrus.Debugf("Checker: Check service=%v", in.Service)
 
 	switch in.Service {
 	case Startup:
@@ -103,7 +105,10 @@ func (c *Checker) Check(ctx context.Context, in *grpc_health_v1.HealthCheckReque
 				}
 				svcInfo += `]`
 			}
-			logrus.Infof(`Probe service "%v" [%v]%v`, in.Service, resp.Status, svcInfo)
+			logger := log.FromContextOrDefault(c.ctx)
+			logger.Info(
+				"Probe service", "Service", in.Service,
+				"Status", resp.Status, "svcInfo", svcInfo)
 		}
 		return resp, err
 	default:
@@ -117,7 +122,6 @@ func (c *Checker) SetServingStatus(service string, servingStatus grpc_health_v1.
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	//logrus.Debugf("Checker: Set serving status for service=%v, status=%v", service, servingStatus)
 	switch service {
 	case Startup:
 		fallthrough
@@ -149,7 +153,6 @@ func (c *Checker) SetServingStatus(service string, servingStatus grpc_health_v1.
 							}
 						}
 					}
-					//logrus.Debugf(`SetServingStatus: probe service "%v" [%v]`, probeSvc, probeStatus)
 					c.HealthServerStatusModifier.SetServingStatus(probeSvc, probeStatus)
 				}
 			}

pkg/ipam/server.go

@@ -21,29 +21,35 @@ import (
 	"fmt"
 	"net"
 
+	"github.com/go-logr/logr"
 	ipamAPI "github.com/nordix/meridio/api/ipam/v1"
 	"github.com/nordix/meridio/pkg/ipam/prefix"
 	"github.com/nordix/meridio/pkg/ipam/storage/sqlite"
 	"github.com/nordix/meridio/pkg/ipam/trench"
 	"github.com/nordix/meridio/pkg/ipam/types"
-	"github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
 	"google.golang.org/protobuf/types/known/emptypb"
 )
 
 type IpamServer struct {
+	ctx    context.Context
+	logger logr.Logger
 	ipamAPI.UnimplementedIpamServer
 	Trenches      map[ipamAPI.IPFamily]types.Trench
 	PrefixLengths map[ipamAPI.IPFamily]*types.PrefixLengths
 }
 
 // NewIpam -
-func NewServer(datastore string,
+func NewServer(
+	ctx context.Context,
+	datastore string,
 	trenchName string,
 	nspConn *grpc.ClientConn,
 	cidrs map[ipamAPI.IPFamily]string,
 	prefixLengths map[ipamAPI.IPFamily]*types.PrefixLengths) (ipamAPI.IpamServer, error) {
 	is := &IpamServer{
+		ctx:           ctx,
+		logger:        logr.FromContextOrDiscard(ctx),
 		Trenches:      make(map[ipamAPI.IPFamily]types.Trench),
 		PrefixLengths: prefixLengths,
 	}
@@ -56,14 +62,14 @@ func NewServer(datastore string,
 	for ipFamily, cidr := range cidrs {
 		name := getTrenchName(trenchName, ipFamily)
 		prefix := prefix.New(name, cidr, nil)
-		newTrench, err := trench.New(context.TODO(), prefix, store, is.PrefixLengths[ipFamily])
+		newTrench, err := trench.New(ctx, prefix, store, is.PrefixLengths[ipFamily])
 		if err != nil {
 			return nil, err
 		}
 		is.Trenches[ipFamily] = newTrench
 		trenchWatchers = append(trenchWatchers, newTrench)
 	}
-	conduitWatcher, err := trench.NewConduitWatcher(context.TODO(), nspConn, trenchName, trenchWatchers)
+	conduitWatcher, err := trench.NewConduitWatcher(ctx, nspConn, trenchName, trenchWatchers)
 	if err != nil {
 		return nil, err
 	}
@@ -73,7 +79,7 @@ func NewServer(datastore string,
 }
 
 func (is *IpamServer) Allocate(ctx context.Context, child *ipamAPI.Child) (*ipamAPI.Prefix, error) {
-	logrus.Infof("Allocate: %v", child)
+	is.logger.Info("Allocate", "child", child)
 	trench, exists := is.Trenches[child.GetSubnet().GetIpFamily()]
 	if !exists {
 		return nil, fmt.Errorf("cannot allocate in this ip family")
@@ -120,7 +126,7 @@ func (is *IpamServer) Allocate(ctx context.Context, child *ipamAPI.Child) (*ipam
 }
 
 func (is *IpamServer) Release(ctx context.Context, child *ipamAPI.Child) (*emptypb.Empty, error) {
-	logrus.Infof("Release: %v", child)
+	is.logger.Info("Release", "child", child)
 	trench, exists := is.Trenches[child.GetSubnet().GetIpFamily()]
 	if !exists {
 		return &emptypb.Empty{}, nil

pkg/security/credentials/credentials.go

@@ -3,7 +3,7 @@ package credentials
 import (
 	"context"
 
-	"github.com/sirupsen/logrus"
+	"github.com/nordix/meridio/pkg/log"
 	"github.com/spiffe/go-spiffe/v2/spiffegrpc/grpccredentials"
 	"github.com/spiffe/go-spiffe/v2/spiffetls/tlsconfig"
 	"github.com/spiffe/go-spiffe/v2/svid/x509svid"
@@ -30,15 +30,16 @@ func GetServerWithSource(ctx context.Context, source *workloadapi.X509Source) cr
 
 func GetX509Source(ctx context.Context) *workloadapi.X509Source {
 	// todo: retry if source in nil or empty
+	logger := log.FromContextOrDefault(ctx)
 	source, err := workloadapi.NewX509Source(ctx)
 	if err != nil {
-		logrus.Errorf("error getting x509 source: %v", err)
+		logger.Error(err, "error getting x509 source")
 	}
 	var svid *x509svid.SVID
 	svid, err = source.GetX509SVID()
 	if err != nil {
-		logrus.Errorf("error getting x509 svid: %v", err)
+		logger.Error(err, "error getting x509 svid")
 	}
-	logrus.Infof("sVID: %q", svid.ID)
+	logger.Info("GetX509Source", "sVID", svid.ID)
 	return source
 }