diff --git a/Nudr_DataRepository/api_default.go b/Nudr_DataRepository/api_default.go index 97c15557..06a07abd 100644 --- a/Nudr_DataRepository/api_default.go +++ b/Nudr_DataRepository/api_default.go @@ -24,6 +24,7 @@ import ( "github.com/antihax/optional" "github.com/5GC-DEV/openapi-cdac" + "github.com/5GC-DEV/openapi-cdac/logger" "github.com/5GC-DEV/openapi-cdac/models" ) @@ -4521,19 +4522,48 @@ func (a *DefaultApiService) PolicyDataUesUeIdSmDataGet(ctx context.Context, ueId localVarHeaderParams["Accept"] = localVarHTTPHeaderAccept } + logger.OpenapiLog.Debugf( + "PolicyDataUesUeIdSmDataGet Request: ueId=%s path=%s query=%v", + ueId, + localVarPath, + localVarQueryParams.Encode(), + ) + r, err := openapi.PrepareRequest(ctx, a.client.cfg, localVarPath, localVarHTTPMethod, localVarPostBody, localVarHeaderParams, localVarQueryParams, localVarFormParams, localVarFormFileName, localVarFileName, localVarFileBytes) if err != nil { + logger.OpenapiLog.Errorf( + "PrepareRequest failed ueId=%s err=%v", + ueId, + err, + ) return localVarReturnValue, nil, err } localVarHTTPResponse, err := openapi.CallAPI(a.client.cfg, r) if err != nil || localVarHTTPResponse == nil { + logger.OpenapiLog.Errorf( + "CallAPI failed ueId=%s err=%v rsp=%v", + ueId, + err, + localVarHTTPResponse, + ) return localVarReturnValue, localVarHTTPResponse, err } + logger.OpenapiLog.Errorf( + "UDR Response: status=%d %s", + localVarHTTPResponse.StatusCode, + localVarHTTPResponse.Status, + ) + localVarBody, err := ioutil.ReadAll(localVarHTTPResponse.Body) localVarHTTPResponse.Body.Close() if err != nil { + logger.OpenapiLog.Errorf( + "Read body failed ueId=%s err=%v", + ueId, + err, + ) return localVarReturnValue, localVarHTTPResponse, err } @@ -4542,20 +4572,49 @@ func (a *DefaultApiService) PolicyDataUesUeIdSmDataGet(ctx context.Context, ueId ErrorStatus: localVarHTTPResponse.Status, } + logger.OpenapiLog.Infof( + "UDR Raw Body UE=%s body=%s", + ueId, + string(localVarBody), + ) + switch localVarHTTPResponse.StatusCode { case 200: err = openapi.Deserialize(&localVarReturnValue, localVarBody, localVarHTTPResponse.Header.Get("Content-Type")) if err != nil { + logger.OpenapiLog.Errorf( + "Deserialize failed ueId=%s err=%v", + ueId, + err, + ) apiError.ErrorStatus = err.Error() } + logger.OpenapiLog.Errorf( + "Decoded SmPolicyData UE=%s data=%+v", + ueId, + localVarReturnValue, + ) return localVarReturnValue, localVarHTTPResponse, nil case 400: var v models.ProblemDetails + logger.OpenapiLog.Errorf( + "UDR returned 400 Bad Request, body=%s", + string(localVarBody), + ) err = openapi.Deserialize(&v, localVarBody, localVarHTTPResponse.Header.Get("Content-Type")) if err != nil { + logger.OpenapiLog.Errorf( + "Failed to deserialize 400 response: err=%v body=%s", + err, + string(localVarBody), + ) apiError.ErrorStatus = err.Error() return localVarReturnValue, localVarHTTPResponse, apiError } + logger.OpenapiLog.Errorf( + "UDR 400 ProblemDetails: %+v", + v, + ) apiError.ErrorModel = v return localVarReturnValue, localVarHTTPResponse, apiError case 401: diff --git a/client.go b/client.go index b8ba755a..6fce6d77 100644 --- a/client.go +++ b/client.go @@ -35,6 +35,7 @@ import ( "time" "github.com/5GC-DEV/openapi-cdac/logger" + "github.com/google/uuid" "golang.org/x/net/http2" "golang.org/x/oauth2" "gopkg.in/h2non/gock.v1" @@ -53,7 +54,23 @@ var ( Transport: &http2.Transport{ AllowHTTP: true, DialTLS: func(network, addr string, cfg *tls.Config) (net.Conn, error) { - return net.Dial(network, addr) + logger.OpenapiLog.Infof( + "[HTTP2] Dial network=%s addr=%s", + network, + addr, + ) + + conn, err := net.Dial(network, addr) + + if err != nil { + logger.OpenapiLog.Errorf( + "[HTTP2] Dial failed addr=%s err=%v", + addr, + err, + ) + } + + return conn, err }, }, } @@ -128,7 +145,6 @@ func ParameterToString(obj interface{}, collectionFormat string) string { return fmt.Sprintf("%v", obj) } -// callAPI do the request. func CallAPI(cfg Configuration, request *http.Request) (*http.Response, error) { logger.OpenapiLog.Debugln("[CallAPI] Enter") @@ -148,43 +164,227 @@ func CallAPI(cfg Configuration, request *http.Request) (*http.Response, error) { } var ( - resp *http.Response - err error + resp *http.Response + err error + httpClient *http.Client ) - if request.URL.Scheme == "https" { - logger.OpenapiLog.Debugln("[CallAPI] Using HTTPS client") + const maxRetries = 3 - resp, err = innerHTTP2Client.Do(request) + switch request.URL.Scheme { + + case "https": + logger.OpenapiLog.Debugln("[CallAPI] Using HTTPS client") + httpClient = innerHTTP2Client - } else if request.URL.Scheme == "http" { + case "http": logger.OpenapiLog.Debugln("[CallAPI] Using HTTP cleartext client") + httpClient = innerHTTP2CleartextClient - resp, err = innerHTTP2CleartextClient.Do(request) + default: + logger.OpenapiLog.Errorf( + "[CallAPI] Unsupported scheme: %s", + request.URL.Scheme, + ) + + return nil, fmt.Errorf( + "unsupported scheme[%s]", + request.URL.Scheme, + ) + } + if deadline, ok := request.Context().Deadline(); ok { + logger.OpenapiLog.Infof( + "[CallAPI] Initial Context Deadline=%v Remaining=%v", + deadline, + time.Until(deadline), + ) } else { - logger.OpenapiLog.Errorf("[CallAPI] Unsupported scheme: %s", - request.URL.Scheme) + logger.OpenapiLog.Infof( + "[CallAPI] Request has no context deadline", + ) + } + + var idempotencyKey string + + if isNonIdempotent(request.Method) { - return nil, fmt.Errorf("unsupported scheme[%s]", - request.URL.Scheme) + requestInfo := request.Header.Get("3gpp-Sbi-Request-Info") + + if requestInfo == "" { + + idempotencyKey = uuid.NewString() + + request.Header.Set( + "3gpp-Sbi-Request-Info", + fmt.Sprintf("idempotency-key=%s", idempotencyKey), + ) + + logger.OpenapiLog.Infof( + "[CallAPI] Generated IdempotencyKey=%s", + idempotencyKey, + ) + + } else { + + idempotencyKey = requestInfo + + logger.OpenapiLog.Infof( + "[CallAPI] Existing 3gpp-Sbi-Request-Info=%s", + requestInfo, + ) + } + } + + for attempt := 1; attempt <= maxRetries; attempt++ { + + if deadline, ok := request.Context().Deadline(); ok { + logger.OpenapiLog.Infof( + "[CallAPI] Attempt=%d Method=%s RemainingContext=%v Deadline=%v", + attempt, + request.Method, + time.Until(deadline), + deadline, + ) + } + + logger.OpenapiLog.Infof( + "[CallAPI] HTTP Client Timeout=%v", + httpClient.Timeout, + ) + + if attempt > 1 && + isNonIdempotent(request.Method) && + idempotencyKey != "" { + + request.Header.Set( + "3gpp-Sbi-Request-Info", + fmt.Sprintf( + "retrans=true; idempotency-key=%s", + idempotencyKey, + ), + ) + + logger.OpenapiLog.Infof( + "[CallAPI] Retry attempt=%d with SBI Request Info=%s", + attempt, + request.Header.Get("3gpp-Sbi-Request-Info"), + ) + } + + resp, err = httpClient.Do(request) + + if err == nil { + break + } + + logger.OpenapiLog.Errorf( + "[CallAPI] attempt=%d/%d failed errType=%T err=%v", + attempt, + maxRetries, + err, + err, + ) + + logger.OpenapiLog.Errorf( + "[CallAPI] errors.Is(context.DeadlineExceeded)=%v", + errors.Is(err, context.DeadlineExceeded), + ) + + logger.OpenapiLog.Errorf( + "[CallAPI] errors.Is(context.Canceled)=%v", + errors.Is(err, context.Canceled), + ) + + if ue, ok := err.(*url.Error); ok { + + logger.OpenapiLog.Errorf( + "[CallAPI] url.Error Op=%s URL=%s InnerType=%T InnerErr=%v", + ue.Op, + ue.URL, + ue.Err, + ue.Err, + ) + + if errors.Is(ue.Err, context.DeadlineExceeded) { + logger.OpenapiLog.Errorf( + "[CallAPI] Request context deadline exceeded", + ) + } + + if errors.Is(ue.Err, context.Canceled) { + logger.OpenapiLog.Errorf( + "[CallAPI] Request context cancelled", + ) + } + + if unwrapped := errors.Unwrap(ue.Err); unwrapped != nil { + logger.OpenapiLog.Errorf( + "[CallAPI] UnwrappedType=%T UnwrappedErr=%v", + unwrapped, + unwrapped, + ) + } + } + if !shouldRetry(request.Method, err) { + logger.OpenapiLog.Warnf( + "[CallAPI] Retry not allowed method=%s err=%v", + request.Method, + err, + ) + + return resp, err + } + if attempt < maxRetries { + + if request.GetBody != nil { + request.Body, _ = request.GetBody() + } + + backoff := time.Duration(attempt*100) * time.Millisecond + + logger.OpenapiLog.Warnf( + "[CallAPI] Retrying after %v", + backoff, + ) + + time.Sleep(backoff) + } } if err != nil { - logger.OpenapiLog.Errorf("[CallAPI] HTTP request failed: %v", err) + logger.OpenapiLog.Errorf( + "[CallAPI] HTTP request failed after retries: %v", + err, + ) + return resp, err } if resp == nil { - logger.OpenapiLog.Errorln("[CallAPI] Received nil HTTP response") + logger.OpenapiLog.Errorln( + "[CallAPI] Received nil HTTP response", + ) + return nil, fmt.Errorf("nil http response") } - logger.OpenapiLog.Debugf("[CallAPI] Response Status: %s", resp.Status) - logger.OpenapiLog.Debugf("[CallAPI] Response Status Code: %d", resp.StatusCode) + logger.OpenapiLog.Debugf( + "[CallAPI] Response Status: %s", + resp.Status, + ) + + logger.OpenapiLog.Debugf( + "[CallAPI] Response Status Code: %d", + resp.StatusCode, + ) for key, value := range resp.Header { - logger.OpenapiLog.Debugf("[CallAPI] Response Header %s: %v", key, value) + logger.OpenapiLog.Debugf( + "[CallAPI] Response Header %s: %v", + key, + value, + ) } logger.OpenapiLog.Debugln("[CallAPI] Exit") @@ -644,8 +844,17 @@ func Deserialize(v interface{}, b []byte, contentType string) (err error) { logger.OpenapiLog.Debugf("[Deserialize] String body: %s", *s) return nil } - + logger.OpenapiLog.Errorf( + "[Deserialize] contentType='%s' bodyLen=%d body='%s'", + contentType, + len(b), + string(b), + ) mediaType := KindOfMediaType(contentType) + logger.OpenapiLog.Errorf( + "[Deserialize] mediaType=%v", + mediaType, + ) logger.OpenapiLog.Debugf("[Deserialize] Detected media type: %v", mediaType) @@ -847,3 +1056,52 @@ func InterceptH2CClient() { func RestoreH2CClient() { gock.RestoreClient(innerHTTP2CleartextClient) } + +func shouldRetry(method string, err error) bool { + if err == nil { + return false + } + + // Idempotent methods + switch method { + case http.MethodGet, + http.MethodHead, + http.MethodPut, + http.MethodDelete: + return true + } + + // Non-idempotent POST + if method == http.MethodPost { + errStr := err.Error() + + // RFC7540 / 3GPP TS 29.500 allowed retry cases + if strings.Contains(errStr, "REFUSED_STREAM") { + return true + } + + if strings.Contains(errStr, "GOAWAY") { + return true + } + + if strings.Contains(errStr, "client conn could not be established") { + logger.OpenapiLog.Warn( + "[CallAPI] Retrying POST due to connection establishment failure", + ) + return true + } + + } + + return false +} + +func isNonIdempotent(method string) bool { + switch method { + case http.MethodPost, + http.MethodPatch: + return true + default: + return false + } +} diff --git a/go.mod b/go.mod index 42380088..d88145ca 100644 --- a/go.mod +++ b/go.mod @@ -15,6 +15,7 @@ require ( require ( github.com/davecgh/go-spew v1.1.1 // indirect + github.com/google/uuid v1.6.0 github.com/h2non/parth v0.0.0-20190131123155-b4df798d6542 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect go.uber.org/multierr v1.11.0 // indirect diff --git a/go.sum b/go.sum index 615b0b13..af0e5cea 100644 --- a/go.sum +++ b/go.sum @@ -4,6 +4,8 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/golang-jwt/jwt/v5 v5.2.2 h1:Rl4B7itRWVtYIHFrSNd7vhTiz9UpLdi6gZhZ3wEeDy8= github.com/golang-jwt/jwt/v5 v5.2.2/go.mod h1:pqrtFR0X4osieyHYxtmOUWsAWrfe1Q5UVIyoH402zdk= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/h2non/parth v0.0.0-20190131123155-b4df798d6542 h1:2VTzZjLZBgl62/EtslCrtky5vbi9dd7HrQPQIx6wqiw= github.com/h2non/parth v0.0.0-20190131123155-b4df798d6542/go.mod h1:Ow0tF8D4Kplbc8s8sSb3V2oUCygFHVp8gC3Dn6U4MNI= github.com/mitchellh/mapstructure v1.5.0 h1:jeMsZIYE/09sWLaz43PL7Gy6RuMjD2eJVyuac5Z2hdY=