X-Git-Url: https://gerrit.o-ran-sc.org/r/gitweb?a=blobdiff_plain;f=pkg%2Fcontrol%2Fcontrol.go;h=7de724ec09bf05a3970b2dd1c7c10886012bd498;hb=3d80b72cb374aec809740f3bec895d4b37a4fc2f;hp=aee1158c5ca0affa097211ec58d48adfcbfed657;hpb=afbf95f5756a7b781859beb1e68b41f7319ed208;p=ric-plt%2Fsubmgr.git diff --git a/pkg/control/control.go b/pkg/control/control.go index aee1158..7de724e 100755 --- a/pkg/control/control.go +++ b/pkg/control/control.go @@ -30,6 +30,7 @@ import ( "gerrit.o-ran-sc.org/r/ric-plt/e2ap/pkg/e2ap" rtmgrclient "gerrit.o-ran-sc.org/r/ric-plt/submgr/pkg/rtmgr_client" "gerrit.o-ran-sc.org/r/ric-plt/xapp-frame/pkg/models" + "gerrit.o-ran-sc.org/r/ric-plt/xapp-frame/pkg/restapi/operations/common" "gerrit.o-ran-sc.org/r/ric-plt/xapp-frame/pkg/xapp" httptransport "github.com/go-openapi/runtime/client" "github.com/go-openapi/strfmt" @@ -46,8 +47,12 @@ func idstring(err error, entries ...fmt.Stringer) string { var retval string = "" var filler string = "" for _, entry := range entries { - retval += filler + entry.String() - filler = " " + if entry != nil { + retval += filler + entry.String() + filler = " " + } else { + retval += filler + "(NIL)" + } } if err != nil { retval += filler + "err(" + err.Error() + ")" @@ -63,20 +68,29 @@ func idstring(err error, entries ...fmt.Stringer) string { var e2tSubReqTimeout time.Duration var e2tSubDelReqTime time.Duration var e2tRecvMsgTimeout time.Duration +var waitRouteCleanup_ms time.Duration var e2tMaxSubReqTryCount uint64 // Initial try + retry var e2tMaxSubDelReqTryCount uint64 // Initial try + retry +var checkE2State string var readSubsFromDb string +var dbRetryForever string +var dbTryCount int type Control struct { *xapp.RMRClient - e2ap *E2ap - registry *Registry - tracker *Tracker - db Sdlnterface - //subscriber *xapp.Subscriber - CntRecvMsg uint64 - ResetTestFlag bool - Counters map[string]xapp.Counter + e2ap *E2ap + registry *Registry + tracker *Tracker + restDuplicateCtrl *DuplicateCtrl + e2IfState *E2IfState + e2IfStateDb XappRnibInterface + e2SubsDb Sdlnterface + restSubsDb Sdlnterface + CntRecvMsg uint64 + ResetTestFlag bool + Counters map[string]xapp.Counter + LoggerLevel int + UTTesting bool } type RMRMeid struct { @@ -87,9 +101,24 @@ type RMRMeid struct { type SubmgrRestartTestEvent struct{} type SubmgrRestartUpEvent struct{} +type PackSubscriptionRequestErrortEvent struct { + ErrorInfo ErrorInfo +} + +func (p *PackSubscriptionRequestErrortEvent) SetEvent(errorInfo *ErrorInfo) { + p.ErrorInfo = *errorInfo +} + +type SDLWriteErrortEvent struct { + ErrorInfo ErrorInfo +} + +func (s *SDLWriteErrortEvent) SetEvent(errorInfo *ErrorInfo) { + s.ErrorInfo = *errorInfo +} func init() { - xapp.Logger.Info("SUBMGR") + xapp.Logger.Debug("SUBMGR") viper.AutomaticEnv() viper.SetEnvPrefix("submgr") viper.AllowEmptyEnv(true) @@ -107,35 +136,38 @@ func NewControl() *Control { tracker := new(Tracker) tracker.Init() + restDuplicateCtrl := new(DuplicateCtrl) + restDuplicateCtrl.Init() + + e2IfState := new(E2IfState) + c := &Control{e2ap: new(E2ap), - registry: registry, - tracker: tracker, - db: CreateSdl(), - //subscriber: subscriber, - Counters: xapp.Metric.RegisterCounterGroup(GetMetricsOpts(), "SUBMGR"), - } + registry: registry, + tracker: tracker, + restDuplicateCtrl: restDuplicateCtrl, + e2IfState: e2IfState, + e2IfStateDb: CreateXappRnibIfInstance(), + e2SubsDb: CreateSdl(), + restSubsDb: CreateRESTSdl(), + Counters: xapp.Metric.RegisterCounterGroup(GetMetricsOpts(), "SUBMGR"), + LoggerLevel: 1, + } + + e2IfState.Init(c) c.ReadConfigParameters("") // Register REST handler for testing support xapp.Resource.InjectRoute("/ric/v1/test/{testId}", c.TestRestHandler, "POST") + xapp.Resource.InjectRoute("/ric/v1/restsubscriptions", c.GetAllRestSubscriptions, "GET") xapp.Resource.InjectRoute("/ric/v1/symptomdata", c.SymptomDataHandler, "GET") - go xapp.Subscription.Listen(c.SubscriptionHandler, c.QueryHandler, c.SubscriptionDeleteHandlerCB) - - if readSubsFromDb == "false" { - return c + if readSubsFromDb == "true" { + // Read subscriptions from db + c.ReadE2Subscriptions() + c.ReadRESTSubscriptions() } - // Read subscriptions from db - xapp.Logger.Info("Reading subscriptions from db") - subIds, register, err := c.ReadAllSubscriptionsFromSdl() - if err != nil { - xapp.Logger.Error("%v", err) - } else { - c.registry.subIds = subIds - c.registry.register = register - c.HandleUncompletedSubscriptions(register) - } + go xapp.Subscription.Listen(c.RESTSubscriptionHandler, c.RESTQueryHandler, c.RESTSubscriptionDeleteHandler) return c } @@ -144,43 +176,143 @@ func (c *Control) SymptomDataHandler(w http.ResponseWriter, r *http.Request) { xapp.Resource.SendSymptomDataJson(w, r, subscriptions, "platform/subscriptions.json") } +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) GetAllRestSubscriptions(w http.ResponseWriter, r *http.Request) { + xapp.Logger.Debug("GetAllRestSubscriptions() called") + response := c.registry.GetAllRestSubscriptions() + w.Write(response) +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) ReadE2Subscriptions() error { + var err error + var subIds []uint32 + var register map[uint32]*Subscription + for i := 0; dbRetryForever == "true" || i < dbTryCount; i++ { + xapp.Logger.Debug("Reading E2 subscriptions from db") + subIds, register, err = c.ReadAllSubscriptionsFromSdl() + if err != nil { + xapp.Logger.Error("%v", err) + <-time.After(1 * time.Second) + } else { + c.registry.subIds = subIds + c.registry.register = register + c.HandleUncompletedSubscriptions(register) + return nil + } + } + xapp.Logger.Debug("Continuing without retring") + return err +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) ReadRESTSubscriptions() error { + var err error + var restSubscriptions map[string]*RESTSubscription + for i := 0; dbRetryForever == "true" || i < dbTryCount; i++ { + xapp.Logger.Debug("Reading REST subscriptions from db") + restSubscriptions, err = c.ReadAllRESTSubscriptionsFromSdl() + if err != nil { + xapp.Logger.Error("%v", err) + <-time.After(1 * time.Second) + } else { + c.registry.restSubscriptions = restSubscriptions + return nil + } + } + xapp.Logger.Debug("Continuing without retring") + return err +} + //------------------------------------------------------------------- // //------------------------------------------------------------------- func (c *Control) ReadConfigParameters(f string) { + xapp.Logger.Debug("ReadConfigParameters") + + c.LoggerLevel = int(xapp.Logger.GetLevel()) + xapp.Logger.Info("LoggerLevel = %v", c.LoggerLevel) + c.e2ap.SetASN1DebugPrintStatus(c.LoggerLevel) + // viper.GetDuration returns nanoseconds e2tSubReqTimeout = viper.GetDuration("controls.e2tSubReqTimeout_ms") * 1000000 if e2tSubReqTimeout == 0 { e2tSubReqTimeout = 2000 * 1000000 + xapp.Logger.Debug("WARNING: Using hard coded default value for e2tSubReqTimeout") } - xapp.Logger.Info("e2tSubReqTimeout %v", e2tSubReqTimeout) + xapp.Logger.Debug("e2tSubReqTimeout= %v", e2tSubReqTimeout) + e2tSubDelReqTime = viper.GetDuration("controls.e2tSubDelReqTime_ms") * 1000000 if e2tSubDelReqTime == 0 { e2tSubDelReqTime = 2000 * 1000000 + xapp.Logger.Debug("WARNING: Using hard coded default value for e2tSubDelReqTime") } - xapp.Logger.Info("e2tSubDelReqTime %v", e2tSubDelReqTime) + xapp.Logger.Debug("e2tSubDelReqTime= %v", e2tSubDelReqTime) + e2tRecvMsgTimeout = viper.GetDuration("controls.e2tRecvMsgTimeout_ms") * 1000000 if e2tRecvMsgTimeout == 0 { e2tRecvMsgTimeout = 2000 * 1000000 + xapp.Logger.Debug("WARNING: Using hard coded default value for e2tRecvMsgTimeout") } - xapp.Logger.Info("e2tRecvMsgTimeout %v", e2tRecvMsgTimeout) + xapp.Logger.Debug("e2tRecvMsgTimeout= %v", e2tRecvMsgTimeout) + e2tMaxSubReqTryCount = viper.GetUint64("controls.e2tMaxSubReqTryCount") if e2tMaxSubReqTryCount == 0 { e2tMaxSubReqTryCount = 1 + xapp.Logger.Debug("WARNING: Using hard coded default value for e2tMaxSubReqTryCount") } - xapp.Logger.Info("e2tMaxSubReqTryCount %v", e2tMaxSubReqTryCount) + xapp.Logger.Debug("e2tMaxSubReqTryCount= %v", e2tMaxSubReqTryCount) + e2tMaxSubDelReqTryCount = viper.GetUint64("controls.e2tMaxSubDelReqTryCount") if e2tMaxSubDelReqTryCount == 0 { e2tMaxSubDelReqTryCount = 1 + xapp.Logger.Debug("WARNING: Using hard coded default value for e2tMaxSubDelReqTryCount") } - xapp.Logger.Info("e2tMaxSubDelReqTryCount %v", e2tMaxSubDelReqTryCount) + xapp.Logger.Debug("e2tMaxSubDelReqTryCount= %v", e2tMaxSubDelReqTryCount) + + checkE2State = viper.GetString("controls.checkE2State") + if checkE2State == "" { + checkE2State = "true" + xapp.Logger.Debug("WARNING: Using hard coded default value for checkE2State") + } + xapp.Logger.Debug("checkE2State= %v", checkE2State) readSubsFromDb = viper.GetString("controls.readSubsFromDb") if readSubsFromDb == "" { readSubsFromDb = "true" + xapp.Logger.Debug("WARNING: Using hard coded default value for readSubsFromDb") + } + xapp.Logger.Debug("readSubsFromDb= %v", readSubsFromDb) + + dbTryCount = viper.GetInt("controls.dbTryCount") + if dbTryCount == 0 { + dbTryCount = 200 + xapp.Logger.Debug("WARNING: Using hard coded default value for dbTryCount") } - xapp.Logger.Info("readSubsFromDb %v", readSubsFromDb) + xapp.Logger.Debug("dbTryCount= %v", dbTryCount) + + dbRetryForever = viper.GetString("controls.dbRetryForever") + if dbRetryForever == "" { + dbRetryForever = "true" + xapp.Logger.Debug("WARNING: Using hard coded default value for dbRetryForever") + } + xapp.Logger.Debug("dbRetryForever= %v", dbRetryForever) + + // Internal cfg parameter, used to define a wait time for RMR route clean-up. None default + // value 100ms used currently only in unittests. + waitRouteCleanup_ms = viper.GetDuration("controls.waitRouteCleanup_ms") * 1000000 + if waitRouteCleanup_ms == 0 { + waitRouteCleanup_ms = 5000 * 1000000 + xapp.Logger.Debug("WARNING: Using hard coded default value for waitRouteCleanup_ms") + } + xapp.Logger.Debug("waitRouteCleanup= %v", waitRouteCleanup_ms) } //------------------------------------------------------------------- @@ -191,9 +323,12 @@ func (c *Control) HandleUncompletedSubscriptions(register map[uint32]*Subscripti xapp.Logger.Debug("HandleUncompletedSubscriptions. len(register) = %v", len(register)) for subId, subs := range register { if subs.SubRespRcvd == false { - subs.NoRespToXapp = true - xapp.Logger.Debug("SendSubscriptionDeleteReq. subId = %v", subId) - c.SendSubscriptionDeleteReq(subs) + // If policy subscription has already been made successfully unsuccessful update should not be deleted. + if subs.PolicyUpdate == false { + subs.NoRespToXapp = true + xapp.Logger.Debug("SendSubscriptionDeleteReq. subId = %v", subId) + c.SendSubscriptionDeleteReq(subs) + } } } } @@ -213,46 +348,168 @@ func (c *Control) Run() { //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionResponse, error) { +func (c *Control) GetOrCreateRestSubscription(p *models.SubscriptionParams, md5sum string, xAppRmrEndpoint string) (*RESTSubscription, string, error) { + + var restSubId string + var restSubscription *RESTSubscription + var err error + + prevRestSubsId, exists := c.restDuplicateCtrl.GetLastKnownRestSubsIdBasedOnMd5sum(md5sum) + if p.SubscriptionID == "" { + // Subscription does not contain REST subscription Id + if exists { + restSubscription, err = c.registry.GetRESTSubscription(prevRestSubsId, false) + if restSubscription != nil { + // Subscription not found + restSubId = prevRestSubsId + if err == nil { + xapp.Logger.Debug("Existing restSubId %s found by MD5sum %s for a request without subscription ID - using previous subscription", prevRestSubsId, md5sum) + } else { + xapp.Logger.Debug("Existing restSubId %s found by MD5sum %s for a request without subscription ID - Note: %s", prevRestSubsId, md5sum, err.Error()) + } + } else { + xapp.Logger.Debug("None existing restSubId %s referred by MD5sum %s for a request without subscription ID - deleting cached entry", prevRestSubsId, md5sum) + c.restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(md5sum) + } + } + + if restSubscription == nil { + restSubId = ksuid.New().String() + restSubscription = c.registry.CreateRESTSubscription(&restSubId, &xAppRmrEndpoint, p.Meid) + } + } else { + // Subscription contains REST subscription Id + restSubId = p.SubscriptionID + + xapp.Logger.Debug("RestSubscription ID %s provided via REST request", restSubId) + restSubscription, err = c.registry.GetRESTSubscription(restSubId, false) + if err != nil { + // Subscription with id in REST request does not exist + xapp.Logger.Error("%s", err.Error()) + c.UpdateCounter(cRestSubFailToXapp) + return nil, "", err + } + + if !exists { + xapp.Logger.Debug("Existing restSubscription found for ID %s, new request based on md5sum", restSubId) + } else { + xapp.Logger.Debug("Existing restSubscription found for ID %s(%s), re-transmission based on md5sum match with previous request", prevRestSubsId, restSubId) + } + } + + return restSubscription, restSubId, nil +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) RESTSubscriptionHandler(params interface{}) (*models.SubscriptionResponse, int) { + + c.CntRecvMsg++ + c.UpdateCounter(cRestSubReqFromXapp) - restSubId := ksuid.New().String() subResp := models.SubscriptionResponse{} - subResp.SubscriptionID = &restSubId p := params.(*models.SubscriptionParams) - c.CntRecvMsg++ + if c.LoggerLevel > 2 { + c.PrintRESTSubscriptionRequest(p) + } - c.UpdateCounter(cSubReqFromXapp) + if c.e2IfState.IsE2ConnectionUp(p.Meid) == false { + xapp.Logger.Error("No E2 connection for ranName %v", *p.Meid) + c.UpdateCounter(cRestReqRejDueE2Down) + return nil, common.SubscribeServiceUnavailableCode + } if p.ClientEndpoint == nil { - xapp.Logger.Error("ClientEndpoint == nil") - return nil, fmt.Errorf("") + err := fmt.Errorf("ClientEndpoint == nil") + xapp.Logger.Error("%v", err) + c.UpdateCounter(cRestSubFailToXapp) + return nil, common.SubscribeBadRequestCode } _, xAppRmrEndpoint, err := ConstructEndpointAddresses(*p.ClientEndpoint) if err != nil { xapp.Logger.Error("%s", err.Error()) - return nil, err + c.UpdateCounter(cRestSubFailToXapp) + return nil, common.SubscribeBadRequestCode } - restSubscription, err := c.registry.CreateRESTSubscription(&restSubId, &xAppRmrEndpoint, p.Meid) + md5sum, err := CalculateRequestMd5sum(params) if err != nil { - xapp.Logger.Error("%s", err.Error()) - return nil, err + xapp.Logger.Error("Failed to generate md5sum from incoming request - %s", err.Error()) } + restSubscription, restSubId, err := c.GetOrCreateRestSubscription(p, md5sum, xAppRmrEndpoint) + if err != nil { + xapp.Logger.Error("Subscription with id in REST request does not exist") + return nil, common.SubscribeNotFoundCode + } + + subResp.SubscriptionID = &restSubId subReqList := e2ap.SubscriptionRequestList{} err = c.e2ap.FillSubscriptionReqMsgs(params, &subReqList, restSubscription) if err != nil { xapp.Logger.Error("%s", err.Error()) + c.restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(md5sum) c.registry.DeleteRESTSubscription(&restSubId) - return nil, err + c.UpdateCounter(cRestSubFailToXapp) + return nil, common.SubscribeBadRequestCode } - go c.processSubscriptionRequests(restSubscription, &subReqList, p.ClientEndpoint, p.Meid, &restSubId) + duplicate := c.restDuplicateCtrl.IsDuplicateToOngoingTransaction(restSubId, md5sum) + if duplicate { + err := fmt.Errorf("Retransmission blocker direct ACK for request of restSubsId %s restSubId MD5sum %s as retransmission", restSubId, md5sum) + xapp.Logger.Debug("%s", err) + c.UpdateCounter(cRestSubRespToXapp) + return &subResp, common.SubscribeCreatedCode + } + + c.WriteRESTSubscriptionToDb(restSubId, restSubscription) + e2SubscriptionDirectives, err := c.GetE2SubscriptionDirectives(p) + if err != nil { + xapp.Logger.Error("%s", err) + return nil, common.SubscribeBadRequestCode + } + go c.processSubscriptionRequests(restSubscription, &subReqList, p.ClientEndpoint, p.Meid, &restSubId, xAppRmrEndpoint, md5sum, e2SubscriptionDirectives) - return &subResp, nil + c.UpdateCounter(cRestSubRespToXapp) + return &subResp, common.SubscribeCreatedCode +} +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) GetE2SubscriptionDirectives(p *models.SubscriptionParams) (*E2SubscriptionDirectives, error) { + + e2SubscriptionDirectives := &E2SubscriptionDirectives{} + if p == nil || p.E2SubscriptionDirectives == nil { + e2SubscriptionDirectives.E2TimeoutTimerValue = e2tSubReqTimeout + e2SubscriptionDirectives.E2MaxTryCount = int64(e2tMaxSubReqTryCount) + e2SubscriptionDirectives.CreateRMRRoute = true + xapp.Logger.Debug("p == nil || p.E2SubscriptionDirectives == nil. Using default values for E2TimeoutTimerValue = %v and E2RetryCount = %v RMRRoutingNeeded = true", e2tSubReqTimeout, e2tMaxSubReqTryCount) + } else { + if p.E2SubscriptionDirectives.E2TimeoutTimerValue >= 1 && p.E2SubscriptionDirectives.E2TimeoutTimerValue <= 10 { + e2SubscriptionDirectives.E2TimeoutTimerValue = time.Duration(p.E2SubscriptionDirectives.E2TimeoutTimerValue) * 1000000000 // Duration type cast returns nano seconds + } else { + return nil, fmt.Errorf("p.E2SubscriptionDirectives.E2TimeoutTimerValue out of range (1-10 seconds): %v", p.E2SubscriptionDirectives.E2TimeoutTimerValue) + } + if p.E2SubscriptionDirectives.E2RetryCount == nil { + xapp.Logger.Error("p.E2SubscriptionDirectives.E2RetryCount == nil. Using default value") + e2SubscriptionDirectives.E2MaxTryCount = int64(e2tMaxSubReqTryCount) + } else { + if *p.E2SubscriptionDirectives.E2RetryCount >= 0 && *p.E2SubscriptionDirectives.E2RetryCount <= 10 { + e2SubscriptionDirectives.E2MaxTryCount = *p.E2SubscriptionDirectives.E2RetryCount + 1 // E2MaxTryCount = First sending plus two retries + } else { + return nil, fmt.Errorf("p.E2SubscriptionDirectives.E2RetryCount out of range (0-10): %v", *p.E2SubscriptionDirectives.E2RetryCount) + } + } + e2SubscriptionDirectives.CreateRMRRoute = p.E2SubscriptionDirectives.RMRRoutingNeeded + } + xapp.Logger.Debug("e2SubscriptionDirectives.E2TimeoutTimerValue: %v", e2SubscriptionDirectives.E2TimeoutTimerValue) + xapp.Logger.Debug("e2SubscriptionDirectives.E2MaxTryCount: %v", e2SubscriptionDirectives.E2MaxTryCount) + xapp.Logger.Debug("e2SubscriptionDirectives.CreateRMRRoute: %v", e2SubscriptionDirectives.CreateRMRRoute) + return e2SubscriptionDirectives, nil } //------------------------------------------------------------------- @@ -260,67 +517,59 @@ func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionR //------------------------------------------------------------------- func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription, subReqList *e2ap.SubscriptionRequestList, - clientEndpoint *models.SubscriptionParamsClientEndpoint, meid *string, restSubId *string) { + clientEndpoint *models.SubscriptionParamsClientEndpoint, meid *string, restSubId *string, xAppRmrEndpoint string, md5sum string, e2SubscriptionDirectives *E2SubscriptionDirectives) { - xapp.Logger.Info("Subscription Request count=%v ", len(subReqList.E2APSubscriptionRequests)) + c.SubscriptionProcessingStartDelay() + xapp.Logger.Debug("Subscription Request count=%v ", len(subReqList.E2APSubscriptionRequests)) - _, xAppRmrEndpoint, err := ConstructEndpointAddresses(*clientEndpoint) - if err != nil { - xapp.Logger.Error("%s", err.Error()) - return - } + var xAppEventInstanceID int64 + var e2EventInstanceID int64 + errorInfo := &ErrorInfo{} + + defer c.restDuplicateCtrl.SetMd5sumFromLastOkRequest(*restSubId, md5sum) - var requestorID int64 - var instanceId int64 for index := 0; index < len(subReqList.E2APSubscriptionRequests); index++ { subReqMsg := subReqList.E2APSubscriptionRequests[index] + xAppEventInstanceID = (int64)(subReqMsg.RequestId.Id) trans := c.tracker.NewXappTransaction(xapp.NewRmrEndpoint(xAppRmrEndpoint), *restSubId, subReqMsg.RequestId, &xapp.RMRMeid{RanName: *meid}) if trans == nil { - c.registry.DeleteRESTSubscription(restSubId) - xapp.Logger.Error("XAPP-SubReq transaction not created. RESTSubId=%s, EndPoint=%s, Meid=%s", *restSubId, xAppRmrEndpoint, *meid) - return + // Send notification to xApp that prosessing of a Subscription Request has failed. + err := fmt.Errorf("Tracking failure") + errorInfo.ErrorCause = err.Error() + c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans, errorInfo) + continue } - defer trans.Release() - xapp.Logger.Info("Handle SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) - subRespMsg, err := c.handleSubscriptionRequest(trans, &subReqMsg, meid, restSubId) + xapp.Logger.Debug("Handle SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) + + subRespMsg, errorInfo, err := c.handleSubscriptionRequest(trans, &subReqMsg, meid, *restSubId, e2SubscriptionDirectives) + + xapp.Logger.Debug("Handled SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) + trans.Release() + if err != nil { - // Send notification to xApp that prosessing of a Subscription Request has failed. Currently it is not possible - // to indicate error. Such possibility should be added. As a workaround requestorID and instanceId are set to zero value - requestorID = (int64)(0) - instanceId = (int64)(0) - resp := &models.SubscriptionResponse{ - SubscriptionID: restSubId, - SubscriptionInstances: []*models.SubscriptionInstance{ - &models.SubscriptionInstance{RequestorID: &requestorID, InstanceID: &instanceId}, - }, - } - // Mark REST subscription request processed. - restSubscription.SetProcessed() - xapp.Logger.Info("Sending unsuccessful REST notification to endpoint=%v:%v, InstanceId=%v, %s", clientEndpoint.Host, clientEndpoint.HTTPPort, instanceId, idstring(nil, trans)) - xapp.Subscription.Notify(resp, *clientEndpoint) + c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans, errorInfo) } else { - xapp.Logger.Info("SubscriptionRequest index=%v processed successfully. endpoint=%v, InstanceId=%v, %s", index, *clientEndpoint, instanceId, idstring(nil, trans)) - - // Store successfully processed InstanceId for deletion - restSubscription.AddInstanceId(subRespMsg.RequestId.InstanceId) - - // Send notification to xApp that a Subscription Request has been processed. - requestorID = (int64)(subRespMsg.RequestId.Id) - instanceId = (int64)(subRespMsg.RequestId.InstanceId) - resp := &models.SubscriptionResponse{ - SubscriptionID: restSubId, - SubscriptionInstances: []*models.SubscriptionInstance{ - &models.SubscriptionInstance{RequestorID: &requestorID, InstanceID: &instanceId}, - }, - } - // Mark REST subscription request processesd. - restSubscription.SetProcessed() - xapp.Logger.Info("Sending successful REST notification to endpoint=%v, InstanceId=%v, %s", *clientEndpoint, instanceId, idstring(nil, trans)) - xapp.Subscription.Notify(resp, *clientEndpoint) + e2EventInstanceID = (int64)(subRespMsg.RequestId.InstanceId) + restSubscription.AddMd5Sum(md5sum) + xapp.Logger.Debug("SubscriptionRequest index=%v processed successfullyfor %s. endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + index, *restSubId, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) + c.sendSuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, e2EventInstanceID, clientEndpoint, trans) } - c.UpdateCounter(cSubRespToXapp) + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------ +func (c *Control) SubscriptionProcessingStartDelay() { + if c.UTTesting == true { + // This is temporary fix for the UT problem that notification arrives before subscription response + // Correct fix would be to allow notification come before response and process it correctly + xapp.Logger.Debug("Setting 50 ms delay before starting processing Subscriptions") + <-time.After(time.Millisecond * 50) + xapp.Logger.Debug("Continuing after delay") } } @@ -328,137 +577,252 @@ func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription // //------------------------------------------------------------------ func (c *Control) handleSubscriptionRequest(trans *TransactionXapp, subReqMsg *e2ap.E2APSubscriptionRequest, meid *string, - restSubId *string) (*e2ap.E2APSubscriptionResponse, error) { + restSubId string, e2SubscriptionDirectives *E2SubscriptionDirectives) (*e2ap.E2APSubscriptionResponse, *ErrorInfo, error) { + + errorInfo := ErrorInfo{} err := c.tracker.Track(trans) if err != nil { - err = fmt.Errorf("XAPP-SubReq: %s", idstring(err, trans)) - xapp.Logger.Error("%s", err.Error()) - return nil, err + xapp.Logger.Error("XAPP-SubReq Tracking error: %s", idstring(err, trans)) + errorInfo.ErrorCause = err.Error() + err = fmt.Errorf("Tracking failure") + return nil, &errorInfo, err } - subs, err := c.registry.AssignToSubscription(trans, subReqMsg, c.ResetTestFlag, c) + subs, errorInfo, err := c.registry.AssignToSubscription(trans, subReqMsg, c.ResetTestFlag, c, e2SubscriptionDirectives.CreateRMRRoute) if err != nil { - err = fmt.Errorf("XAPP-SubReq: %s", idstring(err, trans)) - xapp.Logger.Error("%s", err.Error()) - return nil, err + xapp.Logger.Error("XAPP-SubReq Assign error: %s", idstring(err, trans)) + return nil, &errorInfo, err } // // Wake subs request // - go c.handleSubscriptionCreate(subs, trans) + subs.OngoingReqCount++ + go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives) event, _ := trans.WaitEvent(0) //blocked wait as timeout is handled in subs side + subs.OngoingReqCount-- err = nil if event != nil { switch themsg := event.(type) { case *e2ap.E2APSubscriptionResponse: trans.Release() - return themsg, nil + if c.e2IfState.IsE2ConnectionUp(meid) == true { + return themsg, &errorInfo, nil + } else { + c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) + c.RemoveSubscriptionFromDb(subs) + err = fmt.Errorf("E2 interface down") + errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "") + return nil, &errorInfo, err + } case *e2ap.E2APSubscriptionFailure: - err = fmt.Errorf("SubscriptionFailure received") - return nil, err + err = fmt.Errorf("E2 SubscriptionFailure received") + errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "") + return nil, &errorInfo, err + case *PackSubscriptionRequestErrortEvent: + err = fmt.Errorf("E2 SubscriptionRequest pack failure") + return nil, &themsg.ErrorInfo, err + case *SDLWriteErrortEvent: + err = fmt.Errorf("SDL write failure") + return nil, &themsg.ErrorInfo, err default: + err = fmt.Errorf("Unexpected E2 subscription response received") + errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "") break } + } else { + // Timer expiry + err = fmt.Errorf("E2 subscription response timeout") + errorInfo.SetInfo(err.Error(), "", models.SubscriptionInstanceTimeoutTypeE2Timeout) + if subs.PolicyUpdate == true { + return nil, &errorInfo, err + } } - err = fmt.Errorf("XAPP-SubReq: failed %s", idstring(err, trans, subs)) - xapp.Logger.Error("%s", err.Error()) - c.registry.RemoveFromSubscription(subs, trans, 5*time.Second, c) - return nil, err + + xapp.Logger.Error("XAPP-SubReq E2 subscription failed %s", idstring(err, trans, subs)) + + c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) + return nil, &errorInfo, err } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionDeleteHandlerCB(restSubId string) error { +func (c *Control) sendUnsuccesfullResponseNotification(restSubId *string, restSubscription *RESTSubscription, xAppEventInstanceID int64, err error, + clientEndpoint *models.SubscriptionParamsClientEndpoint, trans *TransactionXapp, errorInfo *ErrorInfo) { + + // Send notification to xApp that prosessing of a Subscription Request has failed. + e2EventInstanceID := (int64)(0) + if errorInfo.ErrorSource == "" { + // Submgr is default source of error + errorInfo.ErrorSource = models.SubscriptionInstanceErrorSourceSUBMGR + } + resp := &models.SubscriptionResponse{ + SubscriptionID: restSubId, + SubscriptionInstances: []*models.SubscriptionInstance{ + &models.SubscriptionInstance{E2EventInstanceID: &e2EventInstanceID, + ErrorCause: errorInfo.ErrorCause, + ErrorSource: errorInfo.ErrorSource, + TimeoutType: errorInfo.TimeoutType, + XappEventInstanceID: &xAppEventInstanceID}, + }, + } + // Mark REST subscription request processed. + restSubscription.SetProcessed(err) + c.UpdateRESTSubscriptionInDB(*restSubId, restSubscription, false) + if trans != nil { + xapp.Logger.Debug("Sending unsuccessful REST notification (cause %s) to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + errorInfo.ErrorCause, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) + } else { + xapp.Logger.Debug("Sending unsuccessful REST notification (cause %s) to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v", + errorInfo.ErrorCause, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID) + } + + c.UpdateCounter(cRestSubFailNotifToXapp) + xapp.Subscription.Notify(resp, *clientEndpoint) + + if c.e2IfState.IsE2ConnectionUp(&restSubscription.Meid) == false && restSubscription.SubReqOngoing == false { + c.registry.DeleteRESTSubscription(restSubId) + c.RemoveRESTSubscriptionFromDb(*restSubId) + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) sendSuccesfullResponseNotification(restSubId *string, restSubscription *RESTSubscription, xAppEventInstanceID int64, e2EventInstanceID int64, + clientEndpoint *models.SubscriptionParamsClientEndpoint, trans *TransactionXapp) { + + // Store successfully processed InstanceId for deletion + restSubscription.AddE2InstanceId((uint32)(e2EventInstanceID)) + restSubscription.AddXappIdToE2Id(xAppEventInstanceID, e2EventInstanceID) + + // Send notification to xApp that a Subscription Request has been processed. + resp := &models.SubscriptionResponse{ + SubscriptionID: restSubId, + SubscriptionInstances: []*models.SubscriptionInstance{ + &models.SubscriptionInstance{E2EventInstanceID: &e2EventInstanceID, + ErrorCause: "", + XappEventInstanceID: &xAppEventInstanceID}, + }, + } + // Mark REST subscription request processesd. + restSubscription.SetProcessed(nil) + c.UpdateRESTSubscriptionInDB(*restSubId, restSubscription, false) + xapp.Logger.Debug("Sending successful REST notification to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) + + c.UpdateCounter(cRestSubNotifToXapp) + xapp.Subscription.Notify(resp, *clientEndpoint) + + if c.e2IfState.IsE2ConnectionUp(&restSubscription.Meid) == false && restSubscription.SubReqOngoing == false { + c.registry.DeleteRESTSubscription(restSubId) + c.RemoveRESTSubscriptionFromDb(*restSubId) + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) RESTSubscriptionDeleteHandler(restSubId string) int { c.CntRecvMsg++ - c.UpdateCounter(cSubDelReqFromXapp) + c.UpdateCounter(cRestSubDelReqFromXapp) - xapp.Logger.Info("SubscriptionDeleteRequest from XAPP") + xapp.Logger.Debug("SubscriptionDeleteRequest from XAPP") - restSubscription, err := c.registry.GetRESTSubscription(restSubId) + restSubscription, err := c.registry.GetRESTSubscription(restSubId, true) if err != nil { xapp.Logger.Error("%s", err.Error()) if restSubscription == nil { // Subscription was not found - return nil + c.UpdateCounter(cRestSubDelRespToXapp) + return common.UnsubscribeNoContentCode } else { if restSubscription.SubReqOngoing == true { err := fmt.Errorf("Handling of the REST Subscription Request still ongoing %s", restSubId) xapp.Logger.Error("%s", err.Error()) - return err + c.UpdateCounter(cRestSubDelFailToXapp) + return common.UnsubscribeBadRequestCode } else if restSubscription.SubDelReqOngoing == true { // Previous request for same restSubId still ongoing - return nil + c.UpdateCounter(cRestSubDelRespToXapp) + return common.UnsubscribeNoContentCode } } } xAppRmrEndPoint := restSubscription.xAppRmrEndPoint go func() { + xapp.Logger.Debug("Deleteting handler: processing instances = %v", restSubscription.InstanceIds) for _, instanceId := range restSubscription.InstanceIds { - err := c.SubscriptionDeleteHandler(&restSubId, &xAppRmrEndPoint, &restSubscription.Meid, instanceId) + xAppEventInstanceID, err := c.SubscriptionDeleteHandler(&restSubId, &xAppRmrEndPoint, &restSubscription.Meid, instanceId) + if err != nil { xapp.Logger.Error("%s", err.Error()) - //return err } - xapp.Logger.Info("Deleteting instanceId = %v", instanceId) - restSubscription.DeleteInstanceId(instanceId) + xapp.Logger.Debug("Deleteting instanceId = %v", instanceId) + restSubscription.DeleteXappIdToE2Id(xAppEventInstanceID) + restSubscription.DeleteE2InstanceId(instanceId) } + c.restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(restSubscription.lastReqMd5sum) c.registry.DeleteRESTSubscription(&restSubId) + c.RemoveRESTSubscriptionFromDb(restSubId) }() - c.UpdateCounter(cSubDelRespToXapp) - - return nil + c.UpdateCounter(cRestSubDelRespToXapp) + return common.UnsubscribeNoContentCode } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string, meid *string, instanceId uint32) error { +func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string, meid *string, instanceId uint32) (int64, error) { - trans := c.tracker.NewXappTransaction(xapp.NewRmrEndpoint(*endPoint), *restSubId, e2ap.RequestId{0, 0}, &xapp.RMRMeid{RanName: *meid}) + var xAppEventInstanceID int64 + subs, err := c.registry.GetSubscriptionFirstMatch([]uint32{instanceId}) + if err != nil { + xapp.Logger.Debug("Subscription Delete Handler subscription for restSubId=%v, E2EventInstanceID=%v not found %s", + restSubId, instanceId, idstring(err, nil)) + return xAppEventInstanceID, nil + } + + xAppEventInstanceID = int64(subs.ReqId.Id) + trans := c.tracker.NewXappTransaction(xapp.NewRmrEndpoint(*endPoint), *restSubId, e2ap.RequestId{subs.ReqId.Id, 0}, &xapp.RMRMeid{RanName: *meid}) if trans == nil { err := fmt.Errorf("XAPP-SubDelReq transaction not created. restSubId %s, endPoint %s, meid %s, instanceId %v", *restSubId, *endPoint, *meid, instanceId) xapp.Logger.Error("%s", err.Error()) } defer trans.Release() - err := c.tracker.Track(trans) - if err != nil { - err := fmt.Errorf("XAPP-SubDelReq %s:", idstring(err, trans)) - xapp.Logger.Error("%s", err.Error()) - return &time.ParseError{} - } - - subs, err := c.registry.GetSubscriptionFirstMatch([]uint32{instanceId}) + err = c.tracker.Track(trans) if err != nil { err := fmt.Errorf("XAPP-SubDelReq %s:", idstring(err, trans)) xapp.Logger.Error("%s", err.Error()) - return err + return xAppEventInstanceID, &time.ParseError{} } // // Wake subs delete // + subs.OngoingDelCount++ go c.handleSubscriptionDelete(subs, trans) trans.WaitEvent(0) //blocked wait as timeout is handled in subs side + subs.OngoingDelCount-- xapp.Logger.Debug("XAPP-SubDelReq: Handling event %s ", idstring(nil, trans, subs)) - c.registry.RemoveFromSubscription(subs, trans, 5*time.Second, c) + c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) - return nil + return xAppEventInstanceID, nil } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) QueryHandler() (models.SubscriptionList, error) { - xapp.Logger.Info("QueryHandler() called") +func (c *Control) RESTQueryHandler() (models.SubscriptionList, error) { + xapp.Logger.Debug("RESTQueryHandler() called") c.CntRecvMsg++ @@ -466,7 +830,7 @@ func (c *Control) QueryHandler() (models.SubscriptionList, error) { } func (c *Control) TestRestHandler(w http.ResponseWriter, r *http.Request) { - xapp.Logger.Info("TestRestHandler() called") + xapp.Logger.Debug("RESTTestRestHandler() called") pathParams := mux.Vars(r) s := pathParams["testId"] @@ -475,7 +839,7 @@ func (c *Control) TestRestHandler(w http.ResponseWriter, r *http.Request) { if contains := strings.Contains(s, "deletesubid="); contains == true { var splits = strings.Split(s, "=") if subId, err := strconv.ParseInt(splits[1], 10, 64); err == nil { - xapp.Logger.Info("RemoveSubscriptionFromSdl() called. subId = %v", subId) + xapp.Logger.Debug("RemoveSubscriptionFromSdl() called. subId = %v", subId) c.RemoveSubscriptionFromSdl(uint32(subId)) return } @@ -483,18 +847,19 @@ func (c *Control) TestRestHandler(w http.ResponseWriter, r *http.Request) { // This can be used to remove all subscriptions db from if s == "emptydb" { - xapp.Logger.Info("RemoveAllSubscriptionsFromSdl() called") + xapp.Logger.Debug("RemoveAllSubscriptionsFromSdl() called") c.RemoveAllSubscriptionsFromSdl() + c.RemoveAllRESTSubscriptionsFromSdl() return } // This is meant to cause submgr's restart in testing if s == "restart" { - xapp.Logger.Info("os.Exit(1) called") + xapp.Logger.Debug("os.Exit(1) called") os.Exit(1) } - xapp.Logger.Info("Unsupported rest command received %s", s) + xapp.Logger.Debug("Unsupported rest command received %s", s) } //------------------------------------------------------------------- @@ -511,7 +876,7 @@ func (c *Control) rmrSendToE2T(desc string, subs *Subscription, trans *Transacti params.PayloadLen = len(trans.Payload.Buf) params.Payload = trans.Payload.Buf params.Mbuf = nil - xapp.Logger.Info("MSG to E2T: %s %s %s", desc, trans.String(), params.String()) + xapp.Logger.Debug("MSG to E2T: %s %s %s", desc, trans.String(), params.String()) err = c.SendWithRetry(params, false, 5) if err != nil { xapp.Logger.Error("rmrSendToE2T: Send failed: %+v", err) @@ -530,7 +895,7 @@ func (c *Control) rmrSendToXapp(desc string, subs *Subscription, trans *Transact params.PayloadLen = len(trans.Payload.Buf) params.Payload = trans.Payload.Buf params.Mbuf = nil - xapp.Logger.Info("MSG to XAPP: %s %s %s", desc, trans.String(), params.String()) + xapp.Logger.Debug("MSG to XAPP: %s %s %s", desc, trans.String(), params.String()) err = c.SendWithRetry(params, false, 5) if err != nil { xapp.Logger.Error("rmrSendToXapp: Send failed: %+v", err) @@ -572,7 +937,7 @@ func (c *Control) Consume(msg *xapp.RMRParams) (err error) { case xapp.RIC_SUB_DEL_FAILURE: go c.handleE2TSubscriptionDeleteFailure(msg) default: - xapp.Logger.Info("Unknown Message Type '%d', discarding", msg.Mtype) + xapp.Logger.Debug("Unknown Message Type '%d', discarding", msg.Mtype) } return } @@ -581,9 +946,14 @@ func (c *Control) Consume(msg *xapp.RMRParams) (err error) { // handle from XAPP Subscription Request //------------------------------------------------------------------ func (c *Control) handleXAPPSubscriptionRequest(params *xapp.RMRParams) { - xapp.Logger.Info("MSG from XAPP: %s", params.String()) + xapp.Logger.Debug("MSG from XAPP: %s", params.String()) c.UpdateCounter(cSubReqFromXapp) + if c.e2IfState.IsE2ConnectionUp(¶ms.Meid.RanName) == false { + xapp.Logger.Error("No E2 connection for ranName %v", params.Meid.RanName) + return + } + subReqMsg, err := c.e2ap.UnpackSubscriptionRequest(params.Payload) if err != nil { xapp.Logger.Error("XAPP-SubReq: %s", idstring(err, params)) @@ -603,7 +973,7 @@ func (c *Control) handleXAPPSubscriptionRequest(params *xapp.RMRParams) { } //TODO handle subscription toward e2term inside AssignToSubscription / hide handleSubscriptionCreate in it? - subs, err := c.registry.AssignToSubscription(trans, subReqMsg, c.ResetTestFlag, c) + subs, _, err := c.registry.AssignToSubscription(trans, subReqMsg, c.ResetTestFlag, c, true) if err != nil { xapp.Logger.Error("XAPP-SubReq: %s", idstring(err, trans)) return @@ -617,8 +987,11 @@ func (c *Control) handleXAPPSubscriptionRequest(params *xapp.RMRParams) { //------------------------------------------------------------------ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *TransactionXapp) { - go c.handleSubscriptionCreate(subs, trans) + e2SubscriptionDirectives, _ := c.GetE2SubscriptionDirectives(nil) + subs.OngoingReqCount++ + go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives) event, _ := trans.WaitEvent(0) //blocked wait as timeout is handled in subs side + subs.OngoingReqCount-- var err error if event != nil { switch themsg := event.(type) { @@ -642,7 +1015,7 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction break } } - xapp.Logger.Info("XAPP-SubReq: failed %s", idstring(err, trans, subs)) + xapp.Logger.Debug("XAPP-SubReq: failed %s", idstring(err, trans, subs)) //c.registry.RemoveFromSubscription(subs, trans, 5*time.Second) } @@ -650,9 +1023,14 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction // handle from XAPP Subscription Delete Request //------------------------------------------------------------------ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) { - xapp.Logger.Info("MSG from XAPP: %s", params.String()) + xapp.Logger.Debug("MSG from XAPP: %s", params.String()) c.UpdateCounter(cSubDelReqFromXapp) + if c.e2IfState.IsE2ConnectionUp(¶ms.Meid.RanName) == false { + xapp.Logger.Error("No E2 connection for ranName %v", params.Meid.RanName) + return + } + subDelReqMsg, err := c.e2ap.UnpackSubscriptionDeleteRequest(params.Payload) if err != nil { xapp.Logger.Error("XAPP-SubDelReq %s", idstring(err, params)) @@ -681,13 +1059,16 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) { // // Wake subs delete // + subs.OngoingDelCount++ go c.handleSubscriptionDelete(subs, trans) trans.WaitEvent(0) //blocked wait as timeout is handled in subs side + subs.OngoingDelCount-- xapp.Logger.Debug("XAPP-SubDelReq: Handling event %s ", idstring(nil, trans, subs)) if subs.NoRespToXapp == true { // Do no send delete responses to xapps due to submgr restart is deleting uncompleted subscriptions + xapp.Logger.Debug("XAPP-SubDelReq: subs.NoRespToXapp == true") return } @@ -709,8 +1090,9 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) { //------------------------------------------------------------------- // SUBS CREATE Handling //------------------------------------------------------------------- -func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *TransactionXapp) { +func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *TransactionXapp, e2SubscriptionDirectives *E2SubscriptionDirectives) { + var event interface{} = nil var removeSubscriptionFromDb bool = false trans := c.tracker.NewSubsTransaction(subs) subs.WaitTransactionTurn(trans) @@ -721,7 +1103,7 @@ func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *Tran subRfMsg, valid := subs.GetCachedResponse() if subRfMsg == nil && valid == true { - event := c.sendE2TSubscriptionRequest(subs, trans, parentTrans) + event = c.sendE2TSubscriptionRequest(subs, trans, parentTrans, e2SubscriptionDirectives) switch event.(type) { case *e2ap.E2APSubscriptionResponse: subRfMsg, valid = subs.SetCachedResponse(event, true) @@ -729,29 +1111,37 @@ func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *Tran case *e2ap.E2APSubscriptionFailure: removeSubscriptionFromDb = true subRfMsg, valid = subs.SetCachedResponse(event, false) - xapp.Logger.Info("SUBS-SubReq: internal delete due event(%s) %s", typeofSubsMessage(event), idstring(nil, trans, subs, parentTrans)) - c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + xapp.Logger.Debug("SUBS-SubReq: internal delete due failure event(%s) %s", typeofSubsMessage(event), idstring(nil, trans, subs, parentTrans)) case *SubmgrRestartTestEvent: // This simulates that no response has been received and after restart subscriptions are restored from db xapp.Logger.Debug("Test restart flag is active. Dropping this transaction to test restart case") - return + case *PackSubscriptionRequestErrortEvent, *SDLWriteErrortEvent: + subRfMsg, valid = subs.SetCachedResponse(event, false) default: - xapp.Logger.Info("SUBS-SubReq: internal delete due event(%s) %s", typeofSubsMessage(event), idstring(nil, trans, subs, parentTrans)) - removeSubscriptionFromDb = true - subRfMsg, valid = subs.SetCachedResponse(nil, false) - c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + // Timer expiry + if subs.PolicyUpdate == false { + xapp.Logger.Debug("SUBS-SubReq: internal delete due default event(%s) %s", typeofSubsMessage(event), idstring(nil, trans, subs, parentTrans)) + removeSubscriptionFromDb = true + subRfMsg, valid = subs.SetCachedResponse(nil, false) + c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + } } xapp.Logger.Debug("SUBS-SubReq: Handling (e2t response %s) %s", typeofSubsMessage(subRfMsg), idstring(nil, trans, subs, parentTrans)) } else { xapp.Logger.Debug("SUBS-SubReq: Handling (cached response %s) %s", typeofSubsMessage(subRfMsg), idstring(nil, trans, subs, parentTrans)) } + err := c.UpdateSubscriptionInDB(subs, removeSubscriptionFromDb) + if err != nil { + subRfMsg, valid = subs.SetCachedResponse(event, false) + c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + } + //Now RemoveFromSubscription in here to avoid race conditions (mostly concerns delete) if valid == false { - c.registry.RemoveFromSubscription(subs, parentTrans, 5*time.Second, c) + c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanup_ms, c) } - c.UpdateSubscriptionInDB(subs, removeSubscriptionFromDb) parentTrans.SendEvent(subRfMsg, 0) } @@ -780,7 +1170,7 @@ func (c *Control) handleSubscriptionDelete(subs *Subscription, parentTrans *Tran //Now RemoveFromSubscription in here to avoid race conditions (mostly concerns delete) // If parallel deletes ongoing both might pass earlier sendE2TSubscriptionDeleteRequest(...) if // RemoveFromSubscription locates in caller side (now in handleXAPPSubscriptionDeleteRequest(...)) - c.registry.RemoveFromSubscription(subs, parentTrans, 5*time.Second, c) + c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanup_ms, c) c.registry.UpdateSubscriptionToDb(subs, c) parentTrans.SendEvent(nil, 0) } @@ -788,22 +1178,38 @@ func (c *Control) handleSubscriptionDelete(subs *Subscription, parentTrans *Tran //------------------------------------------------------------------- // send to E2T Subscription Request //------------------------------------------------------------------- -func (c *Control) sendE2TSubscriptionRequest(subs *Subscription, trans *TransactionSubs, parentTrans *TransactionXapp) interface{} { +func (c *Control) sendE2TSubscriptionRequest(subs *Subscription, trans *TransactionSubs, parentTrans *TransactionXapp, e2SubscriptionDirectives *E2SubscriptionDirectives) interface{} { var err error var event interface{} = nil var timedOut bool = false + const ricRequestorId = 123 subReqMsg := subs.SubReqMsg subReqMsg.RequestId = subs.GetReqId().RequestId + subReqMsg.RequestId.Id = ricRequestorId trans.Mtype, trans.Payload, err = c.e2ap.PackSubscriptionRequest(subReqMsg) if err != nil { xapp.Logger.Error("SUBS-SubReq: %s", idstring(err, trans, subs, parentTrans)) - return event + return &PackSubscriptionRequestErrortEvent{ + ErrorInfo{ + ErrorSource: models.SubscriptionInstanceErrorSourceASN1, + ErrorCause: err.Error(), + }, + } } // Write uncompleted subscrition in db. If no response for subscrition it need to be re-processed (deleted) after restart - c.WriteSubscriptionToDb(subs) - for retries := uint64(0); retries < e2tMaxSubReqTryCount; retries++ { + err = c.WriteSubscriptionToDb(subs) + if err != nil { + return &SDLWriteErrortEvent{ + ErrorInfo{ + ErrorSource: models.SubscriptionInstanceErrorSourceDBAAS, + ErrorCause: err.Error(), + }, + } + } + + for retries := int64(0); retries < e2SubscriptionDirectives.E2MaxTryCount; retries++ { desc := fmt.Sprintf("(retry %d)", retries) if retries == 0 { c.UpdateCounter(cSubReqToE2) @@ -812,7 +1218,7 @@ func (c *Control) sendE2TSubscriptionRequest(subs *Subscription, trans *Transact } c.rmrSendToE2T(desc, subs, trans) if subs.DoNotWaitSubResp == false { - event, timedOut = trans.WaitEvent(e2tSubReqTimeout) + event, timedOut = trans.WaitEvent(e2SubscriptionDirectives.E2TimeoutTimerValue) if timedOut { c.UpdateCounter(cSubReqTimerExpiry) continue @@ -820,6 +1226,7 @@ func (c *Control) sendE2TSubscriptionRequest(subs *Subscription, trans *Transact } else { // Simulating case where subscrition request has been sent but response has not been received before restart event = &SubmgrRestartTestEvent{} + xapp.Logger.Debug("Restart event, DoNotWaitSubResp == true") } break } @@ -835,9 +1242,11 @@ func (c *Control) sendE2TSubscriptionDeleteRequest(subs *Subscription, trans *Tr var err error var event interface{} var timedOut bool + const ricRequestorId = 123 subDelReqMsg := &e2ap.E2APSubscriptionDeleteRequest{} subDelReqMsg.RequestId = subs.GetReqId().RequestId + subDelReqMsg.RequestId.Id = ricRequestorId subDelReqMsg.FunctionId = subs.SubReqMsg.FunctionId trans.Mtype, trans.Payload, err = c.e2ap.PackSubscriptionDeleteRequest(subDelReqMsg) if err != nil { @@ -868,8 +1277,9 @@ func (c *Control) sendE2TSubscriptionDeleteRequest(subs *Subscription, trans *Tr // handle from E2T Subscription Response //------------------------------------------------------------------- func (c *Control) handleE2TSubscriptionResponse(params *xapp.RMRParams) { - xapp.Logger.Info("MSG from E2T: %s", params.String()) + xapp.Logger.Debug("MSG from E2T: %s", params.String()) c.UpdateCounter(cSubRespFromE2) + subRespMsg, err := c.e2ap.UnpackSubscriptionResponse(params.Payload) if err != nil { xapp.Logger.Error("MSG-SubResp %s", idstring(err, params)) @@ -898,7 +1308,7 @@ func (c *Control) handleE2TSubscriptionResponse(params *xapp.RMRParams) { // handle from E2T Subscription Failure //------------------------------------------------------------------- func (c *Control) handleE2TSubscriptionFailure(params *xapp.RMRParams) { - xapp.Logger.Info("MSG from E2T: %s", params.String()) + xapp.Logger.Debug("MSG from E2T: %s", params.String()) c.UpdateCounter(cSubFailFromE2) subFailMsg, err := c.e2ap.UnpackSubscriptionFailure(params.Payload) if err != nil { @@ -928,7 +1338,7 @@ func (c *Control) handleE2TSubscriptionFailure(params *xapp.RMRParams) { // handle from E2T Subscription Delete Response //------------------------------------------------------------------- func (c *Control) handleE2TSubscriptionDeleteResponse(params *xapp.RMRParams) (err error) { - xapp.Logger.Info("MSG from E2T: %s", params.String()) + xapp.Logger.Debug("MSG from E2T: %s", params.String()) c.UpdateCounter(cSubDelRespFromE2) subDelRespMsg, err := c.e2ap.UnpackSubscriptionDeleteResponse(params.Payload) if err != nil { @@ -958,7 +1368,7 @@ func (c *Control) handleE2TSubscriptionDeleteResponse(params *xapp.RMRParams) (e // handle from E2T Subscription Delete Failure //------------------------------------------------------------------- func (c *Control) handleE2TSubscriptionDeleteFailure(params *xapp.RMRParams) { - xapp.Logger.Info("MSG from E2T: %s", params.String()) + xapp.Logger.Debug("MSG from E2T: %s", params.String()) c.UpdateCounter(cSubDelFailFromE2) subDelFailMsg, err := c.e2ap.UnpackSubscriptionDeleteFailure(params.Payload) if err != nil { @@ -992,14 +1402,14 @@ func typeofSubsMessage(v interface{}) string { return "NIL" } switch v.(type) { - case *e2ap.E2APSubscriptionRequest: - return "SubReq" + //case *e2ap.E2APSubscriptionRequest: + // return "SubReq" case *e2ap.E2APSubscriptionResponse: return "SubResp" case *e2ap.E2APSubscriptionFailure: return "SubFail" - case *e2ap.E2APSubscriptionDeleteRequest: - return "SubDelReq" + //case *e2ap.E2APSubscriptionDeleteRequest: + // return "SubDelReq" case *e2ap.E2APSubscriptionDeleteResponse: return "SubDelResp" case *e2ap.E2APSubscriptionDeleteFailure: @@ -1012,18 +1422,20 @@ func typeofSubsMessage(v interface{}) string { //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) WriteSubscriptionToDb(subs *Subscription) { +func (c *Control) WriteSubscriptionToDb(subs *Subscription) error { xapp.Logger.Debug("WriteSubscriptionToDb() subId = %v", subs.ReqId.InstanceId) err := c.WriteSubscriptionToSdl(subs.ReqId.InstanceId, subs) if err != nil { xapp.Logger.Error("%v", err) + return err } + return nil } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) UpdateSubscriptionInDB(subs *Subscription, removeSubscriptionFromDb bool) { +func (c *Control) UpdateSubscriptionInDB(subs *Subscription, removeSubscriptionFromDb bool) error { if removeSubscriptionFromDb == true { // Subscription was written in db already when subscription request was sent to BTS, except for merged request @@ -1031,10 +1443,12 @@ func (c *Control) UpdateSubscriptionInDB(subs *Subscription, removeSubscriptionF } else { // Update is needed for successful response and merge case here if subs.RetryFromXapp == false { - c.WriteSubscriptionToDb(subs) + err := c.WriteSubscriptionToDb(subs) + return err } } subs.RetryFromXapp = false + return nil } //------------------------------------------------------------------- @@ -1048,30 +1462,139 @@ func (c *Control) RemoveSubscriptionFromDb(subs *Subscription) { } } +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) WriteRESTSubscriptionToDb(restSubId string, restSubs *RESTSubscription) { + xapp.Logger.Debug("WriteRESTSubscriptionToDb() restSubId = %s", restSubId) + err := c.WriteRESTSubscriptionToSdl(restSubId, restSubs) + if err != nil { + xapp.Logger.Error("%v", err) + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) UpdateRESTSubscriptionInDB(restSubId string, restSubs *RESTSubscription, removeRestSubscriptionFromDb bool) { + + if removeRestSubscriptionFromDb == true { + // Subscription was written in db already when subscription request was sent to BTS, except for merged request + c.RemoveRESTSubscriptionFromDb(restSubId) + } else { + c.WriteRESTSubscriptionToDb(restSubId, restSubs) + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) RemoveRESTSubscriptionFromDb(restSubId string) { + xapp.Logger.Debug("RemoveRESTSubscriptionFromDb() restSubId = %s", restSubId) + err := c.RemoveRESTSubscriptionFromSdl(restSubId) + if err != nil { + xapp.Logger.Error("%v", err) + } +} + func (c *Control) SendSubscriptionDeleteReq(subs *Subscription) { + const ricRequestorId = 123 xapp.Logger.Debug("Sending subscription delete due to restart. subId = %v", subs.ReqId.InstanceId) // Send delete for every endpoint in the subscription - subDelReqMsg := &e2ap.E2APSubscriptionDeleteRequest{} - subDelReqMsg.RequestId = subs.GetReqId().RequestId - subDelReqMsg.FunctionId = subs.SubReqMsg.FunctionId - mType, payload, err := c.e2ap.PackSubscriptionDeleteRequest(subDelReqMsg) - if err != nil { - xapp.Logger.Error("SendSubscriptionDeleteReq() %s", idstring(err)) + if subs.PolicyUpdate == false { + subDelReqMsg := &e2ap.E2APSubscriptionDeleteRequest{} + subDelReqMsg.RequestId = subs.GetReqId().RequestId + subDelReqMsg.RequestId.Id = ricRequestorId + subDelReqMsg.FunctionId = subs.SubReqMsg.FunctionId + mType, payload, err := c.e2ap.PackSubscriptionDeleteRequest(subDelReqMsg) + if err != nil { + xapp.Logger.Error("SendSubscriptionDeleteReq() %s", idstring(err)) + return + } + for _, endPoint := range subs.EpList.Endpoints { + params := &xapp.RMRParams{} + params.Mtype = mType + params.SubId = int(subs.GetReqId().InstanceId) + params.Xid = "" + params.Meid = subs.Meid + params.Src = endPoint.String() + params.PayloadLen = len(payload.Buf) + params.Payload = payload.Buf + params.Mbuf = nil + subs.DeleteFromDb = true + c.handleXAPPSubscriptionDeleteRequest(params) + } + } +} + +func (c *Control) PrintRESTSubscriptionRequest(p *models.SubscriptionParams) { + + fmt.Println("CRESTSubscriptionRequest") + + if p == nil { return } - for _, endPoint := range subs.EpList.Endpoints { - params := &xapp.RMRParams{} - params.Mtype = mType - params.SubId = int(subs.GetReqId().InstanceId) - params.Xid = "" - params.Meid = subs.Meid - params.Src = endPoint.String() - params.PayloadLen = len(payload.Buf) - params.Payload = payload.Buf - params.Mbuf = nil - subs.DeleteFromDb = true - c.handleXAPPSubscriptionDeleteRequest(params) + + if p.SubscriptionID != "" { + fmt.Println(" SubscriptionID = ", p.SubscriptionID) + } else { + fmt.Println(" SubscriptionID = ''") + } + + fmt.Printf(" ClientEndpoint.Host = %s\n", p.ClientEndpoint.Host) + + if p.ClientEndpoint.HTTPPort != nil { + fmt.Printf(" ClientEndpoint.HTTPPort = %v\n", *p.ClientEndpoint.HTTPPort) + } else { + fmt.Println(" ClientEndpoint.HTTPPort = nil") + } + + if p.ClientEndpoint.RMRPort != nil { + fmt.Printf(" ClientEndpoint.RMRPort = %v\n", *p.ClientEndpoint.RMRPort) + } else { + fmt.Println(" ClientEndpoint.RMRPort = nil") + } + + if p.Meid != nil { + fmt.Printf(" Meid = %s\n", *p.Meid) + } else { + fmt.Println(" Meid = nil") + } + + if p.E2SubscriptionDirectives == nil { + fmt.Println(" E2SubscriptionDirectives = nil") + } else { + fmt.Println(" E2SubscriptionDirectives") + if p.E2SubscriptionDirectives.E2RetryCount == nil { + fmt.Println(" E2RetryCount == nil") + } else { + fmt.Printf(" E2RetryCount = %v\n", *p.E2SubscriptionDirectives.E2RetryCount) + } + fmt.Printf(" E2TimeoutTimerValue = %v\n", p.E2SubscriptionDirectives.E2TimeoutTimerValue) + fmt.Printf(" RMRRoutingNeeded = %v\n", p.E2SubscriptionDirectives.RMRRoutingNeeded) + } + for _, subscriptionDetail := range p.SubscriptionDetails { + if p.RANFunctionID != nil { + fmt.Printf(" RANFunctionID = %v\n", *p.RANFunctionID) + } else { + fmt.Println(" RANFunctionID = nil") + } + fmt.Printf(" SubscriptionDetail.XappEventInstanceID = %v\n", *subscriptionDetail.XappEventInstanceID) + fmt.Printf(" SubscriptionDetail.EventTriggers = %v\n", subscriptionDetail.EventTriggers) + + for _, actionToBeSetup := range subscriptionDetail.ActionToBeSetupList { + fmt.Printf(" SubscriptionDetail.ActionToBeSetup.ActionID = %v\n", *actionToBeSetup.ActionID) + fmt.Printf(" SubscriptionDetail.ActionToBeSetup.ActionType = %s\n", *actionToBeSetup.ActionType) + fmt.Printf(" SubscriptionDetail.ActionToBeSetup.ActionDefinition = %v\n", actionToBeSetup.ActionDefinition) + + if actionToBeSetup.SubsequentAction != nil { + fmt.Printf(" SubscriptionDetail.ActionToBeSetup.SubsequentAction.SubsequentActionType = %s\n", *actionToBeSetup.SubsequentAction.SubsequentActionType) + fmt.Printf(" SubscriptionDetail.ActionToBeSetup..SubsequentAction.TimeToWait = %s\n", *actionToBeSetup.SubsequentAction.TimeToWait) + } else { + fmt.Println(" SubscriptionDetail.ActionToBeSetup.SubsequentAction = nil") + } + } } }