X-Git-Url: https://gerrit.o-ran-sc.org/r/gitweb?a=blobdiff_plain;f=pkg%2Fcontrol%2Fcontrol.go;h=49b7968428661dce37f445fb8804481bf465a843;hb=9c4697fa22fae79ac923e72f417ecbebf1c1e4d6;hp=4df76768dfc1cfac66607cdc853025eb26835737;hpb=42723e2593926f1cfa144b503bf043a0fe36e657;p=ric-plt%2Fsubmgr.git diff --git a/pkg/control/control.go b/pkg/control/control.go index 4df7676..49b7968 100755 --- a/pkg/control/control.go +++ b/pkg/control/control.go @@ -22,18 +22,16 @@ package control import ( "fmt" "net/http" - "os" - "strconv" - "strings" + "sync" "time" "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" - "github.com/gorilla/mux" "github.com/segmentio/ksuid" "github.com/spf13/viper" ) @@ -70,20 +68,26 @@ 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 restDuplicateCtrl duplicateCtrl +var dbRetryForever string +var dbTryCount int type Control struct { *xapp.RMRClient - e2ap *E2ap - registry *Registry - tracker *Tracker - e2SubsDb Sdlnterface - restSubsDb Sdlnterface - CntRecvMsg uint64 - ResetTestFlag bool - Counters map[string]xapp.Counter - LoggerLevel uint32 + 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 { @@ -94,9 +98,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) @@ -114,104 +133,216 @@ 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, - e2SubsDb: CreateSdl(), - restSubsDb: CreateRESTSdl(), - Counters: xapp.Metric.RegisterCounterGroup(GetMetricsOpts(), "SUBMGR"), - LoggerLevel: 3, - } + 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/symptomdata", c.SymptomDataHandler, "GET") + xapp.Resource.InjectRoute("/ric/v1/test/{testId}", c.TestRestHandler, "POST") + xapp.Resource.InjectRoute("/ric/v1/restsubscriptions", c.GetAllRestSubscriptions, "GET") - go xapp.Subscription.Listen(c.SubscriptionHandler, c.QueryHandler, c.SubscriptionDeleteHandlerCB) + xapp.Resource.InjectRoute("/ric/v1/get_all_e2nodes", c.GetAllE2Nodes, "GET") + xapp.Resource.InjectRoute("/ric/v1/get_e2node_rest_subscriptions/{ranName}", c.GetAllE2NodeRestSubscriptions, "GET") - if readSubsFromDb == "false" { - return c - } + xapp.Resource.InjectRoute("/ric/v1/get_all_xapps", c.GetAllXapps, "GET") + xapp.Resource.InjectRoute("/ric/v1/get_xapp_rest_restsubscriptions/{xappServiceName}", c.GetAllXappRestSubscriptions, "GET") + xapp.Resource.InjectRoute("/ric/v1/get_e2subscriptions/{restId}", c.GetE2Subscriptions, "GET") - restDuplicateCtrl.Init() + xapp.Resource.InjectRoute("/ric/v1/delete_all_e2node_subscriptions/{ranName}", c.DeleteAllE2nodeSubscriptions, "DELETE") + xapp.Resource.InjectRoute("/ric/v1/delete_all_xapp_subscriptions/{xappServiceName}", c.DeleteAllXappSubscriptions, "DELETE") - // 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) + if readSubsFromDb == "true" { + // Read subscriptions from db + err := c.ReadE2Subscriptions() + if err != nil { + xapp.Logger.Error("ReadE2Subscriptions() failed %s", err.Error()) + } + err = c.ReadRESTSubscriptions() + if err != nil { + xapp.Logger.Error("ReadRESTSubscriptions() failed %s", err.Error()) + } } - restSubscriptions, err := c.ReadAllRESTSubscriptionsFromSdl() - if err != nil { - xapp.Logger.Error("%v", err) - } else { - c.registry.restSubscriptions = restSubscriptions - } + go xapp.Subscription.Listen(c.RESTSubscriptionHandler, c.RESTQueryHandler, c.RESTSubscriptionDeleteHandler) return c } func (c *Control) SymptomDataHandler(w http.ResponseWriter, r *http.Request) { - subscriptions, _ := c.registry.QueryHandler() + subscriptions, err := c.registry.QueryHandler() + if err != nil { + xapp.Logger.Error("QueryHandler() failed %s", err.Error()) + } + xapp.Resource.SendSymptomDataJson(w, r, subscriptions, "platform/subscriptions.json") } +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) RESTQueryHandler() (models.SubscriptionList, error) { + xapp.Logger.Debug("RESTQueryHandler() called") + + c.CntRecvMsg++ + + return c.registry.QueryHandler() +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +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 + go c.HandleUncompletedSubscriptions(register) + return nil + } + } + xapp.Logger.Debug("Continuing without retring") + return err +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------- +func (c *Control) ReadRESTSubscriptions() error { + + xapp.Logger.Debug("ReadRESTSubscriptions()") + 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 { + // Fix REST subscriptions ongoing status after restart + for restSubId, restSubscription := range restSubscriptions { + restSubscription.SubReqOngoing = false + restSubscription.SubDelReqOngoing = false + err := c.WriteRESTSubscriptionToSdl(restSubId, restSubscription) + if err != nil { + xapp.Logger.Error("WriteRESTSubscriptionToSdl() failed:%s", err.Error()) + } + } + 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) - - // 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.Info("waitRouteCleanup %v", waitRouteCleanup_ms) + 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.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.Info("e2tMaxSubDelReqTryCount %v", e2tMaxSubDelReqTryCount) + 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) - c.LoggerLevel = viper.GetUint32("logger.level") - if c.LoggerLevel == 0 { - c.LoggerLevel = 3 + 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) } //------------------------------------------------------------------- @@ -222,9 +353,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) + } } } } @@ -244,54 +378,52 @@ func (c *Control) Run() { //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) GetOrCreateRestSubscription(p *models.SubscriptionParams, md5sum string, xAppRmrEndpoint string) (*RESTSubscription, string, error) { +func (c *Control) GetOrCreateRestSubscription(p *models.SubscriptionParams, md5sum string, xAppRmrEndpoint string, xAppServiceName string) (*RESTSubscription, string, error) { var restSubId string var restSubscription *RESTSubscription var err error - prevRestSubsId, exists := restDuplicateCtrl.GetLastKnownRestSubsIdBasedOnMd5sum(md5sum) + 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.Info("Existing restSubId %s found by MD5sum %s for a request without subscription ID - using previous subscription", prevRestSubsId, md5sum) + xapp.Logger.Debug("Existing restSubId %s found by MD5sum %s for a request without subscription ID - using previous subscription", prevRestSubsId, md5sum) } else { - xapp.Logger.Info("Existing restSubId %s found by MD5sum %s for a request without subscription ID - Note: %s", prevRestSubsId, md5sum, err.Error()) + 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.Info("None existing restSubId %s referred by MD5sum %s for a request without subscription ID - deleting cached entry", prevRestSubsId, md5sum) - restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(md5sum) + 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, err = c.registry.CreateRESTSubscription(&restSubId, &xAppRmrEndpoint, p.Meid) - if err != nil { - xapp.Logger.Error("%s", err.Error()) - c.UpdateCounter(cRestSubFailToXapp) - return nil, "", err - } + restSubscription = c.registry.CreateRESTSubscription(&restSubId, &xAppServiceName, &xAppRmrEndpoint, p.Meid) } } else { + // Subscription contains REST subscription Id restSubId = p.SubscriptionID - xapp.Logger.Info("RestSubscription ID %s provided via REST request", restSubId) - + 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.Info("Existing restSubscription found for ID %s, new request based on md5sum", restSubId) + xapp.Logger.Debug("Existing restSubscription found for ID %s, new request based on md5sum", restSubId) } else { - xapp.Logger.Info("Existing restSubscription found for ID %s(%s), re-transmission based on md5sum match with previous request", prevRestSubsId, restSubId) + xapp.Logger.Debug("Existing restSubscription found for ID %s(%s), re-transmission based on md5sum match with previous request", prevRestSubsId, restSubId) } } @@ -301,7 +433,7 @@ func (c *Control) GetOrCreateRestSubscription(p *models.SubscriptionParams, md5s //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionResponse, error) { +func (c *Control) RESTSubscriptionHandler(params interface{}) (*models.SubscriptionResponse, int) { c.CntRecvMsg++ c.UpdateCounter(cRestSubReqFromXapp) @@ -313,17 +445,30 @@ func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionR c.PrintRESTSubscriptionRequest(p) } + 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") + err := fmt.Errorf("ClientEndpoint == nil") + xapp.Logger.Error("%v", err) c.UpdateCounter(cRestSubFailToXapp) - return nil, fmt.Errorf("") + return nil, common.SubscribeBadRequestCode } + e2SubscriptionDirectives, err := c.GetE2SubscriptionDirectives(p) + if err != nil { + xapp.Logger.Error("%s", err) + c.UpdateCounter(cRestSubFailToXapp) + return nil, common.SubscribeBadRequestCode + } _, xAppRmrEndpoint, err := ConstructEndpointAddresses(*p.ClientEndpoint) if err != nil { xapp.Logger.Error("%s", err.Error()) c.UpdateCounter(cRestSubFailToXapp) - return nil, err + return nil, common.SubscribeBadRequestCode } md5sum, err := CalculateRequestMd5sum(params) @@ -331,10 +476,10 @@ func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionR xapp.Logger.Error("Failed to generate md5sum from incoming request - %s", err.Error()) } - restSubscription, restSubId, err := c.GetOrCreateRestSubscription(p, md5sum, xAppRmrEndpoint) + restSubscription, restSubId, err := c.GetOrCreateRestSubscription(p, md5sum, xAppRmrEndpoint, p.ClientEndpoint.Host) if err != nil { - xapp.Logger.Error("Failed to get/allocate REST subscription") - return nil, err + xapp.Logger.Error("Subscription with id in REST request does not exist") + return nil, common.SubscribeNotFoundCode } subResp.SubscriptionID = &restSubId @@ -342,23 +487,61 @@ func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionR err = c.e2ap.FillSubscriptionReqMsgs(params, &subReqList, restSubscription) if err != nil { xapp.Logger.Error("%s", err.Error()) - restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(md5sum) + c.restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(md5sum) c.registry.DeleteRESTSubscription(&restSubId) c.UpdateCounter(cRestSubFailToXapp) - return nil, err + return nil, common.SubscribeBadRequestCode } - duplicate := restDuplicateCtrl.IsDuplicateToOngoingTransaction(restSubId, md5sum) + duplicate := c.restDuplicateCtrl.IsDuplicateToOngoingTransaction(restSubId, md5sum) if duplicate { - xapp.Logger.Info("Retransmission blocker direct ACK for request of restSubsId %s restSubId MD5sum %s as retransmission", restSubId, md5sum) + 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.registry.DeleteRESTSubscription(&restSubId) c.UpdateCounter(cRestSubRespToXapp) - return &subResp, nil + return &subResp, common.SubscribeCreatedCode } - go c.processSubscriptionRequests(restSubscription, &subReqList, p.ClientEndpoint, p.Meid, &restSubId, xAppRmrEndpoint, md5sum) + c.WriteRESTSubscriptionToDb(restSubId, restSubscription) + go c.processSubscriptionRequests(restSubscription, &subReqList, p.ClientEndpoint, p.Meid, &restSubId, xAppRmrEndpoint, md5sum, e2SubscriptionDirectives) c.UpdateCounter(cRestSubRespToXapp) - return &subResp, nil + 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 } //------------------------------------------------------------------- @@ -366,14 +549,16 @@ func (c *Control) SubscriptionHandler(params interface{}) (*models.SubscriptionR //------------------------------------------------------------------- func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription, subReqList *e2ap.SubscriptionRequestList, - clientEndpoint *models.SubscriptionParamsClientEndpoint, meid *string, restSubId *string, xAppRmrEndpoint string, md5sum 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("E2 SubscriptionRequest count = %v ", len(subReqList.E2APSubscriptionRequests)) var xAppEventInstanceID int64 var e2EventInstanceID int64 + errorInfo := &ErrorInfo{} - defer restDuplicateCtrl.SetMd5sumFromLastOkRequest(*restSubId, md5sum) + defer c.restDuplicateCtrl.SetMd5sumFromLastOkRequest(*restSubId, md5sum) for index := 0; index < len(subReqList.E2APSubscriptionRequests); index++ { subReqMsg := subReqList.E2APSubscriptionRequests[index] @@ -383,26 +568,44 @@ func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription if trans == nil { // Send notification to xApp that prosessing of a Subscription Request has failed. err := fmt.Errorf("Tracking failure") - c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans) + errorInfo.ErrorCause = err.Error() + c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans, errorInfo) continue } - xapp.Logger.Info("Handle SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) + xapp.Logger.Debug("Handle SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) - subRespMsg, err := c.handleSubscriptionRequest(trans, &subReqMsg, meid, *restSubId) + subRespMsg, errorInfo, err := c.handleSubscriptionRequest(trans, &subReqMsg, meid, *restSubId, e2SubscriptionDirectives) - xapp.Logger.Info("Handled SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) + xapp.Logger.Debug("Handled SubscriptionRequest index=%v, %s", index, idstring(nil, trans)) + trans.Release() if err != nil { - c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans) + if err.Error() == "TEST: restart event received" { + // This is just for UT cases. Stop here subscription processing + return + } + c.sendUnsuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, err, clientEndpoint, trans, errorInfo) } else { e2EventInstanceID = (int64)(subRespMsg.RequestId.InstanceId) restSubscription.AddMd5Sum(md5sum) - xapp.Logger.Info("SubscriptionRequest index=%v processed successfullyfor %s. endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + 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.sendSuccesfullResponseNotification(restSubId, restSubscription, xAppEventInstanceID, e2EventInstanceID, clientEndpoint, trans, errorInfo) } - trans.Release() + } +} + +//------------------------------------------------------------------- +// +//------------------------------------------------------------------ +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") } } @@ -410,63 +613,100 @@ 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 { xapp.Logger.Error("XAPP-SubReq Tracking error: %s", idstring(err, trans)) + errorInfo.ErrorCause = err.Error() err = fmt.Errorf("Tracking failure") - return nil, err + 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 { xapp.Logger.Error("XAPP-SubReq Assign error: %s", idstring(err, trans)) - return nil, err + return nil, &errorInfo, err } // // Wake subs request // - go c.handleSubscriptionCreate(subs, trans) + subs.OngoingReqCount++ + go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives, 0) 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 { + errorInfo = c.e2ap.CheckActionNotAdmittedList(xapp.RIC_SUB_RESP, themsg.ActionNotAdmittedList, c) + 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, "") + } case *e2ap.E2APSubscriptionFailure: - err = fmt.Errorf("E2 SubscriptionFailure received") - return nil, err + err = fmt.Errorf("RICSubscriptionFailure. E2NodeCause: (Cause:%v, Value %v)", themsg.Cause.Content, themsg.Cause.Value) + errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "") + case *PackSubscriptionRequestErrortEvent: + err = fmt.Errorf("E2 RICSubscriptionRequest pack failure") + errorInfo = themsg.ErrorInfo + case *SDLWriteErrortEvent: + err = fmt.Errorf("SDL write failure") + errorInfo = themsg.ErrorInfo + case *SubmgrRestartTestEvent: + err = fmt.Errorf("TEST: restart event received") + xapp.Logger.Debug("%s", err) + return nil, &errorInfo, err default: - err = fmt.Errorf("unexpected E2 subscription response received") + err = fmt.Errorf("Unexpected E2 subscription response received") + errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "") break } } else { - err = fmt.Errorf("E2 subscription response timeout") + // Timer expiry + err = fmt.Errorf("E2 RICSubscriptionResponse timeout") + errorInfo.SetInfo(err.Error(), "", models.SubscriptionInstanceTimeoutTypeE2Timeout) + if subs.PolicyUpdate == true { + return nil, &errorInfo, err + } } - xapp.Logger.Error("XAPP-SubReq E2 subscription failed %s", idstring(err, trans, subs)) - c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) - return nil, err + xapp.Logger.Error("XAPP-SubReq E2 subscription failed: %s", idstring(err, trans, subs)) + err2 := c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) + if err2 != nil { + xapp.Logger.Error("RemoveFromSubscription failed: %s", err2.Error()) + } + return nil, &errorInfo, err } //------------------------------------------------------------------- // //------------------------------------------------------------------- func (c *Control) sendUnsuccesfullResponseNotification(restSubId *string, restSubscription *RESTSubscription, xAppEventInstanceID int64, err error, - clientEndpoint *models.SubscriptionParamsClientEndpoint, trans *TransactionXapp) { + clientEndpoint *models.SubscriptionParamsClientEndpoint, trans *TransactionXapp, errorInfo *ErrorInfo) { // Send notification to xApp that prosessing of a Subscription Request has failed. e2EventInstanceID := (int64)(0) - errorCause := err.Error() + 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: &errorCause, + ErrorCause: errorInfo.ErrorCause, + ErrorSource: errorInfo.ErrorSource, + TimeoutType: errorInfo.TimeoutType, XappEventInstanceID: &xAppEventInstanceID}, }, } @@ -474,22 +714,31 @@ func (c *Control) sendUnsuccesfullResponseNotification(restSubId *string, restSu restSubscription.SetProcessed(err) c.UpdateRESTSubscriptionInDB(*restSubId, restSubscription, false) if trans != nil { - xapp.Logger.Info("Sending unsuccessful REST notification (cause %s) to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", - errorCause, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) + xapp.Logger.Debug("Sending unsuccessful REST notification: ErrorCause:%s, ErrorSource:%s, TimeoutType:%s, to Endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + errorInfo.ErrorCause, errorInfo.ErrorSource, errorInfo.TimeoutType, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) } else { - xapp.Logger.Info("Sending unsuccessful REST notification (cause %s) to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v", - errorCause, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID) + xapp.Logger.Debug("Sending unsuccessful REST notification: ErrorCause:%s, ErrorSource:%s, TimeoutType:%s, to Endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v", + errorInfo.ErrorCause, errorInfo.ErrorSource, errorInfo.TimeoutType, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID) } c.UpdateCounter(cRestSubFailNotifToXapp) - xapp.Subscription.Notify(resp, *clientEndpoint) + err = xapp.Subscription.Notify(resp, *clientEndpoint) + if err != nil { + xapp.Logger.Error("xapp.Subscription.Notify failed %s", err.Error()) + } + + // E2 is down. Delete completely processed request safely now + 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) { + clientEndpoint *models.SubscriptionParamsClientEndpoint, trans *TransactionXapp, errorInfo *ErrorInfo) { // Store successfully processed InstanceId for deletion restSubscription.AddE2InstanceId((uint32)(e2EventInstanceID)) @@ -500,81 +749,91 @@ func (c *Control) sendSuccesfullResponseNotification(restSubId *string, restSubs SubscriptionID: restSubId, SubscriptionInstances: []*models.SubscriptionInstance{ &models.SubscriptionInstance{E2EventInstanceID: &e2EventInstanceID, - ErrorCause: nil, + ErrorCause: errorInfo.ErrorCause, + ErrorSource: errorInfo.ErrorSource, XappEventInstanceID: &xAppEventInstanceID}, }, } // Mark REST subscription request processesd. restSubscription.SetProcessed(nil) c.UpdateRESTSubscriptionInDB(*restSubId, restSubscription, false) - xapp.Logger.Info("Sending successful REST notification to endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", - clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) - + xapp.Logger.Debug("Sending successful REST notification: ErrorCause:%s, ErrorSource:%s, TimeoutType:%s, to Endpoint=%v:%v, XappEventInstanceID=%v, E2EventInstanceID=%v, %s", + errorInfo.ErrorCause, errorInfo.ErrorSource, errorInfo.TimeoutType, clientEndpoint.Host, *clientEndpoint.HTTPPort, xAppEventInstanceID, e2EventInstanceID, idstring(nil, trans)) c.UpdateCounter(cRestSubNotifToXapp) - xapp.Subscription.Notify(resp, *clientEndpoint) + err := xapp.Subscription.Notify(resp, *clientEndpoint) + if err != nil { + xapp.Logger.Error("xapp.Subscription.Notify failed %s", err.Error()) + } + + // E2 is down. Delete completely processed request safely now + if c.e2IfState.IsE2ConnectionUp(&restSubscription.Meid) == false && restSubscription.SubReqOngoing == false { + c.registry.DeleteRESTSubscription(restSubId) + c.RemoveRESTSubscriptionFromDb(*restSubId) + } } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionDeleteHandlerCB(restSubId string) error { +func (c *Control) RESTSubscriptionDeleteHandler(restSubId string) int { c.CntRecvMsg++ c.UpdateCounter(cRestSubDelReqFromXapp) - xapp.Logger.Info("SubscriptionDeleteRequest from XAPP") + xapp.Logger.Debug("SubscriptionDeleteRequest from XAPP") 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.Info("Deleteting instances = %v", restSubscription.InstanceIds) + xapp.Logger.Debug("Deleteting handler: processing instances = %v", restSubscription.InstanceIds) for _, instanceId := range restSubscription.InstanceIds { - xAppEventInstanceID, err := c.SubscriptionDeleteHandler(&restSubId, &xAppRmrEndPoint, &restSubscription.Meid, instanceId) + xAppEventInstanceID, err := c.SubscriptionDeleteHandler(&restSubId, &xAppRmrEndPoint, &restSubscription.Meid, instanceId, 0) if err != nil { xapp.Logger.Error("%s", err.Error()) - //return err } - xapp.Logger.Info("Deleteting instanceId = %v", instanceId) + xapp.Logger.Debug("Deleteting instanceId = %v", instanceId) restSubscription.DeleteXappIdToE2Id(xAppEventInstanceID) restSubscription.DeleteE2InstanceId(instanceId) } - restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(restSubscription.lastReqMd5sum) + c.restDuplicateCtrl.DeleteLastKnownRestSubsIdBasedOnMd5sum(restSubscription.lastReqMd5sum) c.registry.DeleteRESTSubscription(&restSubId) c.RemoveRESTSubscriptionFromDb(restSubId) }() c.UpdateCounter(cRestSubDelRespToXapp) - - return nil + return common.UnsubscribeNoContentCode } //------------------------------------------------------------------- // //------------------------------------------------------------------- -func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string, meid *string, instanceId uint32) (int64, error) { +func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string, meid *string, instanceId uint32, waitRouteCleanupTime time.Duration) (int64, error) { var xAppEventInstanceID int64 subs, err := c.registry.GetSubscriptionFirstMatch([]uint32{instanceId}) if err != nil { - xapp.Logger.Info("Subscription Delete Handler subscription for restSubId=%v, E2EventInstanceID=%v not found %s", + xapp.Logger.Debug("Subscription Delete Handler subscription for restSubId=%v, E2EventInstanceID=%v not found %s", restSubId, instanceId, idstring(err, nil)) return xAppEventInstanceID, nil } @@ -596,58 +855,19 @@ func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string, // // Wake subs delete // - go c.handleSubscriptionDelete(subs, trans) + subs.OngoingDelCount++ + go c.handleSubscriptionDelete(subs, trans, waitRouteCleanupTime) 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, waitRouteCleanup_ms, c) - - return xAppEventInstanceID, nil -} - -//------------------------------------------------------------------- -// -//------------------------------------------------------------------- -func (c *Control) QueryHandler() (models.SubscriptionList, error) { - xapp.Logger.Info("QueryHandler() called") - - c.CntRecvMsg++ - - return c.registry.QueryHandler() -} - -func (c *Control) TestRestHandler(w http.ResponseWriter, r *http.Request) { - xapp.Logger.Info("TestRestHandler() called") - - pathParams := mux.Vars(r) - s := pathParams["testId"] - - // This can be used to delete single subscription from db - 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) - c.RemoveSubscriptionFromSdl(uint32(subId)) - return - } - } - - // This can be used to remove all subscriptions db from - if s == "emptydb" { - xapp.Logger.Info("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") - os.Exit(1) + err = c.registry.RemoveFromSubscription(subs, trans, waitRouteCleanup_ms, c) + if err != nil { + xapp.Logger.Error("XAPP-SubDelReq %s:", idstring(fmt.Errorf("RemoveFromSubscription faliled"), trans, subs)) } - xapp.Logger.Info("Unsupported rest command received %s", s) + return xAppEventInstanceID, nil } //------------------------------------------------------------------- @@ -664,7 +884,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) @@ -683,7 +903,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) @@ -725,7 +945,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 } @@ -734,9 +954,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)) @@ -755,8 +980,7 @@ func (c *Control) handleXAPPSubscriptionRequest(params *xapp.RMRParams) { return } - //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 @@ -770,8 +994,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, waitRouteCleanup_ms) 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) { @@ -781,7 +1008,10 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction if err == nil { trans.Release() c.UpdateCounter(cSubRespToXapp) - c.rmrSendToXapp("", subs, trans) + err := c.rmrSendToXapp("", subs, trans) + if err != nil { + xapp.Logger.Error("rmrSendToXapp() failed:%s", err.Error()) + } return } case *e2ap.E2APSubscriptionFailure: @@ -795,17 +1025,21 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction break } } - xapp.Logger.Info("XAPP-SubReq: failed %s", idstring(err, trans, subs)) - //c.registry.RemoveFromSubscription(subs, trans, 5*time.Second) + xapp.Logger.Debug("XAPP-SubReq: failed %s", idstring(err, trans, subs)) } //------------------------------------------------------------------- // 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)) @@ -834,13 +1068,16 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) { // // Wake subs delete // - go c.handleSubscriptionDelete(subs, trans) + subs.OngoingDelCount++ + go c.handleSubscriptionDelete(subs, trans, waitRouteCleanup_ms) 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 } @@ -852,18 +1089,19 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) { trans.Mtype, trans.Payload, err = c.e2ap.PackSubscriptionDeleteResponse(subDelRespMsg) if err == nil { c.UpdateCounter(cSubDelRespToXapp) - c.rmrSendToXapp("", subs, trans) + err := c.rmrSendToXapp("", subs, trans) + if err != nil { + xapp.Logger.Error("rmrSendToXapp() failed:%s", err.Error()) + } } - - //TODO handle subscription toward e2term insiged RemoveFromSubscription / hide handleSubscriptionDelete in it? - //c.registry.RemoveFromSubscription(subs, trans, 5*time.Second) } //------------------------------------------------------------------- // SUBS CREATE Handling //------------------------------------------------------------------- -func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *TransactionXapp) { +func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *TransactionXapp, e2SubscriptionDirectives *E2SubscriptionDirectives, waitRouteCleanupTime time.Duration) { + var event interface{} = nil var removeSubscriptionFromDb bool = false trans := c.tracker.NewSubsTransaction(subs) subs.WaitTransactionTurn(trans) @@ -874,37 +1112,55 @@ 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) subs.SubRespRcvd = true case *e2ap.E2APSubscriptionFailure: - removeSubscriptionFromDb = true subRfMsg, valid = subs.SetCachedResponse(event, false) - xapp.Logger.Info("SUBS-SubReq: internal delete due failure 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 + // This is used to simulate 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") + subRfMsg, valid = subs.SetCachedResponse(event, false) + parentTrans.SendEvent(subRfMsg, 0) return + case *PackSubscriptionRequestErrortEvent, *SDLWriteErrortEvent: + subRfMsg, valid = subs.SetCachedResponse(event, false) default: - xapp.Logger.Info("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) + // 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)) + subRfMsg, valid = subs.SetCachedResponse(nil, false) + c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + } else { + subRfMsg, valid = subs.SetCachedResponse(nil, true) + } } 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)) } + if valid == false { + removeSubscriptionFromDb = true + } + + err := c.UpdateSubscriptionInDB(subs, removeSubscriptionFromDb) + if err != nil { + valid = false + c.sendE2TSubscriptionDeleteRequest(subs, trans, parentTrans) + + } - //Now RemoveFromSubscription in here to avoid race conditions (mostly concerns delete) + // Now RemoveFromSubscription in here to avoid race conditions (mostly concerns delete) if valid == false { - c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanup_ms, c) + err = c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanupTime, c) + if err != nil { + xapp.Logger.Error("RemoveFromSubscription() failed:%s", err.Error()) + } } - c.UpdateSubscriptionInDB(subs, removeSubscriptionFromDb) parentTrans.SendEvent(subRfMsg, 0) } @@ -912,7 +1168,7 @@ func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *Tran // SUBS DELETE Handling //------------------------------------------------------------------- -func (c *Control) handleSubscriptionDelete(subs *Subscription, parentTrans *TransactionXapp) { +func (c *Control) handleSubscriptionDelete(subs *Subscription, parentTrans *TransactionXapp, waitRouteCleanupTime time.Duration) { trans := c.tracker.NewSubsTransaction(subs) subs.WaitTransactionTurn(trans) @@ -930,18 +1186,16 @@ func (c *Control) handleSubscriptionDelete(subs *Subscription, parentTrans *Tran } else { subs.mutex.Unlock() } - //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, waitRouteCleanup_ms, c) - c.registry.UpdateSubscriptionToDb(subs, c) + + // Now RemoveFromSubscription in here to avoid race conditions (mostly concerns delete) + c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanupTime, c) parentTrans.SendEvent(nil, 0) } //------------------------------------------------------------------- // 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 @@ -952,23 +1206,40 @@ func (c *Control) sendE2TSubscriptionRequest(subs *Subscription, trans *Transact 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 + xapp.Logger.Error("SUBS-SubReq ASN1 pack error: %s", idstring(err, trans, subs, parentTrans)) + 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) + err = c.WriteSubscriptionToDb(subs) + if err != nil { + return &SDLWriteErrortEvent{ + ErrorInfo{ + ErrorSource: models.SubscriptionInstanceErrorSourceDBAAS, + ErrorCause: err.Error(), + }, + } + } - for retries := uint64(0); retries < e2tMaxSubReqTryCount; retries++ { + for retries := int64(0); retries < e2SubscriptionDirectives.E2MaxTryCount; retries++ { desc := fmt.Sprintf("(retry %d)", retries) if retries == 0 { c.UpdateCounter(cSubReqToE2) } else { c.UpdateCounter(cSubReReqToE2) } - c.rmrSendToE2T(desc, subs, trans) + err := c.rmrSendToE2T(desc, subs, trans) + if err != nil { + xapp.Logger.Error("rmrSendToE2T() failed:%s", err.Error()) + } + if subs.DoNotWaitSubResp == false { - event, timedOut = trans.WaitEvent(e2tSubReqTimeout) + event, timedOut = trans.WaitEvent(e2SubscriptionDirectives.E2TimeoutTimerValue) if timedOut { c.UpdateCounter(cSubReqTimerExpiry) continue @@ -976,6 +1247,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 } @@ -1010,7 +1282,10 @@ func (c *Control) sendE2TSubscriptionDeleteRequest(subs *Subscription, trans *Tr } else { c.UpdateCounter(cSubDelReReqToE2) } - c.rmrSendToE2T(desc, subs, trans) + err := c.rmrSendToE2T(desc, subs, trans) + if err != nil { + xapp.Logger.Error("SUBS-SubDelReq: rmrSendToE2T failure: %s", idstring(err, trans, subs, parentTrans)) + } event, timedOut = trans.WaitEvent(e2tSubDelReqTime) if timedOut { c.UpdateCounter(cSubDelReqTimerExpiry) @@ -1026,7 +1301,7 @@ 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) @@ -1045,6 +1320,7 @@ func (c *Control) handleE2TSubscriptionResponse(params *xapp.RMRParams) { xapp.Logger.Error("MSG-SubResp: %s", idstring(err, params, subs)) return } + xapp.Logger.Debug("SUBS-SubResp: Sending event, trans= %v", trans) sendOk, timedOut := trans.SendEvent(subRespMsg, e2tRecvMsgTimeout) if sendOk == false { err = fmt.Errorf("Passing event to transaction failed: sendOk(%t) timedOut(%t)", sendOk, timedOut) @@ -1057,7 +1333,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 { @@ -1086,8 +1362,8 @@ 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()) +func (c *Control) handleE2TSubscriptionDeleteResponse(params *xapp.RMRParams) { + xapp.Logger.Debug("MSG from E2T: %s", params.String()) c.UpdateCounter(cSubDelRespFromE2) subDelRespMsg, err := c.e2ap.UnpackSubscriptionDeleteResponse(params.Payload) if err != nil { @@ -1117,7 +1393,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 { @@ -1171,18 +1447,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 @@ -1190,10 +1468,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 } //------------------------------------------------------------------- @@ -1244,31 +1524,38 @@ func (c *Control) RemoveRESTSubscriptionFromDb(restSubId string) { func (c *Control) SendSubscriptionDeleteReq(subs *Subscription) { + if c.UTTesting == true { + // Reqistry mutex is not locked after real restart but it can be when restart is simulated in unit tests + c.registry.mutex = new(sync.Mutex) + } + 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.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) + 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) + } } } @@ -1276,6 +1563,10 @@ func (c *Control) PrintRESTSubscriptionRequest(p *models.SubscriptionParams) { fmt.Println("CRESTSubscriptionRequest") + if p == nil { + return + } + if p.SubscriptionID != "" { fmt.Println(" SubscriptionID = ", p.SubscriptionID) } else { @@ -1302,6 +1593,18 @@ func (c *Control) PrintRESTSubscriptionRequest(p *models.SubscriptionParams) { 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)