diff --git a/cns/logger/log.go b/cns/logger/log.go index bfccd9b3d5..306403b5a6 100644 --- a/cns/logger/log.go +++ b/cns/logger/log.go @@ -164,6 +164,26 @@ func Response(tag string, response interface{}, returnCode int, returnStr string sendTraceInternal(msg) } +// ResponseEx put request and response info together to help easier debug. +func ResponseEx(tag string, request interface{}, response interface{}, returnCode int, returnStr string, err error) { + Log.logger.ResponseEx(tag, request, response, returnCode, returnStr, err) + + if Log.th == nil || Log.DisableTraceLogging { + return + } + + var msg string + if err == nil && returnCode == 0 { + msg = fmt.Sprintf("[%s] Sent %T %+v %T %+v.", tag, request, request, response, response) + } else if err != nil { + msg = fmt.Sprintf("[%s] Code:%s, %+v, %+v, %s.", tag, returnStr, request, response, err.Error()) + } else { + msg = fmt.Sprintf("[%s] Code:%s, %+v, %+v.", tag, returnStr, request, response) + } + + sendTraceInternal(msg) +} + // Send AI telemetry metric func SendMetric(metric aitelemetry.Metric) { if Log.th == nil || Log.DisableMetricLogging { diff --git a/cns/nmagentclient/nmagentclient.go b/cns/nmagentclient/nmagentclient.go index 26135a3650..9b2b8f4237 100644 --- a/cns/nmagentclient/nmagentclient.go +++ b/cns/nmagentclient/nmagentclient.go @@ -200,12 +200,11 @@ func (nmagentclient *NMAgentClient) GetNcVersionListWithOutToken(ncNeedUpdateLis var nmaNcListResponse NMANetworkContainerListResponse rBytes, _ := ioutil.ReadAll(response.Body) - logger.Printf("Response body is %v", rBytes) - json.Unmarshal(rBytes, &nmaNcListResponse) - if nmaNcListResponse.ResponseCode != strconv.Itoa(http.StatusOK) { - logger.Printf("[NMAgentClient][Response] GetNcVersionListWithOutToken unmarshal failed with %s", rBytes) + if err := json.Unmarshal(rBytes, &nmaNcListResponse); err != nil { + logger.Printf("[NMAgentClient][Response] GetNcVersionListWithOutToken unmarshal failed with %s", err) return nil } + logger.Printf("NMAgent NC List Response is %s", nmaNcListResponse) var receivedNcVersionListInMap = make(map[string]string) for _, containers := range nmaNcListResponse.Containers { diff --git a/cns/restserver/ipam.go b/cns/restserver/ipam.go index 506c1c16ca..5a55c4a1e1 100644 --- a/cns/restserver/ipam.go +++ b/cns/restserver/ipam.go @@ -25,7 +25,8 @@ func (service *HTTPRestService) requestIPConfigHandler(w http.ResponseWriter, r ) err = service.Listener.Decode(w, r, &ipconfigRequest) - logger.Request(service.Name, &ipconfigRequest, err) + operationName := "requestIPConfigHandler" + logger.Request(service.Name+operationName, ipconfigRequest, err) if err != nil { return } @@ -35,7 +36,7 @@ func (service *HTTPRestService) requestIPConfigHandler(w http.ResponseWriter, r if returnCode == Success { if podIpInfo, err = requestIPConfigHelper(service, ipconfigRequest); err != nil { returnCode = FailedToAllocateIpConfig - returnMessage = fmt.Sprintf("AllocateIPConfig failed: %v", err) + returnMessage = fmt.Sprintf("AllocateIPConfig failed: %v, IP config request is %s", err, ipconfigRequest) } } @@ -50,7 +51,7 @@ func (service *HTTPRestService) requestIPConfigHandler(w http.ResponseWriter, r reserveResp.PodIpInfo = podIpInfo err = service.Listener.Encode(w, &reserveResp) - logger.Response(service.Name, reserveResp, resp.ReturnCode, ReturnCodeToString(resp.ReturnCode), err) + logger.ResponseEx(service.Name+operationName, ipconfigRequest, reserveResp, resp.ReturnCode, ReturnCodeToString(resp.ReturnCode), err) } func (service *HTTPRestService) releaseIPConfigHandler(w http.ResponseWriter, r *http.Request) { @@ -62,6 +63,7 @@ func (service *HTTPRestService) releaseIPConfigHandler(w http.ResponseWriter, r ) statusCode = UnexpectedError + operationName := "releaseIPConfigHandler" defer func() { resp := cns.Response{} @@ -72,13 +74,15 @@ func (service *HTTPRestService) releaseIPConfigHandler(w http.ResponseWriter, r } err = service.Listener.Encode(w, &resp) - logger.Response(service.Name, resp, resp.ReturnCode, ReturnCodeToString(resp.ReturnCode), err) + logger.ResponseEx(service.Name, req, resp, resp.ReturnCode, ReturnCodeToString(resp.ReturnCode), err) }() err = service.Listener.Decode(w, r, &req) - logger.Request(service.Name, &req, err) + logger.Request(service.Name+operationName, req, err) if err != nil { returnMessage = err.Error() + logger.Errorf("releaseIPConfigHandler decode failed becase %v, release IP config info %s", + returnMessage, req) return } @@ -87,6 +91,7 @@ func (service *HTTPRestService) releaseIPConfigHandler(w http.ResponseWriter, r if err = service.releaseIPConfig(podInfo); err != nil { statusCode = NotFound returnMessage = err.Error() + logger.Errorf("releaseIPConfigHandler releaseIPConfig failed because %v, release IP config info %s", returnMessage, req) return } return @@ -100,33 +105,33 @@ func (service *HTTPRestService) MarkIPAsPendingRelease(totalIpsToRelease int) (m defer service.Unlock() for uuid, existingIpConfig := range service.PodIPConfigState { - if existingIpConfig.State == cns.PendingProgramming { - updatedIpConfig, err := service.updateIPConfigState(uuid, cns.PendingRelease, existingIpConfig.OrchestratorContext) - if err != nil { - return nil, err - } + if existingIpConfig.State == cns.PendingProgramming { + updatedIpConfig, err := service.updateIPConfigState(uuid, cns.PendingRelease, existingIpConfig.OrchestratorContext) + if err != nil { + return nil, err + } - pendingReleasedIps[uuid] = updatedIpConfig + pendingReleasedIps[uuid] = updatedIpConfig if len(pendingReleasedIps) == totalIpsToRelease { return pendingReleasedIps, nil } - } + } } - - // if not all expected IPs are set to PendingRelease, then check the Available IPs + + // if not all expected IPs are set to PendingRelease, then check the Available IPs for uuid, existingIpConfig := range service.PodIPConfigState { - if existingIpConfig.State == cns.Available { - updatedIpConfig, err := service.updateIPConfigState(uuid, cns.PendingRelease, existingIpConfig.OrchestratorContext) - if err != nil { - return nil, err - } - - pendingReleasedIps[uuid] = updatedIpConfig - + if existingIpConfig.State == cns.Available { + updatedIpConfig, err := service.updateIPConfigState(uuid, cns.PendingRelease, existingIpConfig.OrchestratorContext) + if err != nil { + return nil, err + } + + pendingReleasedIps[uuid] = updatedIpConfig + if len(pendingReleasedIps) == totalIpsToRelease { return pendingReleasedIps, nil - } - } + } + } } logger.Printf("[MarkIPAsPendingRelease] Set total ips to PendingRelease %d, expected %d", len(pendingReleasedIps), totalIpsToRelease) @@ -140,9 +145,9 @@ func (service *HTTPRestService) updateIPConfigState(ipId string, updatedState st ipConfig.OrchestratorContext = orchestratorContext service.PodIPConfigState[ipId] = ipConfig return ipConfig, nil - } - - return cns.IPConfigurationStatus{}, fmt.Errorf("[updateIPConfigState] Failed to update state %s for the IPConfig. ID %s not found PodIPConfigState", updatedState, ipId) + } + + return cns.IPConfigurationStatus{}, fmt.Errorf("[updateIPConfigState] Failed to update state %s for the IPConfig. ID %s not found PodIPConfigState", updatedState, ipId) } // MarkIpsAsAvailableUntransacted will update pending programming IPs to available if NMAgent side's programmed nc version keep up with nc version. @@ -208,12 +213,14 @@ func (service *HTTPRestService) getIPAddressesHandler(w http.ResponseWriter, r * } err = service.Listener.Encode(w, &resp) - logger.Response(service.Name, resp, resp.Response.ReturnCode, ReturnCodeToString(resp.Response.ReturnCode), err) + logger.ResponseEx(service.Name, req, resp, resp.Response.ReturnCode, ReturnCodeToString(resp.Response.ReturnCode), err) }() err = service.Listener.Decode(w, r, &req) if err != nil { returnMessage = err.Error() + logger.Errorf("getIPAddressesHandler decode failed because %v, GetIPAddressesRequest is %v", + returnMessage, req) return } @@ -311,6 +318,8 @@ func (service *HTTPRestService) setIPConfigAsAvailable(ipconfig cns.IPConfigurat } delete(service.PodIPIDByOrchestratorContext, podInfo.GetOrchestratorContextKey()) + logger.Printf("[setIPConfigAsAvailable] Deleted outdated pod info %s from PodIPIDByOrchestratorContext since IP %s with ID %s will be released and set as Available", + podInfo.GetOrchestratorContextKey(), ipconfig.IPAddress, ipconfig.ID) return ipconfig, nil } @@ -324,15 +333,17 @@ func (service *HTTPRestService) releaseIPConfig(podInfo cns.KubernetesPodInfo) e ipID := service.PodIPIDByOrchestratorContext[podInfo.GetOrchestratorContextKey()] if ipID != "" { if ipconfig, isExist := service.PodIPConfigState[ipID]; isExist { + logger.Printf("[releaseIPConfig] Releasing IP %+v for pod %+v", ipconfig.IPAddress, podInfo) _, err := service.setIPConfigAsAvailable(ipconfig, podInfo) if err != nil { return fmt.Errorf("[releaseIPConfig] failed to mark IPConfig [%+v] as Available. err: %v", ipconfig, err) } logger.Printf("[releaseIPConfig] Released IP %+v for pod %+v", ipconfig.IPAddress, podInfo) - } else { - logger.Errorf("[releaseIPConfig] Failed to get release ipconfig. Pod to IPID exists, but IPID to IPConfig doesn't exist, CNS State potentially corrupt") - return fmt.Errorf("[releaseIPConfig] releaseIPConfig failed. Pod to IPID exists, but IPID to IPConfig doesn't exist, CNS State potentially corrupt") + logger.Errorf("[releaseIPConfig] Failed to get release ipconfig %+v and pod info is %+v. Pod to IPID exists, but IPID to IPConfig doesn't exist, CNS State potentially corrupt", + ipconfig.IPAddress, podInfo) + return fmt.Errorf("[releaseIPConfig] releaseIPConfig failed. IPconfig %+v and pod info is %+v. Pod to IPID exists, but IPID to IPConfig doesn't exist, CNS State potentially corrupt", + ipconfig.IPAddress, podInfo) } } else { logger.Errorf("[releaseIPConfig] SetIPConfigAsAvailable failed to release, no allocation found for pod [%+v]", podInfo) @@ -352,7 +363,7 @@ func (service *HTTPRestService) MarkExistingIPsAsPending(pendingIPIDs []string) return fmt.Errorf("Failed to mark IP [%v] as pending, currently allocated", id) } - logger.Printf("[MarkExistingIPsAsPending]: Marking IP [%+v] to PendingRelease", ipconfig) + logger.Printf("[MarkExistingIPsAsPending]: Marking IP [%+v] to PendingRelease", ipconfig) ipconfig.State = cns.PendingRelease service.PodIPConfigState[id] = ipconfig } else { diff --git a/log/logger.go b/log/logger.go index 81c29e63ca..fa73043cc1 100644 --- a/log/logger.go +++ b/log/logger.go @@ -189,6 +189,17 @@ func (logger *Logger) Response(tag string, response interface{}, returnCode int, } } +// ResponseEx logs a structured response and the request associate with it. +func (logger *Logger) ResponseEx(tag string, request interface{}, response interface{}, returnCode int, returnStr string, err error) { + if err == nil && returnCode == 0 { + logger.Printf("[%s] Sent %T %+v %T %+v.", tag, request, request, response, response) + } else if err != nil { + logger.Errorf("[%s] Code:%s, %+v, %+v %s.", tag, returnStr, request, response, err.Error()) + } else { + logger.Errorf("[%s] Code:%s, %+v, %+v.", tag, returnStr, request, response) + } +} + // logf logs a formatted string. func (logger *Logger) logf(format string, args ...interface{}) { if logger.callCount%rotationCheckFrq == 0 {