Skip to content

Fix log which let log to show more readable info. #803

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Mar 18, 2021
Merged

Fix log which let log to show more readable info. #803

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 20 additions & 0 deletions cns/logger/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Copy link
Member

@neaggarwMS neaggarwMS Mar 16, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need this? Log.logger.ResponseEx will print to AI too, right?

Copy link
Contributor Author

@csfmomo csfmomo Mar 16, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't see either Log.logger.ResponseEx or Log.logger.Response prints to AI.
image

Copy link
Contributor Author

@csfmomo csfmomo Mar 17, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After offline sync up, we'll keep it as it is for now. I'll make a separate PR to remove duplicate AI telemetry log populating issue.

}

// Send AI telemetry metric
func SendMetric(metric aitelemetry.Metric) {
if Log.th == nil || Log.DisableMetricLogging {
Expand Down
7 changes: 3 additions & 4 deletions cns/nmagentclient/nmagentclient.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
75 changes: 43 additions & 32 deletions cns/restserver/ipam.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand All @@ -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)
}
}

Expand All @@ -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) {
Expand All @@ -62,6 +63,7 @@ func (service *HTTPRestService) releaseIPConfigHandler(w http.ResponseWriter, r
)

statusCode = UnexpectedError
operationName := "releaseIPConfigHandler"

defer func() {
resp := cns.Response{}
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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.
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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
}

Expand All @@ -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)
Expand All @@ -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 {
Expand Down
11 changes: 11 additions & 0 deletions log/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down