Add more logging to SubnetAllocatorService

Change-Id: Iee4ecdacd86907f06d39c720ad6adac7b53e7b84

java/cloud-store/src/main/java/com/vmware/photon/controller/cloudstore/xenon/entity/SubnetAllocatorService.java

@@ -111,12 +111,23 @@ public static class AllocateSubnet extends ServiceDocument {
     public String subnetId;
     public Long numberOfAllIpAddresses;
     public Long numberOfStaticIpAddresses;
+    // This switch is used to determine whether we want more logging in handle allocation.
+    // We purposely disable it in unit test since we have a UT that generates a lot of small subnets,
+    // and hence runs out of memory.
+    // By default it is true in production. This gives us more insight of how the subnet allocation
+    // algorithm performs. It should not cause memory issue since the log is directed to a rotating file.
+    public Boolean verbose;
 
     private AllocateSubnet() {
       kind = null;
     }
 
     public AllocateSubnet(String subnetId, Long numberOfAllIpAddresses, Long numberOfStaticIpAddresses) {
+      this(subnetId, numberOfAllIpAddresses, numberOfStaticIpAddresses, true);
+    }
+
+    public AllocateSubnet(String subnetId, Long numberOfAllIpAddresses, Long numberOfStaticIpAddresses,
+      Boolean verbose) {
       if (subnetId == null) {
         throw new IllegalArgumentException("subnetId cannot be null");
       }
@@ -142,6 +153,7 @@ public AllocateSubnet(String subnetId, Long numberOfAllIpAddresses, Long numberO
       this.subnetId = subnetId;
       this.numberOfAllIpAddresses = numberOfAllIpAddresses;
       this.numberOfStaticIpAddresses = numberOfStaticIpAddresses;
+      this.verbose = verbose;
     }
   }
 
@@ -156,26 +168,40 @@ public static class ReleaseSubnet extends ServiceDocument {
 
     //Input
     public String subnetId;
+    // This switch is used to determine whether we want more logging in handle allocation.
+    // We purposely disable it in unit test since we have a UT that generates a lot of small subnets,
+    // and hence runs out of memory.
+    // By default it is true in production. This gives us more insight of how the subnet allocation
+    // algorithm performs. It should not cause memory issue since the log is directed to a rotating file.
+    public Boolean verbose;
 
     private ReleaseSubnet() {
       kind = null;
     }
 
     public ReleaseSubnet(String subnetId) {
+      this(subnetId, true);
+    }
+
+    public ReleaseSubnet(String subnetId, Boolean verbose) {
       if (subnetId == null) {
         throw new IllegalArgumentException("subnetId cannot be null");
       }
 
       this.kind = KIND;
       this.subnetId = subnetId;
+      this.verbose = verbose;
     }
   }
 
   public void handleAllocateSubnet(Operation patch) {
-    ServiceUtils.logInfo(this, "Allocating subnet %s", getSelfLink());
-
     AllocateSubnet allocateSubnetPatch = patch.getBody(AllocateSubnet.class);
     State currentState = getState(patch);
+    ServiceUtils.logInfo(this, "Allocating subnet: %s", allocateSubnetPatch.subnetId);
+
+    if (allocateSubnetPatch.verbose) {
+      ServiceUtils.logInfo(this, "Subnet size to be allocated: %d", allocateSubnetPatch.numberOfAllIpAddresses);
+    }
 
     try {
       Long requestedSize = allocateSubnetPatch.numberOfAllIpAddresses;
@@ -186,6 +212,13 @@ public void handleAllocateSubnet(Operation patch) {
       int inverseSubnetMask = IpHelper.safeLongToInt(requestedSize - 1);
       int subnetMask = ~(inverseSubnetMask);
 
+      if (allocateSubnetPatch.verbose) {
+        currentState.freeList.stream().forEach(
+            range -> ServiceUtils.logInfo(this, "Free range before allocation: %d to %d", range.low, range.high));
+        candidateRanges.stream().forEach(
+            range -> ServiceUtils.logInfo(this, "Candidate free range: %d to %d", range.low, range.high));
+      }
+
       IpV4Range createdIpv4Range = null;
       IpV4Range selectedIpv4Range = null;
 
@@ -210,14 +243,24 @@ public void handleAllocateSubnet(Operation patch) {
         return;
       }
 
+      if (allocateSubnetPatch.verbose) {
+        ServiceUtils.logInfo(this, "Selected range: %d to %d", selectedIpv4Range.low, selectedIpv4Range.high);
+      }
+
       currentState.freeList.remove(selectedIpv4Range);
       if (createdIpv4Range.low > selectedIpv4Range.low) {
         IpV4Range lowRange = new IpV4Range(selectedIpv4Range.low, createdIpv4Range.low - 1);
+        if (allocateSubnetPatch.verbose) {
+          ServiceUtils.logInfo(this, "Insert low free range: %d to %d", lowRange.low, lowRange.high);
+        }
         currentState.freeList.add(lowRange);
       }
 
       if (createdIpv4Range.high < selectedIpv4Range.high) {
         IpV4Range highRange = new IpV4Range(createdIpv4Range.high + 1, selectedIpv4Range.high);
+        if (allocateSubnetPatch.verbose) {
+          ServiceUtils.logInfo(this, "Insert high free range: %d to %d", highRange.low, highRange.high);
+        }
         currentState.freeList.add(highRange);
       }
 
@@ -250,6 +293,11 @@ public void handleAllocateSubnet(Operation patch) {
       ServiceUtils.doServiceOperation(this, postOperation);
 
       setState(patch, currentState);
+
+      if (allocateSubnetPatch.verbose) {
+        currentState.freeList.stream().forEach(
+            range -> ServiceUtils.logInfo(this, "Free range after allocation: %d to %d", range.low, range.high));
+      }
       patch.complete();
     } catch (Throwable t) {
       ServiceUtils.logSevere(this, t);
@@ -258,9 +306,9 @@ public void handleAllocateSubnet(Operation patch) {
   }
 
   public void handleReleaseSubnet(Operation patch) {
-    ServiceUtils.logInfo(this, "Releasing subnet %s", getSelfLink());
     ReleaseSubnet releaseSubnetPatch = patch.getBody(ReleaseSubnet.class);
     State currentState = getState(patch);
+    ServiceUtils.logInfo(this, "Releaing subnet: %s", releaseSubnetPatch.subnetId);
 
     try {
       Operation getOperation =
@@ -278,6 +326,11 @@ public void handleReleaseSubnet(Operation patch) {
           Operation.createDelete(this, subnetState.documentSelfLink);
       ServiceUtils.doServiceOperation(this, deleteOperation);
 
+      if (releaseSubnetPatch.verbose) {
+        currentState.freeList.stream().forEach(
+            range -> ServiceUtils.logInfo(this, "Free range before release: %d to %d", range.low, range.high));
+      }
+
       IpV4Range targetRange = new IpV4Range(subnetState.lowIp, subnetState.highIp);
       List<IpV4Range> currentFreeList = currentState.freeList
           .stream()
@@ -300,6 +353,11 @@ public void handleReleaseSubnet(Operation patch) {
       newFreeList.add(targetRange);
       currentState.freeList = newFreeList;
 
+      if (releaseSubnetPatch.verbose) {
+        currentState.freeList.stream().forEach(
+            range -> ServiceUtils.logInfo(this, "Free range after release: %d to %d", range.low, range.high));
+      }
+
       patch.complete();
     } catch (Throwable t) {
       ServiceUtils.logSevere(this, t);

java/cloud-store/src/test/java/com/vmware/photon/controller/cloudstore/xenon/entity/SubnetAllocatorServiceTest.java

@@ -587,7 +587,7 @@ public void testLargeNumberOfSubnetAllocations()
 
         SubnetAllocatorService.AllocateSubnet allocateSubnetPatch =
             new SubnetAllocatorService.AllocateSubnet(
-                i.toString(), 8L, 2L);
+                i.toString(), 8L, 2L, false);
         patchOperation.setBody(allocateSubnetPatch);
 
         Operation completedOperation = host.sendRequestAndWait(patchOperation);
@@ -615,7 +615,7 @@ public void testLargeNumberOfSubnetAllocations()
             .setUri(UriUtils.buildUri(host, startState.documentSelfLink));
 
         SubnetAllocatorService.ReleaseSubnet releaseSubnetPatch =
-            new SubnetAllocatorService.ReleaseSubnet(i.toString());
+            new SubnetAllocatorService.ReleaseSubnet(i.toString(), false);
         patchOperation.setBody(releaseSubnetPatch);
 
         Operation completedOperation = host.sendRequestAndWait(patchOperation);