From 0054ece5d9d4bcb28ecda2f0f36584f6a64fc869 Mon Sep 17 00:00:00 2001 From: Ashwin Sridharan Date: Tue, 8 Oct 2019 15:47:06 -0400 Subject: [PATCH] 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 --- .../subscription/subscription_delete_response.cc | 4 +- src/E2AP-c/subscription/subscription_handler.cc | 77 ++++++++++++++-------- src/E2AP-c/subscription/subscription_handler.hpp | 27 ++++---- 3 files changed, 68 insertions(+), 40 deletions(-) diff --git a/src/E2AP-c/subscription/subscription_delete_response.cc b/src/E2AP-c/subscription/subscription_delete_response.cc index e810e9e..91ede0a 100644 --- 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 --- 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 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 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 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 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 --- 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 _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 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; }; -- 2.16.6