RIC-867: Submgr adaptations to E2APv2.0
[ric-plt/submgr.git] / pkg / control / control.go
index a3d9cdb..0c97afb 100755 (executable)
@@ -22,9 +22,7 @@ package control
 import (
        "fmt"
        "net/http"
-       "os"
-       "strconv"
-       "strings"
+       "sync"
        "time"
 
        "gerrit.o-ran-sc.org/r/ric-plt/e2ap/pkg/e2ap"
@@ -34,7 +32,6 @@ import (
        "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"
 )
@@ -150,27 +147,34 @@ func NewControl() *Control {
                e2SubsDb:          CreateSdl(),
                restSubsDb:        CreateRESTSdl(),
                Counters:          xapp.Metric.RegisterCounterGroup(GetMetricsOpts(), "SUBMGR"),
-               LoggerLevel:       4,
+               LoggerLevel:       1,
        }
 
        e2IfState.Init(c)
        c.ReadConfigParameters("")
 
        // Register REST handler for testing support
+       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")
-       xapp.Resource.InjectRoute("/ric/v1/symptomdata", c.SymptomDataHandler, "GET")
 
-       if readSubsFromDb == "false" {
-               return c
-       }
+       xapp.Resource.InjectRoute("/ric/v1/get_all_e2nodes", c.GetAllE2Nodes, "GET")
+       xapp.Resource.InjectRoute("/ric/v1/get_e2node_rest_subscriptions/{ranName}", c.GetAllE2NodeRestSubscriptions, "GET")
 
-       // Read subscriptions from db
-       c.ReadE2Subscriptions()
-       c.ReadRESTSubscriptions()
+       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")
 
-       go xapp.Subscription.Listen(c.RESTSubscriptionHandler, c.RESTQueryHandler, c.RESTSubscriptionDeleteHandler)
+       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")
 
+       if readSubsFromDb == "true" {
+               // Read subscriptions from db
+               c.ReadE2Subscriptions()
+               c.ReadRESTSubscriptions()
+       }
+
+       go xapp.Subscription.Listen(c.RESTSubscriptionHandler, c.RESTQueryHandler, c.RESTSubscriptionDeleteHandler)
        return c
 }
 
@@ -182,10 +186,12 @@ func (c *Control) SymptomDataHandler(w http.ResponseWriter, r *http.Request) {
 //-------------------------------------------------------------------
 //
 //-------------------------------------------------------------------
-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) RESTQueryHandler() (models.SubscriptionList, error) {
+       xapp.Logger.Debug("RESTQueryHandler() called")
+
+       c.CntRecvMsg++
+
+       return c.registry.QueryHandler()
 }
 
 //-------------------------------------------------------------------
@@ -204,7 +210,7 @@ func (c *Control) ReadE2Subscriptions() error {
                } else {
                        c.registry.subIds = subIds
                        c.registry.register = register
-                       c.HandleUncompletedSubscriptions(register)
+                       go c.HandleUncompletedSubscriptions(register)
                        return nil
                }
        }
@@ -216,6 +222,8 @@ func (c *Control) ReadE2Subscriptions() error {
 //
 //-------------------------------------------------------------------
 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++ {
@@ -225,6 +233,12 @@ func (c *Control) ReadRESTSubscriptions() error {
                        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
+                               c.WriteRESTSubscriptionToSdl(restSubId, restSubscription)
+                       }
                        c.registry.restSubscriptions = restSubscriptions
                        return nil
                }
@@ -241,7 +255,8 @@ func (c *Control) ReadConfigParameters(f string) {
        xapp.Logger.Debug("ReadConfigParameters")
 
        c.LoggerLevel = int(xapp.Logger.GetLevel())
-       xapp.Logger.Debug("LoggerLevel= %v", c.LoggerLevel)
+       xapp.Logger.Info("LoggerLevel = %v", c.LoggerLevel)
+       c.e2ap.SetASN1DebugPrintStatus(c.LoggerLevel)
 
        // viper.GetDuration returns nanoseconds
        e2tSubReqTimeout = viper.GetDuration("controls.e2tSubReqTimeout_ms") * 1000000
@@ -350,7 +365,7 @@ 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
@@ -377,7 +392,7 @@ func (c *Control) GetOrCreateRestSubscription(p *models.SubscriptionParams, md5s
 
                if restSubscription == nil {
                        restSubId = ksuid.New().String()
-                       restSubscription = c.registry.CreateRESTSubscription(&restSubId, &xAppRmrEndpoint, p.Meid)
+                       restSubscription = c.registry.CreateRESTSubscription(&restSubId, &xAppServiceName, &xAppRmrEndpoint, p.Meid)
                }
        } else {
                // Subscription contains REST subscription Id
@@ -442,7 +457,7 @@ func (c *Control) RESTSubscriptionHandler(params interface{}) (*models.Subscript
                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("Subscription with id in REST request does not exist")
                return nil, common.SubscribeNotFoundCode
@@ -463,6 +478,7 @@ func (c *Control) RESTSubscriptionHandler(params interface{}) (*models.Subscript
        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.registry.DeleteRESTSubscription(&restSubId)
                c.UpdateCounter(cRestSubRespToXapp)
                return &subResp, common.SubscribeCreatedCode
        }
@@ -471,6 +487,7 @@ func (c *Control) RESTSubscriptionHandler(params interface{}) (*models.Subscript
        e2SubscriptionDirectives, err := c.GetE2SubscriptionDirectives(p)
        if err != nil {
                xapp.Logger.Error("%s", err)
+               c.registry.DeleteRESTSubscription(&restSubId)
                return nil, common.SubscribeBadRequestCode
        }
        go c.processSubscriptionRequests(restSubscription, &subReqList, p.ClientEndpoint, p.Meid, &restSubId, xAppRmrEndpoint, md5sum, e2SubscriptionDirectives)
@@ -522,7 +539,7 @@ func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription
        clientEndpoint *models.SubscriptionParamsClientEndpoint, meid *string, restSubId *string, xAppRmrEndpoint string, md5sum string, e2SubscriptionDirectives *E2SubscriptionDirectives) {
 
        c.SubscriptionProcessingStartDelay()
-       xapp.Logger.Debug("Subscription Request count=%v ", len(subReqList.E2APSubscriptionRequests))
+       xapp.Logger.Debug("E2 SubscriptionRequest count = %v ", len(subReqList.E2APSubscriptionRequests))
 
        var xAppEventInstanceID int64
        var e2EventInstanceID int64
@@ -551,13 +568,17 @@ func (c *Control) processSubscriptionRequests(restSubscription *RESTSubscription
                trans.Release()
 
                if err != nil {
+                       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.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)
                }
        }
 }
@@ -601,7 +622,7 @@ func (c *Control) handleSubscriptionRequest(trans *TransactionXapp, subReqMsg *e
        // Wake subs request
        //
        subs.OngoingReqCount++
-       go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives)
+       go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives, 0)
        event, _ := trans.WaitEvent(0) //blocked wait as timeout is handled in subs side
        subs.OngoingReqCount--
 
@@ -611,31 +632,35 @@ func (c *Control) handleSubscriptionRequest(trans *TransactionXapp, subReqMsg *e
                case *e2ap.E2APSubscriptionResponse:
                        trans.Release()
                        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, "")
-                               return nil, &errorInfo, err
                        }
                case *e2ap.E2APSubscriptionFailure:
-                       err = fmt.Errorf("E2 SubscriptionFailure received")
+                       err = fmt.Errorf("RICSubscriptionFailure. E2NodeCause: (Cause:%v, Value %v)", themsg.Cause.Content, themsg.Cause.Value)
                        errorInfo.SetInfo(err.Error(), models.SubscriptionInstanceErrorSourceE2Node, "")
-                       return nil, &errorInfo, err
                case *PackSubscriptionRequestErrortEvent:
-                       err = fmt.Errorf("E2 SubscriptionRequest pack failure")
-                       return nil, &themsg.ErrorInfo, err
+                       err = fmt.Errorf("E2 RICSubscriptionRequest pack failure")
+                       errorInfo = themsg.ErrorInfo
                case *SDLWriteErrortEvent:
                        err = fmt.Errorf("SDL write failure")
-                       return nil, &themsg.ErrorInfo, err
+                       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")
                        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
@@ -673,16 +698,17 @@ func (c *Control) sendUnsuccesfullResponseNotification(restSubId *string, restSu
        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",
+               xapp.Logger.Debug("Sending unsuccessful REST notification (Error 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",
+               xapp.Logger.Debug("Sending unsuccessful REST notification (Error 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)
 
+       // 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)
@@ -693,7 +719,7 @@ func (c *Control) sendUnsuccesfullResponseNotification(restSubId *string, restSu
 //
 //-------------------------------------------------------------------
 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))
@@ -704,19 +730,25 @@ func (c *Control) sendSuccesfullResponseNotification(restSubId *string, restSubs
                SubscriptionID: restSubId,
                SubscriptionInstances: []*models.SubscriptionInstance{
                        &models.SubscriptionInstance{E2EventInstanceID: &e2EventInstanceID,
-                               ErrorCause:          "",
+                               ErrorCause:          errorInfo.ErrorCause,
+                               ErrorSource:         errorInfo.ErrorSource,
                                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))
-
+       if errorInfo.ErrorCause != " " {
+               xapp.Logger.Debug("Sending successful REST notification (Error 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 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)
 
+       // 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)
@@ -748,8 +780,8 @@ func (c *Control) RESTSubscriptionDeleteHandler(restSubId string) int {
                                return common.UnsubscribeBadRequestCode
                        } else if restSubscription.SubDelReqOngoing == true {
                                // Previous request for same restSubId still ongoing
-                               c.UpdateCounter(cRestSubDelFailToXapp)
-                               return common.UnsubscribeBadRequestCode
+                               c.UpdateCounter(cRestSubDelRespToXapp)
+                               return common.UnsubscribeNoContentCode
                        }
                }
        }
@@ -758,7 +790,7 @@ func (c *Control) RESTSubscriptionDeleteHandler(restSubId string) int {
        go func() {
                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())
@@ -779,7 +811,7 @@ func (c *Control) RESTSubscriptionDeleteHandler(restSubId string) int {
 //-------------------------------------------------------------------
 //
 //-------------------------------------------------------------------
-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})
@@ -807,7 +839,7 @@ func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string,
        // Wake subs delete
        //
        subs.OngoingDelCount++
-       go c.handleSubscriptionDelete(subs, trans)
+       go c.handleSubscriptionDelete(subs, trans, waitRouteCleanupTime)
        trans.WaitEvent(0) //blocked wait as timeout is handled in subs side
        subs.OngoingDelCount--
 
@@ -818,50 +850,6 @@ func (c *Control) SubscriptionDeleteHandler(restSubId *string, endPoint *string,
        return xAppEventInstanceID, nil
 }
 
-//-------------------------------------------------------------------
-//
-//-------------------------------------------------------------------
-func (c *Control) RESTQueryHandler() (models.SubscriptionList, error) {
-       xapp.Logger.Debug("RESTQueryHandler() called")
-
-       c.CntRecvMsg++
-
-       return c.registry.QueryHandler()
-}
-
-func (c *Control) TestRestHandler(w http.ResponseWriter, r *http.Request) {
-       xapp.Logger.Debug("RESTTestRestHandler() 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.Debug("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.Debug("RemoveAllSubscriptionsFromSdl() called")
-               c.RemoveAllSubscriptionsFromSdl()
-               c.RemoveAllRESTSubscriptionsFromSdl()
-               return
-       }
-
-       // This is meant to cause submgr's restart in testing
-       if s == "restart" {
-               xapp.Logger.Debug("os.Exit(1) called")
-               os.Exit(1)
-       }
-
-       xapp.Logger.Debug("Unsupported rest command received %s", s)
-}
-
 //-------------------------------------------------------------------
 //
 //-------------------------------------------------------------------
@@ -972,7 +960,6 @@ 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, true)
        if err != nil {
                xapp.Logger.Error("XAPP-SubReq: %s", idstring(err, trans))
@@ -989,7 +976,7 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction
 
        e2SubscriptionDirectives, _ := c.GetE2SubscriptionDirectives(nil)
        subs.OngoingReqCount++
-       go c.handleSubscriptionCreate(subs, trans, e2SubscriptionDirectives)
+       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
@@ -1016,7 +1003,6 @@ func (c *Control) wakeSubscriptionRequest(subs *Subscription, trans *Transaction
                }
        }
        xapp.Logger.Debug("XAPP-SubReq: failed %s", idstring(err, trans, subs))
-       //c.registry.RemoveFromSubscription(subs, trans, 5*time.Second)
 }
 
 //-------------------------------------------------------------------
@@ -1060,7 +1046,7 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) {
        // Wake subs delete
        //
        subs.OngoingDelCount++
-       go c.handleSubscriptionDelete(subs, trans)
+       go c.handleSubscriptionDelete(subs, trans, waitRouteCleanup_ms)
        trans.WaitEvent(0) //blocked wait as timeout is handled in subs side
        subs.OngoingDelCount--
 
@@ -1082,15 +1068,12 @@ func (c *Control) handleXAPPSubscriptionDeleteRequest(params *xapp.RMRParams) {
                c.UpdateCounter(cSubDelRespToXapp)
                c.rmrSendToXapp("", subs, trans)
        }
-
-       //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, e2SubscriptionDirectives *E2SubscriptionDirectives) {
+func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *TransactionXapp, e2SubscriptionDirectives *E2SubscriptionDirectives, waitRouteCleanupTime time.Duration) {
 
        var event interface{} = nil
        var removeSubscriptionFromDb bool = false
@@ -1109,36 +1092,43 @@ func (c *Control) handleSubscriptionCreate(subs *Subscription, parentTrans *Tran
                        subRfMsg, valid = subs.SetCachedResponse(event, true)
                        subs.SubRespRcvd = true
                case *e2ap.E2APSubscriptionFailure:
-                       removeSubscriptionFromDb = true
                        subRfMsg, valid = subs.SetCachedResponse(event, false)
                        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:
+                       // 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)
+                       } 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 {
-               subRfMsg, valid = subs.SetCachedResponse(event, false)
+               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)
+               c.registry.RemoveFromSubscription(subs, parentTrans, waitRouteCleanupTime, c)
        }
 
        parentTrans.SendEvent(subRfMsg, 0)
@@ -1148,7 +1138,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)
@@ -1166,11 +1156,9 @@ 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)
 }
 
@@ -1188,7 +1176,7 @@ 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))
+               xapp.Logger.Error("SUBS-SubReq ASN1 pack error: %s", idstring(err, trans, subs, parentTrans))
                return &PackSubscriptionRequestErrortEvent{
                        ErrorInfo{
                                ErrorSource: models.SubscriptionInstanceErrorSourceASN1,
@@ -1295,6 +1283,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)
@@ -1498,6 +1487,11 @@ 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)