Added debugging and fixes for incorrect messages

Fixed thread safety issue
Fixed response code in subscription delete response

Change-Id: I028a9c56fb4bc5082bd596dfc5366f38087217f6
Signed-off-by: Ashwin Sridharan <asridharan@research.att.com>

diff --git a/src/E2AP-c/subscription/subscription_delete_response.cc b/src/E2AP-c/subscription/subscription_delete_response.cc
index e810e9e..91ede0a 100644 (file)
--- a/src/E2AP-c/subscription/subscription_delete_response.cc
+++ b/src/E2AP-c/subscription/subscription_delete_response.cc
@@ -115,7 +115,7 @@ bool subscription_delete_response::encode_e2ap_subscription_delete_response(unsi
     return false;
   }
 
-  xer_fprint(stdout, &asn_DEF_E2AP_PDU, e2ap_pdu_obj);
+  //xer_fprint(stdout, &asn_DEF_E2AP_PDU, e2ap_pdu_obj);
   
   asn_enc_rval_t retval = asn_encode_to_buffer(0, ATS_ALIGNED_BASIC_PER, &asn_DEF_E2AP_PDU, e2ap_pdu_obj, buf, *size);
     
@@ -224,7 +224,7 @@ bool subscription_delete_response::set_fields(UnsuccessfulOutcome_t *unsuccess,
   
   unsigned int ie_index;
 
-  unsuccess->procedureCode = ProcedureCode_id_ricSubscription;
+  unsuccess->procedureCode = ProcedureCode_id_ricSubscriptionDelete;
   unsuccess->criticality = Criticality_reject;
   unsuccess->value.present = UnsuccessfulOutcome__value_PR_RICsubscriptionDeleteFailure;
 

diff --git a/src/E2AP-c/subscription/subscription_handler.cc b/src/E2AP-c/subscription/subscription_handler.cc
index 8b93f2a..f0ee4c6 100644 (file)
--- a/src/E2AP-c/subscription/subscription_handler.cc
+++ b/src/E2AP-c/subscription/subscription_handler.cc
@@ -214,14 +214,15 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
 
   if(retval.code != RC_OK){
     mdclog_write(MDCLOG_ERR, "%s, %d: Error decoding E2AP PDU of RMR type %d. Bytes decoded = %lu out of %d\n", __FILE__, __LINE__, message_type, retval.consumed, payload_length);
-    return;
+    ASN_STRUCT_FREE(asn_DEF_E2AP_PDU, e2ap_recv);
+    return ;
   }
   
   type = e2ap_recv->present;
   mdclog_write(MDCLOG_INFO, "Received RMR message of type = %d", type);
   
   if(type == E2AP_PDU_PR_successfulOutcome){
-
+    
     procedureCode =  e2ap_recv->choice.successfulOutcome->procedureCode;
     mdclog_write(MDCLOG_INFO, "Received E2AP PDU  successful outcome message with procedureCode = %d", procedureCode);  
 
@@ -229,23 +230,33 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
       // subscription response
       // decode the message
       sub_resp.get_fields(e2ap_recv->choice.successfulOutcome, he_response);
+
       {
        std::lock_guard<std::mutex> lock(*(_data_lock.get()));
        // get the id
        id = he_response.get_request_id();
-       if (get_request_status(id) == request_pending ){
+       // get status of id 
+       int req_status = get_request_status(id);
+       if (req_status == request_pending ){
          res = add_subscription_entry(id, he_response);
          if(res)
            set_request_status(id, request_success);
          
-         else
+         else{
            set_request_status(id, request_duplicate);
-
+           mdclog_write(MDCLOG_ERR, "Error:: %s, %d: Request %d seems to be a duplicate\n", __FILE__, __LINE__, id);
+         }
+         
          valid_response = true;
        }
+       else if (req_status > 0){
+         // we don't change status of response since it was not in pending
+         // we simply fail
+         mdclog_write(MDCLOG_ERR, "Error:: %s, %d: Request %d is not in request_pending state, is in State = %d\n", __FILE__, __LINE__, id, req_status);
+         
+       }
        else{
-         std::string error_string =  "Could not find id to match response = ";
-         mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), id);
+         mdclog_write(MDCLOG_ERR,  "%s, %d: Could not find id %d in request queue for subscription", __FILE__, __LINE__,  id);
        }         
        
       }
@@ -259,7 +270,8 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
        std::lock_guard<std::mutex> lock(*(_data_lock.get()));
        // get the id
        id = he_response.get_request_id();
-       if (get_request_status(id) == delete_request_pending ){
+       int req_status = get_request_status(id);
+       if (req_status == delete_request_pending ){
          // Remove the subscription from the table 
          res = delete_subscription_entry(id);
          if(res){
@@ -267,22 +279,26 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
            valid_response = true;
          }
          else{
+           set_request_status(id, delete_request_failed);
            std::string error_string = "Error deleting subscription entry for id = ";
            mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), id);
+           valid_response = true;
          } 
        }      
-       
+       else if (req_status > 0){
+         // we don't change status since it was not in pending
+         // we simply fail
+         mdclog_write(MDCLOG_ERR, "Error:: %s, %d: Request %d for deletion  is not in delete_pending state, is in State = %d\n", __FILE__, __LINE__, id, req_status);
+       }
        else{
-         std::string error_string = "Could not find id for deletion = ";
-         mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), id);
+         mdclog_write(MDCLOG_ERR,  "%s, %d: Could not find id  %d in request queue for deletion ", __FILE__, __LINE__,  id);
        }
 
       }
-    }  
+    }
 
     else{
-      std::string error_string = "Handler received E2AP subscription message with  Unknown procedure code =" ;
-      mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), procedureCode);
+      mdclog_write(MDCLOG_ERR,  "%s, %d: Subscription Handler Response received E2AP PDU success  response with an non-subscription response related type  %d", __FILE__, __LINE__, procedureCode);
     }
     
   }
@@ -298,15 +314,19 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
       {
        std::lock_guard<std::mutex> lock(*(_data_lock.get()));  
        id = he_response.get_request_id();
-       
-       if(get_request_status(id) == request_pending){
+       int req_status = get_request_status(id);
+       if(req_status == request_pending){
          set_request_status(id, request_failed);
          valid_response = true;
-         mdclog_write(MDCLOG_INFO, "Subscription request %d failed", id);
+         mdclog_write(MDCLOG_ERR, "Subscription request %d failed", id);
+       }
+       else if (req_status > 0){
+         // we don't changet status since it was not in pending
+         // we simply fail
+         mdclog_write(MDCLOG_ERR, "Error:: %s, %d: Request %d is not in request_pending state, is in State = %d\n", __FILE__, __LINE__, id, req_status);
        }
        else{
-         std::string error_string =  "Could not find id to match response = ";
-         mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), id);
+         mdclog_write(MDCLOG_ERR,  "%s, %d: Could not find id   %d in request queue for subscription ", __FILE__, __LINE__, id);
        }
       }
     }
@@ -318,23 +338,28 @@ void SubscriptionHandler::Response(int message_type, unsigned char *payload, int
        std::lock_guard<std::mutex> lock(*(_data_lock.get()));
        // get the id
        id = he_response.get_request_id();
-       if(get_request_status(id) == delete_request_pending){
+       int req_status = get_request_status(id);
+       if(req_status == delete_request_pending){
          set_request_status(id, delete_request_failed);
          mdclog_write(MDCLOG_INFO, "Subscription delete request %d failed", id);
          valid_response = true;
        }
+       else if (req_status > 0){
+         mdclog_write(MDCLOG_ERR, "Error:: %s, %d: Request %d for deletion  is not in delete_pending state, is in State = %d\n", __FILE__, __LINE__, id, req_status);
+       }
        else{
-         std::string error_string =  "Could not find id to match response = ";
-         mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), id);
-         return;
+         mdclog_write(MDCLOG_ERR,  "%s, %d: Could not find id  %d  in request queue for deletion ", __FILE__, __LINE__, id);
        }
        
       }
     }
-  }  
+    else{
+      mdclog_write(MDCLOG_ERR,  "%s, %d: Susbcription Handler Response received E2AP PDU failure response with a non-subscription response related type  %d", __FILE__, __LINE__,  procedureCode);
+
+    }
+  }
   else{
-    std::string error_string = "Handler received E2AP subscription message with  Unknown procedure code =" ;
-    mdclog_write(MDCLOG_ERR,  "%s, %d: %s, %d", __FILE__, __LINE__, error_string.c_str(), procedureCode);
+    mdclog_write(MDCLOG_ERR,  "%s, %d: Susbcription Handler Response received E2AP PDU with non response type  %d", __FILE__, __LINE__, type);
   }
   
   

diff --git a/src/E2AP-c/subscription/subscription_handler.hpp b/src/E2AP-c/subscription/subscription_handler.hpp
index c7fae3d..05efa9b 100644 (file)
--- a/src/E2AP-c/subscription/subscription_handler.hpp
+++ b/src/E2AP-c/subscription/subscription_handler.hpp
@@ -127,7 +127,7 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
 
   // get a new unique request id ...
   unsigned int new_req_id = get_next_id();
-  std::cout <<"Using id = " << new_req_id << std::endl;
+  mdclog_write(MDCLOG_INFO, "%s, %d:: Generated new request id %d\n", __FILE__, __LINE__, new_req_id);
   he.set_request(new_req_id, he.get_req_seq());
   
   E2AP_PDU_t *e2ap_pdu = 0;
@@ -154,7 +154,6 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
   std::unique_lock<std::mutex> _local_lock(*(_data_lock.get()));
 
 
-  
   // Send the message
   res = tx(TxCode,  buf_len, buffer);
   if (!res){
@@ -171,8 +170,7 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
   while(1){
 
 
-      
-    // wait to be woken up
+    // release lock and wait to be woken up
     _cv.get()->wait_for(_local_lock, _time_out);
     
     // we have woken and acquired data_lock 
@@ -181,18 +179,28 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
     int status = get_request_status(he.get_request_id());
     
     if (status == request_success){
+      // retreive the subscription response and clear queue
+      response = subscription_responses[he.get_request_id()];
+
+      // clear state
+      delete_request_entry(he.get_request_id());
+      
+      // release data lock
+      _local_lock.unlock();
       mdclog_write(MDCLOG_INFO, "Successfully subscribed for request %d", he.get_request_id());
+ 
       break;
     }
     
     if (status == request_pending){
+
       // woken up spuriously or timed out 
       auto end = std::chrono::system_clock::now();
       std::chrono::duration<double> f = end - start;
       
       if (_time_out_flag && f > _num_retries * _time_out){
        delete_request_entry(he.get_request_id());
-       mdclog_write(MDCLOG_ERR, "Subscription request %d timed out waiting for response ", he.get_request_id());
+       mdclog_write(MDCLOG_ERR, "%s, %d:: Subscription request %d timed out waiting for response ", __FILE__, __LINE__, he.get_request_id());
 
        // Release data lock
        _local_lock.unlock();
@@ -204,8 +212,9 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
       }
     }
 
-    // if we are hear, some spurious
+    // if we are here, some spurious
     // status obtained or request failed . we return false
+    mdclog_write(MDCLOG_ERR, "Error :: %s, %d : Spurious time out caused by invalid state of request %d -- state = %d. Deleting request entry and failing .. \n", __FILE__, __LINE__, he.get_request_id(), status);
     delete_request_entry(he.get_request_id());
     
     // release data lock
@@ -215,12 +224,6 @@ bool SubscriptionHandler::RequestSubscription(subscription_helper &he, subscript
     
   };
             
-  // retreive the subscription response and clear queue
-  response = subscription_responses[he.get_request_id()];
-  delete_request_entry(he.get_request_id());
-
-  // release data lock
-  _local_lock.unlock();
   
   return true;
 };