chore: improve IPAM logging (#3049)

Signed-off-by: Evan Baker <rbtr@users.noreply.github.com>
Azure · Oct 7, 2024 · f7f98d4 · f7f98d4
1 parent 391dc3a
commit f7f98d4
Show file tree

Hide file tree

Showing 5 changed files with 43 additions and 35 deletions.
diff --git a/cns/ipampool/v2/monitor.go b/cns/ipampool/v2/monitor.go
@@ -124,6 +124,7 @@ func (pm *Monitor) reconcile(ctx context.Context) error {
 	pm.z.Info("calculated new request", zap.Int64("demand", pm.demand), zap.Int64("batch", s.batch), zap.Int64("max", s.max), zap.Float64("buffer", s.buffer), zap.Int64("target", target))
 	delta := target - pm.request
 	if delta == 0 {
+		pm.z.Info("NNC already at target IPs, no scaling required")
 		return nil
 	}
 	pm.z.Info("scaling pool", zap.Int64("delta", delta))

diff --git a/cns/kubecontroller/pod/reconciler.go b/cns/kubecontroller/pod/reconciler.go
@@ -61,11 +61,11 @@ type limiter interface {
 // any events.
 // listeners are called with the new Pod list.
 func (p *watcher) NewNotifierFunc(listOpts *client.ListOptions, limiter limiter, listeners ...func([]v1.Pod)) reconcile.Func {
-	p.z.Debug("adding notified for listeners", zap.Int("listeners", len(listeners)))
+	p.z.Info("adding notifier for listeners", zap.Int("listeners", len(listeners)))
 	return func(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
 		if !limiter.Allow() {
 			// rate limit exceeded, requeue
-			p.z.Debug("rate limit exceeded")
+			p.z.Info("rate limit exceeded")
 			return ctrl.Result{Requeue: true}, nil
 		}
 		podList := &v1.PodList{}

diff --git a/cns/restserver/internalapi.go b/cns/restserver/internalapi.go
@@ -563,7 +563,6 @@ func (service *HTTPRestService) CreateOrUpdateNetworkContainerInternal(req *cns.
 	// If the NC was created successfully, log NC snapshot.
 	if returnCode == 0 {
 		logNCSnapshot(*req)
-
 		publishIPStateMetrics(service.buildIPState())
 	} else {
 		logger.Errorf(returnMessage)

diff --git a/cns/restserver/ipam.go b/cns/restserver/ipam.go
@@ -196,10 +196,10 @@ func (service *HTTPRestService) updatePodInfoWithInterfaces(ctx context.Context,
 
 // RequestIPConfigHandler requests an IPConfig from the CNS state
 func (service *HTTPRestService) RequestIPConfigHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "requestIPConfigHandler"
 	var ipconfigRequest cns.IPConfigRequest
 	err := common.Decode(w, r, &ipconfigRequest)
-	operationName := "requestIPConfigHandler"
-	logger.Request(service.Name+operationName, ipconfigRequest, err)
+	logger.Request(opName, ipconfigRequest, err)
 	if err != nil {
 		return
 	}
@@ -215,7 +215,7 @@ func (service *HTTPRestService) RequestIPConfigHandler(w http.ResponseWriter, r
 		}
 		w.Header().Set(cnsReturnCode, reserveResp.Response.ReturnCode.String())
 		err = common.Encode(w, &reserveResp)
-		logger.ResponseEx(service.Name+operationName, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
 		return
 	}
 
@@ -240,7 +240,7 @@ func (service *HTTPRestService) RequestIPConfigHandler(w http.ResponseWriter, r
 		}
 		w.Header().Set(cnsReturnCode, reserveResp.Response.ReturnCode.String())
 		err = common.Encode(w, &reserveResp)
-		logger.ResponseEx(service.Name+operationName, ipconfigsRequest, reserveResp, reserveResp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigsRequest, reserveResp, reserveResp.Response.ReturnCode, err)
 		return
 	}
 
@@ -256,7 +256,7 @@ func (service *HTTPRestService) RequestIPConfigHandler(w http.ResponseWriter, r
 		}
 		w.Header().Set(cnsReturnCode, reserveResp.Response.ReturnCode.String())
 		err = common.Encode(w, &reserveResp)
-		logger.ResponseEx(service.Name+operationName, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
 		return
 	}
 	// As this API is expected to return IPConfigResponse, generate it from the IPConfigsResponse returned above.
@@ -266,15 +266,15 @@ func (service *HTTPRestService) RequestIPConfigHandler(w http.ResponseWriter, r
 	}
 	w.Header().Set(cnsReturnCode, reserveResp.Response.ReturnCode.String())
 	err = common.Encode(w, &reserveResp)
-	logger.ResponseEx(service.Name+operationName, ipconfigsRequest, reserveResp, reserveResp.Response.ReturnCode, err)
+	logger.ResponseEx(opName, ipconfigsRequest, reserveResp, reserveResp.Response.ReturnCode, err)
 }
 
 // RequestIPConfigsHandler requests multiple IPConfigs from the CNS state
 func (service *HTTPRestService) RequestIPConfigsHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "requestIPConfigsHandler"
 	var ipconfigsRequest cns.IPConfigsRequest
 	err := common.Decode(w, r, &ipconfigsRequest)
-	operationName := "requestIPConfigsHandler"
-	logger.Request(service.Name+operationName, ipconfigsRequest, err)
+	logger.Request(opName, ipconfigsRequest, err)
 	if err != nil {
 		return
 	}
@@ -300,13 +300,13 @@ func (service *HTTPRestService) RequestIPConfigsHandler(w http.ResponseWriter, r
 	if err != nil {
 		w.Header().Set(cnsReturnCode, ipConfigsResp.Response.ReturnCode.String())
 		err = common.Encode(w, &ipConfigsResp)
-		logger.ResponseEx(service.Name+operationName, ipconfigsRequest, ipConfigsResp, ipConfigsResp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigsRequest, ipConfigsResp, ipConfigsResp.Response.ReturnCode, err)
 		return
 	}
 
 	w.Header().Set(cnsReturnCode, ipConfigsResp.Response.ReturnCode.String())
 	err = common.Encode(w, &ipConfigsResp)
-	logger.ResponseEx(service.Name+operationName, ipconfigsRequest, ipConfigsResp, ipConfigsResp.Response.ReturnCode, err)
+	logger.ResponseEx(opName, ipconfigsRequest, ipConfigsResp, ipConfigsResp.Response.ReturnCode, err)
 }
 
 func (service *HTTPRestService) updateEndpointState(ipconfigsRequest cns.IPConfigsRequest, podInfo cns.PodInfo, podIPInfo []cns.PodIpInfo) error {
@@ -414,9 +414,10 @@ func (service *HTTPRestService) ReleaseIPConfigHandlerHelper(ctx context.Context
 
 // ReleaseIPConfigHandler frees the IP assigned to a pod from CNS
 func (service *HTTPRestService) ReleaseIPConfigHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "releaseIPConfigHandler"
 	var ipconfigRequest cns.IPConfigRequest
 	err := common.Decode(w, r, &ipconfigRequest)
-	logger.Request(service.Name+"releaseIPConfigHandler", ipconfigRequest, err)
+	logger.Request(opName, ipconfigRequest, err)
 	if err != nil {
 		resp := cns.Response{
 			ReturnCode: types.UnexpectedError,
@@ -425,7 +426,7 @@ func (service *HTTPRestService) ReleaseIPConfigHandler(w http.ResponseWriter, r
 		logger.Errorf("releaseIPConfigHandler decode failed becase %v, release IP config info %s", resp.Message, ipconfigRequest)
 		w.Header().Set(cnsReturnCode, resp.ReturnCode.String())
 		err = common.Encode(w, &resp)
-		logger.ResponseEx(service.Name, ipconfigRequest, resp, resp.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigRequest, resp, resp.ReturnCode, err)
 		return
 	}
 
@@ -439,7 +440,7 @@ func (service *HTTPRestService) ReleaseIPConfigHandler(w http.ResponseWriter, r
 		}
 		w.Header().Set(cnsReturnCode, reserveResp.Response.ReturnCode.String())
 		err = common.Encode(w, &reserveResp)
-		logger.ResponseEx(service.Name, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigRequest, reserveResp, reserveResp.Response.ReturnCode, err)
 		return
 	}
 
@@ -457,19 +458,20 @@ func (service *HTTPRestService) ReleaseIPConfigHandler(w http.ResponseWriter, r
 	if err != nil {
 		w.Header().Set(cnsReturnCode, resp.Response.ReturnCode.String())
 		err = common.Encode(w, &resp)
-		logger.ResponseEx(service.Name, ipconfigRequest, resp, resp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigRequest, resp, resp.Response.ReturnCode, err)
 	}
 
 	w.Header().Set(cnsReturnCode, resp.Response.ReturnCode.String())
 	err = common.Encode(w, &resp)
-	logger.ResponseEx(service.Name, ipconfigRequest, resp, resp.Response.ReturnCode, err)
+	logger.ResponseEx(opName, ipconfigRequest, resp, resp.Response.ReturnCode, err)
 }
 
 // ReleaseIPConfigsHandler frees multiple IPConfigs from the CNS state
 func (service *HTTPRestService) ReleaseIPConfigsHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "releaseIPConfigsHandler"
 	var ipconfigsRequest cns.IPConfigsRequest
 	err := common.Decode(w, r, &ipconfigsRequest)
-	logger.Request(service.Name+"releaseIPConfigsHandler", ipconfigsRequest, err)
+	logger.Request("releaseIPConfigsHandler", ipconfigsRequest, err)
 	if err != nil {
 		resp := cns.Response{
 			ReturnCode: types.UnexpectedError,
@@ -478,20 +480,20 @@ func (service *HTTPRestService) ReleaseIPConfigsHandler(w http.ResponseWriter, r
 		logger.Errorf("releaseIPConfigsHandler decode failed because %v, release IP config info %+v", resp.Message, ipconfigsRequest)
 		w.Header().Set(cnsReturnCode, resp.ReturnCode.String())
 		err = common.Encode(w, &resp)
-		logger.ResponseEx(service.Name, ipconfigsRequest, resp, resp.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigsRequest, resp, resp.ReturnCode, err)
 		return
 	}
 
 	resp, err := service.ReleaseIPConfigHandlerHelper(r.Context(), ipconfigsRequest)
 	if err != nil {
 		w.Header().Set(cnsReturnCode, resp.Response.ReturnCode.String())
 		err = common.Encode(w, &resp)
-		logger.ResponseEx(service.Name, ipconfigsRequest, resp, resp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, ipconfigsRequest, resp, resp.Response.ReturnCode, err)
 	}
 
 	w.Header().Set(cnsReturnCode, resp.Response.ReturnCode.String())
 	err = common.Encode(w, &resp)
-	logger.ResponseEx(service.Name, ipconfigsRequest, resp, resp.Response.ReturnCode, err)
+	logger.ResponseEx(opName, ipconfigsRequest, resp, resp.Response.ReturnCode, err)
 }
 
 func (service *HTTPRestService) removeEndpointState(podInfo cns.PodInfo) error {
@@ -672,16 +674,18 @@ func (service *HTTPRestService) GetPodIPConfigState() map[string]cns.IPConfigura
 }
 
 func (service *HTTPRestService) HandleDebugPodContext(w http.ResponseWriter, r *http.Request) { //nolint
+	opName := "handleDebugPodContext"
 	service.RLock()
 	defer service.RUnlock()
 	resp := cns.GetPodContextResponse{
 		PodContext: service.PodIPIDByPodInterfaceKey,
 	}
 	err := common.Encode(w, &resp)
-	logger.Response(service.Name, resp, resp.Response.ReturnCode, err)
+	logger.Response(opName, resp, resp.Response.ReturnCode, err)
 }
 
 func (service *HTTPRestService) HandleDebugRestData(w http.ResponseWriter, r *http.Request) { //nolint
+	opName := "handleDebugRestData"
 	service.RLock()
 	defer service.RUnlock()
 	resp := GetHTTPServiceDataResponse{
@@ -691,10 +695,11 @@ func (service *HTTPRestService) HandleDebugRestData(w http.ResponseWriter, r *ht
 		},
 	}
 	err := common.Encode(w, &resp)
-	logger.Response(service.Name, resp, resp.Response.ReturnCode, err)
+	logger.Response(opName, resp, resp.Response.ReturnCode, err)
 }
 
 func (service *HTTPRestService) HandleDebugIPAddresses(w http.ResponseWriter, r *http.Request) {
+	opName := "handleDebugIPAddresses"
 	var req cns.GetIPAddressesRequest
 	if err := common.Decode(w, r, &req); err != nil {
 		resp := cns.GetIPAddressStatusResponse{
@@ -704,15 +709,15 @@ func (service *HTTPRestService) HandleDebugIPAddresses(w http.ResponseWriter, r
 			},
 		}
 		err = common.Encode(w, &resp)
-		logger.ResponseEx(service.Name, req, resp, resp.Response.ReturnCode, err)
+		logger.ResponseEx(opName, req, resp, resp.Response.ReturnCode, err)
 		return
 	}
 	// Get all IPConfigs matching a state and return in the response
 	resp := cns.GetIPAddressStatusResponse{
 		IPConfigurationStatus: filter.MatchAnyIPConfigState(service.PodIPConfigState, filter.PredicatesForStates(req.IPConfigStateFilter...)...),
 	}
 	err := common.Encode(w, &resp)
-	logger.ResponseEx(service.Name, req, resp, resp.Response.ReturnCode, err)
+	logger.ResponseEx(opName, req, resp, resp.Response.ReturnCode, err)
 }
 
 // GetAssignedIPConfigs returns a filtered list of IPs which are in
@@ -1093,6 +1098,7 @@ func validateDesiredIPAddresses(desiredIPs []string) error {
 
 // EndpointHandlerAPI forwards the endpoint related APIs to GetEndpointHandler or UpdateEndpointHandler based on the http method
 func (service *HTTPRestService) EndpointHandlerAPI(w http.ResponseWriter, r *http.Request) {
+	opName := "endpointHandler"
 	logger.Printf("[EndpointHandlerAPI] EndpointHandlerAPI received request with http Method %s", r.Method)
 	service.Lock()
 	defer service.Unlock()
@@ -1103,7 +1109,7 @@ func (service *HTTPRestService) EndpointHandlerAPI(w http.ResponseWriter, r *htt
 			Message:    fmt.Sprintf("[EndpointHandlerAPI] EndpointHandlerAPI failed with error: %s", ErrOptManageEndpointState),
 		}
 		err := common.Encode(w, &response)
-		logger.Response(service.Name, response, response.ReturnCode, err)
+		logger.Response(opName, response, response.ReturnCode, err)
 		return
 	}
 	switch r.Method {
@@ -1118,6 +1124,7 @@ func (service *HTTPRestService) EndpointHandlerAPI(w http.ResponseWriter, r *htt
 
 // GetEndpointHandler handles the incoming GetEndpoint requests with http Get method
 func (service *HTTPRestService) GetEndpointHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "getEndpointState"
 	logger.Printf("[GetEndpointState] GetEndpoint for %s", r.URL.Path)
 	endpointID := strings.TrimPrefix(r.URL.Path, cns.EndpointPath)
 	endpointInfo, err := service.GetEndpointHelper(endpointID)
@@ -1139,7 +1146,7 @@ func (service *HTTPRestService) GetEndpointHandler(w http.ResponseWriter, r *htt
 		}
 		w.Header().Set(cnsReturnCode, response.Response.ReturnCode.String())
 		err = common.Encode(w, &response)
-		logger.Response(service.Name, response, response.Response.ReturnCode, err)
+		logger.Response(opName, response, response.Response.ReturnCode, err)
 		return
 	}
 	response := GetEndpointResponse{
@@ -1151,7 +1158,7 @@ func (service *HTTPRestService) GetEndpointHandler(w http.ResponseWriter, r *htt
 	}
 	w.Header().Set(cnsReturnCode, response.Response.ReturnCode.String())
 	err = common.Encode(w, &response)
-	logger.Response(service.Name, response, response.Response.ReturnCode, err)
+	logger.Response(opName, response, response.Response.ReturnCode, err)
 }
 
 // GetEndpointHelper returns the state of the given endpointId
@@ -1192,12 +1199,13 @@ func (service *HTTPRestService) GetEndpointHelper(endpointID string) (*EndpointI
 
 // UpdateEndpointHandler handles the incoming UpdateEndpoint requests with http Patch method
 func (service *HTTPRestService) UpdateEndpointHandler(w http.ResponseWriter, r *http.Request) {
+	opName := "UpdateEndpointHandler"
 	logger.Printf("[updateEndpoint] updateEndpoint for %s", r.URL.Path)
 
 	var req map[string]*IPInfo
 	err := common.Decode(w, r, &req)
 	endpointID := strings.TrimPrefix(r.URL.Path, cns.EndpointPath)
-	logger.Request(service.Name, &req, err)
+	logger.Request(opName, &req, err)
 	// Check if the request is valid
 	if err != nil {
 		response := cns.Response{
@@ -1206,7 +1214,7 @@ func (service *HTTPRestService) UpdateEndpointHandler(w http.ResponseWriter, r *
 		}
 		w.Header().Set(cnsReturnCode, response.ReturnCode.String())
 		err = common.Encode(w, &response)
-		logger.Response(service.Name, response, response.ReturnCode, err)
+		logger.Response(opName, response, response.ReturnCode, err)
 		return
 	}
 	if err = verifyUpdateEndpointStateRequest(req); err != nil {
@@ -1216,7 +1224,7 @@ func (service *HTTPRestService) UpdateEndpointHandler(w http.ResponseWriter, r *
 		}
 		w.Header().Set(cnsReturnCode, response.ReturnCode.String())
 		err = common.Encode(w, &response)
-		logger.Response(service.Name, response, response.ReturnCode, err)
+		logger.Response(opName, response, response.ReturnCode, err)
 		return
 	}
 	// Update the endpoint state
@@ -1228,7 +1236,7 @@ func (service *HTTPRestService) UpdateEndpointHandler(w http.ResponseWriter, r *
 		}
 		w.Header().Set(cnsReturnCode, response.ReturnCode.String())
 		err = common.Encode(w, &response)
-		logger.Response(service.Name, response, response.ReturnCode, err)
+		logger.Response(opName, response, response.ReturnCode, err)
 		return
 	}
 	response := cns.Response{
@@ -1237,7 +1245,7 @@ func (service *HTTPRestService) UpdateEndpointHandler(w http.ResponseWriter, r *
 	}
 	w.Header().Set(cnsReturnCode, response.ReturnCode.String())
 	err = common.Encode(w, &response)
-	logger.Response(service.Name, response, response.ReturnCode, err)
+	logger.Response(opName, response, response.ReturnCode, err)
 }
 
 // UpdateEndpointHelper updates the state of the given endpointId with HNSId, VethName or other InterfaceInfo fields

diff --git a/cns/restserver/metrics.go b/cns/restserver/metrics.go
@@ -143,7 +143,7 @@ func stateTransitionMiddleware(i *cns.IPConfigurationStatus, s types.IPState) {
 }
 
 func publishIPStateMetrics(state *ipState) {
-	labels := []string{} // TODO. ragasthya Add dimensions to the IP Usage metrics.
+	labels := []string{}
 	allocatedIPCount.WithLabelValues(labels...).Set(float64(state.allocatedIPs))
 	assignedIPCount.WithLabelValues(labels...).Set(float64(state.assignedIPs))
 	availableIPCount.WithLabelValues(labels...).Set(float64(state.availableIPs))