Add logs to vl3-ipam server

pkg/ipam/vl3ipam/server.go

@@ -21,10 +21,13 @@ import (
 	"net"
 	"sync"
 
+	"github.com/google/uuid"
+
 	"github.com/networkservicemesh/api/pkg/api/ipam"
 	"github.com/pkg/errors"
 
 	"github.com/networkservicemesh/sdk/pkg/tools/ippool"
+	"github.com/networkservicemesh/sdk/pkg/tools/log"
 )
 
 // ErrUndefined means that operation is not supported
@@ -51,11 +54,10 @@ func NewIPAMServer(prefix string, initialNSEPrefixSize uint8) ipam.IPAMServer {
 var _ ipam.IPAMServer = (*vl3IPAMServer)(nil)
 
 func (s *vl3IPAMServer) ManagePrefixes(prefixServer ipam.IPAM_ManagePrefixesServer) error {
-	var pool = s.pool
-	var mutex = &s.poolMutex
 	var clientsPrefixes []string
 	var err error
 
+	logger := log.Default().WithField("ID", uuid.New().String())
 	for err == nil {
 		var r *ipam.PrefixRequest
 
@@ -64,64 +66,83 @@ func (s *vl3IPAMServer) ManagePrefixes(prefixServer ipam.IPAM_ManagePrefixesServ
 			break
 		}
 
+		logger.Debugf("PrefixRequest: %v", r.String())
 		switch r.Type {
 		case ipam.Type_UNDEFINED:
 			return ErrUndefined
 
 		case ipam.Type_ALLOCATE:
-			var resp ipam.PrefixResponse
-			mutex.Lock()
-			for _, excludePrefix := range r.ExcludePrefixes {
-				pool.ExcludeString(excludePrefix)
-			}
-			resp.Prefix = r.Prefix
-			if resp.Prefix == "" || !pool.ContainsNetString(resp.Prefix) {
-				var ip net.IP
-				ip, err = pool.Pull()
-				if err != nil {
-					mutex.Unlock()
-					break
-				}
-				ipNet := &net.IPNet{
-					IP: ip,
-					Mask: net.CIDRMask(
-						int(s.initalSize),
-						len(ip)*8,
-					),
-				}
-				resp.Prefix = ipNet.String()
+			var resp *ipam.PrefixResponse
+			resp, err = s.allocate(r)
+			if err != nil {
+				break
 			}
-			s.excludedPrefixes = append(s.excludedPrefixes, r.Prefix)
 			clientsPrefixes = append(clientsPrefixes, resp.Prefix)
-			pool.ExcludeString(resp.Prefix)
-			mutex.Unlock()
-			resp.ExcludePrefixes = r.ExcludePrefixes
-			resp.ExcludePrefixes = append(resp.ExcludePrefixes, s.excludedPrefixes...)
-			err = prefixServer.Send(&resp)
+			err = prefixServer.Send(resp)
+			logger.Debugf("Allocated: %v", resp.String())
 
 		case ipam.Type_DELETE:
 			for i, p := range clientsPrefixes {
 				if p != r.Prefix {
 					continue
 				}
-				mutex.Lock()
-				pool.AddNetString(p)
-				mutex.Unlock()
+				s.delete(r)
 				clientsPrefixes = append(clientsPrefixes[:i], clientsPrefixes[i+1:]...)
+				logger.Debugf("Deleted: %v", r.Prefix)
 				break
 			}
 		}
 	}
 
 	s.poolMutex.Lock()
 	for _, prefix := range clientsPrefixes {
-		pool.AddNetString(prefix)
+		s.pool.AddNetString(prefix)
 	}
 	s.poolMutex.Unlock()
+	logger.Debugf("Disconnected. Error: %v", err.Error())
+	logger.Debugf("Deleted: %v", clientsPrefixes)
 
 	if prefixServer.Context().Err() != nil {
 		return nil
 	}
 
 	return errors.Wrap(err, "failed to manage prefixes")
 }
+
+func (s *vl3IPAMServer) allocate(r *ipam.PrefixRequest) (*ipam.PrefixResponse, error) {
+	s.poolMutex.Lock()
+	// We don't need to exclude prefixes which were indicated in the PrefixRequest from the main pool
+	pool := s.pool.Clone()
+	for _, excludePrefix := range r.ExcludePrefixes {
+		pool.ExcludeString(excludePrefix)
+	}
+	resp := &ipam.PrefixResponse{
+		Prefix: r.Prefix,
+	}
+	if resp.Prefix == "" || !s.pool.ContainsNetString(resp.Prefix) {
+		ip, err := pool.Pull()
+		if err != nil {
+			s.poolMutex.Unlock()
+			return nil, err
+		}
+		ipNet := &net.IPNet{
+			IP: ip,
+			Mask: net.CIDRMask(
+				int(s.initalSize),
+				len(ip)*8,
+			),
+		}
+		resp.Prefix = ipNet.String()
+	}
+	s.pool.ExcludeString(resp.Prefix)
+	s.poolMutex.Unlock()
+	resp.ExcludePrefixes = r.ExcludePrefixes
+	resp.ExcludePrefixes = append(resp.ExcludePrefixes, s.excludedPrefixes...)
+	return resp, nil
+}
+
+func (s *vl3IPAMServer) delete(r *ipam.PrefixRequest) {
+	s.poolMutex.Lock()
+	s.pool.AddNetString(r.Prefix)
+	s.poolMutex.Unlock()
+}

pkg/ipam/vl3ipam/server_test.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2022 Cisco and/or its affiliates.
+// Copyright (c) 2022-2023 Cisco and/or its affiliates.
 //
 // SPDX-License-Identifier: Apache-2.0
 //
@@ -34,6 +34,7 @@ import (
 	"github.com/networkservicemesh/sdk/pkg/tools/grpcutils"
 )
 
+// nolint:unparam
 func newVL3IPAMServer(ctx context.Context, t *testing.T, prefix string, initialSize uint8) url.URL {
 	var s = grpc.NewServer()
 	ipam.RegisterIPAMServer(s, vl3ipam.NewIPAMServer(prefix, initialSize))
@@ -87,7 +88,7 @@ func Test_vl3_IPAM_Allocate(t *testing.T) {
 		require.NoError(t, err)
 
 		require.Equal(t, fmt.Sprintf("172.16.%v.0/24", i), resp.Prefix, i)
-		require.NotEmpty(t, resp.ExcludePrefixes)
+		require.Empty(t, resp.ExcludePrefixes)
 	}
 }
 
@@ -117,7 +118,7 @@ func Test_vl3_IPAM_Allocate2(t *testing.T) {
 		require.NoError(t, err)
 
 		require.Equal(t, "173.16.0.0/24", resp.Prefix, i)
-		require.NotEmpty(t, resp.ExcludePrefixes, i)
+		require.Empty(t, resp.ExcludePrefixes, i)
 		cancel()
 		time.Sleep(time.Millisecond * 50)
 	}
@@ -151,8 +152,41 @@ func Test_vl3_IPAM_Allocate3(t *testing.T) {
 		require.NoError(t, err)
 
 		require.Equal(t, "172.16.0.0/30", resp.Prefix, i)
-		require.NotEmpty(t, resp.ExcludePrefixes, i)
+		require.Empty(t, resp.ExcludePrefixes, i)
 		cancel()
 		time.Sleep(time.Millisecond * 50)
 	}
 }
+
+func Test_vl3_IPAM_Allocate4(t *testing.T) {
+	t.Cleanup(func() {
+		goleak.VerifyNone(t)
+	})
+
+	var ctx, cancel = context.WithTimeout(context.Background(), time.Second*5)
+	defer cancel()
+
+	connectTO := newVL3IPAMServer(ctx, t, "172.16.0.0/16", 24)
+
+	var excludedPrefixes []string
+	for i := 0; i < 20; i += 2 {
+		c := newVL3IPAMClient(ctx, t, &connectTO)
+
+		var stream, err = c.ManagePrefixes(ctx)
+		require.NoError(t, err, i)
+
+		excludedPrefixes = append(excludedPrefixes, fmt.Sprintf("172.16.%d.0/24", i))
+		err = stream.Send(&ipam.PrefixRequest{
+			Type:            ipam.Type_ALLOCATE,
+			ExcludePrefixes: excludedPrefixes,
+		})
+
+		require.NoError(t, err)
+
+		resp, err := stream.Recv()
+		require.NoError(t, err)
+
+		require.Equal(t, fmt.Sprintf("172.16.%v.0/24", i+1), resp.Prefix, i)
+		require.NotEmpty(t, resp.ExcludePrefixes, i)
+	}
+}