From 67870af84f5364cb5b91609af1ee3f81e9439aaa Mon Sep 17 00:00:00 2001 From: Sukchan Lee Date: Mon, 22 Jan 2018 23:14:20 +0900 Subject: [PATCH] update trace log for S1AP/NAS --- src/mme/emm_build.c | 26 +++++ src/mme/emm_handler.c | 35 +++---- src/mme/emm_sm.c | 92 +++++++++--------- src/mme/esm_build.c | 29 ++++++ src/mme/esm_handler.c | 4 + src/mme/esm_sm.c | 30 +++--- src/mme/mme_context.c | 6 ++ src/mme/nas_path.c | 16 ++-- src/mme/s1ap_build.c | 156 +++++++++++++----------------- src/mme/s1ap_handler.c | 213 +++++++++++++++++++++++++++-------------- src/mme/s1ap_path.c | 30 ++++-- 11 files changed, 385 insertions(+), 252 deletions(-) diff --git a/src/mme/emm_build.c b/src/mme/emm_build.c index c86943dc8..2346de4d0 100644 --- a/src/mme/emm_build.c +++ b/src/mme/emm_build.c @@ -28,6 +28,8 @@ status_t emm_build_attach_accept( d_assert(mme_ue->enb_ue, return CORE_ERROR, "Null param"); d_assert(esmbuf, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Attach accept\n"); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; @@ -59,6 +61,9 @@ status_t emm_build_attach_accept( guti->guti.mme_gid = mme_ue->guti.mme_gid; guti->guti.mme_code = mme_ue->guti.mme_code; guti->guti.m_tmsi = mme_ue->guti.m_tmsi; + d_trace(3, " GUTI[G:%d,C:%d,M_TMSI:0x%x] IMSI:[%s]\n", + guti->guti.mme_gid, guti->guti.mme_code, guti->guti.m_tmsi, + mme_ue->imsi_bcd); attach_accept->presencemask |= NAS_ATTACH_ACCEPT_EMM_CAUSE_PRESENT; attach_accept->emm_cause = EMM_CAUSE_CS_DOMAIN_NOT_AVAILABLE; @@ -129,6 +134,8 @@ status_t emm_build_identity_request( message.emm.h.message_type = NAS_IDENTITY_REQUEST; /* Request IMSI */ + d_trace(3, "[EMM] Identity request\n"); + d_trace(3, " Identity Type 2 : IMSI\n"); identity_request->identity_type.type = NAS_IDENTITY_TYPE_2_IMSI; rv = nas_plain_encode(emmbuf, &message); @@ -198,6 +205,9 @@ status_t emm_build_security_mode_command( d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Security mode command\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_NEW_SECURITY_CONTEXT; @@ -270,6 +280,9 @@ status_t emm_build_detach_accept(pkbuf_t **emmbuf, mme_ue_t *mme_ue) NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; message.h.protocol_discriminator = NAS_PROTOCOL_DISCRIMINATOR_EMM; + d_trace(3, "[EMM] Detach accept\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + message.emm.h.protocol_discriminator = NAS_PROTOCOL_DISCRIMINATOR_EMM; message.emm.h.message_type = NAS_DETACH_ACCEPT; @@ -286,6 +299,11 @@ status_t emm_build_tau_accept(pkbuf_t **emmbuf, mme_ue_t *mme_ue) &message.emm.tracking_area_update_accept; int served_tai_index = 0; + d_assert(mme_ue, return CORE_ERROR,); + + d_trace(3, "[EMM] Tracking area update accept\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + memset(&message, 0, sizeof(message)); message.emm.h.protocol_discriminator = NAS_PROTOCOL_DISCRIMINATOR_EMM; message.emm.h.message_type = NAS_TRACKING_AREA_UPDATE_ACCEPT; @@ -363,6 +381,11 @@ status_t emm_build_tau_reject(pkbuf_t **emmbuf, nas_emm_cause_t emm_cause, nas_tracking_area_update_reject_t *tau_reject = &message.emm.tracking_area_update_reject; + d_assert(mme_ue, return CORE_ERROR,); + + d_trace(3, "[EMM] Tracking area update reject\n"); + d_trace(3, " IMSI[%s] Cause[%d]\n", mme_ue->imsi_bcd, emm_cause); + memset(&message, 0, sizeof(message)); message.emm.h.protocol_discriminator = NAS_PROTOCOL_DISCRIMINATOR_EMM; message.emm.h.message_type = NAS_TRACKING_AREA_UPDATE_REJECT; @@ -382,6 +405,9 @@ status_t emm_build_service_reject(pkbuf_t **emmbuf, nas_emm_cause_t emm_cause, d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Service reject\n"); + d_trace(3, " IMSI[%s] Cause[%d]\n", mme_ue->imsi_bcd, emm_cause); + memset(&message, 0, sizeof(message)); message.emm.h.protocol_discriminator = NAS_PROTOCOL_DISCRIMINATOR_EMM; message.emm.h.message_type = NAS_SERVICE_REJECT; diff --git a/src/mme/emm_handler.c b/src/mme/emm_handler.c index fd0882424..07e1954bf 100644 --- a/src/mme/emm_handler.c +++ b/src/mme/emm_handler.c @@ -113,7 +113,7 @@ status_t emm_handle_attach_request( imsi_bcd); mme_ue_set_imsi(mme_ue, imsi_bcd); - d_trace(3, "[NAS] Attach request : IMSI[%s] --> EMM\n", imsi_bcd); + d_trace(3, " IMSI[%s]\n", imsi_bcd); break; } @@ -128,21 +128,17 @@ status_t emm_handle_attach_request( guti.mme_code = nas_guti->mme_code; guti.m_tmsi = nas_guti->m_tmsi; - d_trace(3, "[NAS] Attach request : GUTI[G:%d,C:%d,M_TMSI:0x%x]-" - "IMSI:[%s] --> EMM\n", + d_trace(3, " GUTI[G:%d,C:%d,M_TMSI:0x%x] IMSI[%s]\n", guti.mme_gid, guti.mme_code, guti.m_tmsi, MME_UE_HAVE_IMSI(mme_ue) ? mme_ue->imsi_bcd : "Unknown"); - break; } default: { - d_warn("Not implemented(type:%d)", - eps_mobile_identity->imsi.type); - + d_warn("Not implemented[%d]", eps_mobile_identity->imsi.type); break; } } @@ -204,13 +200,13 @@ status_t emm_handle_attach_complete( NAS_EMM_INFORMATION_NETWORK_DAYLIGHT_SAVING_TIME_PRESENT; network_daylight_saving_time->length = 1; - d_trace(3, "[NAS] EMM information : UE[%s] <-- EMM\n", - mme_ue->imsi_bcd); - rv = nas_security_encode(&emmbuf, mme_ue, &message); d_assert(rv == CORE_OK && emmbuf, return CORE_ERROR, "emm build error"); d_assert(nas_send_to_downlink_nas_transport(mme_ue, emmbuf) == CORE_OK,,); + d_trace(3, "[EMM] EMM information\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + return CORE_OK; } @@ -237,11 +233,11 @@ status_t emm_handle_identity_response( mme_ue_set_imsi(mme_ue, imsi_bcd); d_assert(mme_ue->imsi_len, return CORE_ERROR, - "Can't get IMSI(len:%d\n", mme_ue->imsi_len); + "Can't get IMSI : [LEN:%d]\n", mme_ue->imsi_len); } else { - d_warn("Not supported Identity type(%d)", mobile_identity->imsi.type); + d_warn("Not supported Identity type[%d]", mobile_identity->imsi.type); } return CORE_OK; @@ -258,24 +254,24 @@ status_t emm_handle_detach_request( enb_ue = mme_ue->enb_ue; d_assert(enb_ue, return CORE_ERROR, "Null param"); - d_trace(3, "[NAS] Detach request[0x%x] : UE_IMSI[%s] --> EMM\n", - detach_request->detach_type, mme_ue->imsi_bcd); - switch (detach_request->detach_type.detach_type) { /* 0 0 1 : EPS detach */ case NAS_DETACH_TYPE_FROM_UE_EPS_DETACH: + d_trace(3, " EPS Detach\n"); break; /* 0 1 0 : IMSI detach */ case NAS_DETACH_TYPE_FROM_UE_IMSI_DETACH: + d_trace(3, " IMSI Detach\n"); break; case 6: /* 1 1 0 : reserved */ case 7: /* 1 1 1 : reserved */ - d_warn("[NAS] (Unknown) Detach request : UE_IMSI[%s] --> EMM", - mme_ue->imsi_bcd); + d_warn("Unknown Detach type[%d]", + detach_request->detach_type.detach_type); break; /* 0 1 1 : combined EPS/IMSI detach */ case NAS_DETACH_TYPE_FROM_UE_COMBINED_EPS_IMSI_DETACH: + d_trace(3, " Combined EPS/IMSI Detach\n"); default: /* all other values */ break; } @@ -427,8 +423,7 @@ status_t emm_handle_tau_request( guti.mme_code = nas_guti->mme_code; guti.m_tmsi = nas_guti->m_tmsi; - d_trace(3, "[NAS] TAU request : GUTI[G:%d,C:%d,M_TMSI:0x%x]-" - "IMSI:[%s] --> EMM\n", + d_trace(3, " GUTI[G:%d,C:%d,M_TMSI:0x%x] IMSI:[%s]\n", guti.mme_gid, guti.mme_code, guti.m_tmsi, @@ -438,7 +433,7 @@ status_t emm_handle_tau_request( } default: { - d_warn("Not implemented(type:%d)", + d_warn("Not implemented[%d]", eps_mobile_identity->imsi.type); return CORE_OK; diff --git a/src/mme/emm_sm.c b/src/mme/emm_sm.c index 8a6cdfd12..056f4c966 100644 --- a/src/mme/emm_sm.c +++ b/src/mme/emm_sm.c @@ -84,6 +84,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) if (message->emm.h.security_header_type == NAS_SECURITY_HEADER_FOR_SERVICE_REQUEST_MESSAGE) { + d_trace(3, "[EMM] Service request\n"); rv = emm_handle_service_request( mme_ue, &message->emm.service_request); if (rv != CORE_OK) @@ -106,7 +107,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) if (!SECURITY_CONTEXT_IS_VALID(mme_ue)) { - d_warn("No Security Context"); + d_warn("No Security Context : IMSI[%s]", mme_ue->imsi_bcd); rv = nas_send_service_reject(mme_ue, EMM_CAUSE_UE_IDENTITY_CANNOT_BE_DERIVED_BY_THE_NETWORK); d_assert(rv == CORE_OK, return, @@ -119,7 +120,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) S1ap_Cause_PR_nas, S1ap_CauseNas_normal_release, S1AP_UE_CTX_REL_NO_ACTION, 0); d_assert(rv == CORE_OK,, - "s1ap_send_ue_context_release_command() failed"); + "s1ap_send_ue_context_release_command() failed"); return; } @@ -133,6 +134,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) { case NAS_IDENTITY_RESPONSE: { + d_trace(3, "[EMM] Identity response\n"); rv = emm_handle_identity_response(mme_ue, &message->emm.identity_response); if (rv != CORE_OK) @@ -150,10 +152,12 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) return; } + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); break; } case NAS_ATTACH_REQUEST: { + d_trace(3, "[EMM] Attach request\n", mme_ue->imsi_bcd); rv = emm_handle_attach_request( mme_ue, &message->emm.attach_request); if (rv != CORE_OK) @@ -163,11 +167,11 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) FSM_TRAN(s, emm_state_exception); return; } - break; } case NAS_TRACKING_AREA_UPDATE_REQUEST: { + d_trace(3, "[EMM] Tracking area update request\n"); rv = emm_handle_tau_request( mme_ue, &message->emm.tracking_area_update_request); if (rv != CORE_OK) @@ -182,8 +186,8 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) } case NAS_TRACKING_AREA_UPDATE_COMPLETE: { - d_trace(3, "[NAS] Tracking area update complete : " - "UE[%s] --> EMM\n", mme_ue->imsi_bcd); + d_trace(3, "[EMM] Tracking area update complete\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); enb_ue = mme_ue->enb_ue; d_assert(enb_ue, return, "Null param"); @@ -196,8 +200,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) } case NAS_EMM_STATUS: { - d_warn("[NAS] EMM STATUS [IMSI:%s,Cause:%d] " - "in emm_state_attached", + d_warn("[EMM] EMM STATUS : IMSI[%s] Cause[%d]", mme_ue->imsi_bcd, message->emm.emm_status.emm_cause); FSM_TRAN(s, &emm_state_exception); @@ -205,6 +208,8 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) } case NAS_DETACH_REQUEST: { + d_trace(3, "[EMM] Detach request\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); emm_handle_detach_request( mme_ue, &message->emm.detach_request_from_ue); FSM_TRAN(s, &emm_state_detached); @@ -212,8 +217,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) } default: { - d_warn("Unknown message(type:%d)", - message->emm.h.message_type); + d_warn("Unknown message[%d]", message->emm.h.message_type); return; } } @@ -224,7 +228,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) if (mme_ue->max_paging_retry >= MAX_NUM_OF_PAGING) { /* Paging failed */ - d_warn("Paging to UE(%s) failed. Stop paging", + d_warn("[EMM] Paging to IMSI[%s] failed. Stop paging", mme_ue->imsi_bcd); if (mme_ue->last_paging_msg) { @@ -243,7 +247,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) } default: { - d_error("Unknown event %s", mme_event_get_name(e)); + d_error("Unknown event[%s]", mme_event_get_name(e)); return; } } @@ -263,8 +267,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) { rv = nas_send_emm_to_esm(mme_ue, &mme_ue->pdn_connectivity_request); - d_assert(rv == CORE_OK,, - "nas_send_emm_to_esm() failed"); + d_assert(rv == CORE_OK,, "nas_send_emm_to_esm() failed"); FSM_TRAN(s, &emm_state_initial_context_setup); } else @@ -288,8 +291,7 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) if (SECURITY_CONTEXT_IS_VALID(mme_ue)) { rv = nas_send_tau_accept(mme_ue); - d_assert(rv == CORE_OK,, - "nas_send_tau_accept() failed"); + d_assert(rv == CORE_OK,, "nas_send_tau_accept() failed"); FSM_TRAN(&mme_ue->sm, &emm_state_attached); } else @@ -297,23 +299,21 @@ static void emm_state_detached_attached(fsm_t *s, event_t *e) if (MME_HAVE_SGW_S11_PATH(mme_ue)) { mme_s6a_send_air(mme_ue, NULL); - FSM_TRAN(&mme_ue->sm, - &emm_state_authentication); + FSM_TRAN(&mme_ue->sm, &emm_state_authentication); } else { - d_warn("No PDN Connection"); + d_warn("No PDN Connection : UE[%s]", mme_ue->imsi_bcd); rv = nas_send_tau_reject(mme_ue, EMM_CAUSE_UE_IDENTITY_CANNOT_BE_DERIVED_BY_THE_NETWORK); - d_assert(rv == CORE_OK,, - "nas_send_tau_reject() failed"); + d_assert(rv == CORE_OK,, "nas_send_tau_reject() failed"); FSM_TRAN(s, emm_state_exception); } } break; } default: - d_assert(0,, "Invalid EPS-Type[%d]", mme_ue->nas_eps.type); + d_assert(0,, "Invalid NAS-EPS[%d]", mme_ue->nas_eps.type); break; } } @@ -356,6 +356,9 @@ void emm_state_authentication(fsm_t *s, event_t *e) &authentication_response-> authentication_response_parameter; + d_trace(3, "[EMM] Authentication response\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + if (authentication_response_parameter->length != mme_ue->xres_len || memcmp(authentication_response_parameter->res, @@ -363,9 +366,6 @@ void emm_state_authentication(fsm_t *s, event_t *e) { status_t rv; - d_warn("[NAS] Authentication failure [IMSI:%s]", - mme_ue->imsi_bcd); - rv = nas_send_authentication_reject(mme_ue); d_assert(rv == CORE_OK,, "nas send error"); FSM_TRAN(&mme_ue->sm, &emm_state_exception); @@ -385,13 +385,15 @@ void emm_state_authentication(fsm_t *s, event_t *e) &authentication_failure-> authentication_failure_parameter; + d_trace(3, "[EMM] Authentication failure\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + mme_s6a_send_air(mme_ue, authentication_failure_parameter); break; } case NAS_EMM_STATUS: { - d_warn("[NAS] EMM STATUS [IMSI:%s,Cause:%d] " - "in emm_state_authentication", + d_warn("[EMM] EMM STATUS : IMSI[%s] Cause[%d]", mme_ue->imsi_bcd, message->emm.emm_status.emm_cause); FSM_TRAN(s, &emm_state_exception); @@ -399,8 +401,7 @@ void emm_state_authentication(fsm_t *s, event_t *e) } default: { - d_warn("Unknown message(type:%d)", - message->emm.h.message_type); + d_warn("Unknown message[%d]", message->emm.h.message_type); break; } } @@ -408,7 +409,7 @@ void emm_state_authentication(fsm_t *s, event_t *e) } default: { - d_error("Unknown event %s", mme_event_get_name(e)); + d_error("Unknown event[%s]", mme_event_get_name(e)); break; } } @@ -439,8 +440,6 @@ void emm_state_security_mode(fsm_t *s, event_t *e) rv = nas_send_to_downlink_nas_transport(mme_ue, emmbuf); d_assert(rv == CORE_OK && emmbuf, break, "emm send error"); - d_trace(3, "[NAS] Security mode command : UE[%s] <-- EMM\n", - mme_ue->imsi_bcd); break; } case FSM_EXIT_SIG: @@ -456,8 +455,8 @@ void emm_state_security_mode(fsm_t *s, event_t *e) { case NAS_SECURITY_MODE_COMPLETE: { - d_trace(3, "[NAS] Security mode complete : " - "UE[%s] --> EMM\n", mme_ue->imsi_bcd); + d_trace(3, "[EMM] Security mode complete\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); /* Update Kenb */ if (SECURITY_CONTEXT_IS_VALID(mme_ue)) @@ -480,22 +479,21 @@ void emm_state_security_mode(fsm_t *s, event_t *e) FSM_TRAN(s, &emm_state_attached); } else - d_assert(0,, "Invalid EPS-Type[%d]", + d_assert(0,, "Invalid NAS_EPS[%d]", mme_ue->nas_eps.type); break; } case NAS_SECURITY_MODE_REJECT: { - d_warn("[NAS] Security mode reject [IMSI:%s,Cause:%d] " - "UE[%s] --> EMM\n", mme_ue->imsi_bcd, + d_warn("[EMM] Security mode reject : IMSI[%s] Cause[%d]", + mme_ue->imsi_bcd, message->emm.security_mode_reject.emm_cause); FSM_TRAN(s, &emm_state_exception); break; } case NAS_EMM_STATUS: { - d_warn("[NAS] EMM STATUS [IMSI:%s,Cause:%d] " - "in emm_state_security_mode", + d_warn("[EMM] EMM STATUS : IMSI[%s] Cause[%d]", mme_ue->imsi_bcd, message->emm.emm_status.emm_cause); FSM_TRAN(s, &emm_state_exception); @@ -503,8 +501,7 @@ void emm_state_security_mode(fsm_t *s, event_t *e) } default: { - d_warn("Unknown message(type:%d)", - message->emm.h.message_type); + d_warn("Unknown message[%d]", message->emm.h.message_type); break; } } @@ -512,7 +509,7 @@ void emm_state_security_mode(fsm_t *s, event_t *e) } default: { - d_error("Unknown event %s", mme_event_get_name(e)); + d_error("Unknown event[%s]", mme_event_get_name(e)); break; } } @@ -550,8 +547,8 @@ void emm_state_initial_context_setup(fsm_t *s, event_t *e) { case NAS_ATTACH_COMPLETE: { - d_trace(3, "[NAS] Attach complete : UE[%s] --> EMM\n", - mme_ue->imsi_bcd); + d_trace(3, "[EMM] Attach complete\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); rv = emm_handle_attach_complete( mme_ue, &message->emm.attach_complete); if (rv != CORE_OK) @@ -566,8 +563,7 @@ void emm_state_initial_context_setup(fsm_t *s, event_t *e) } case NAS_EMM_STATUS: { - d_warn("[NAS] EMM STATUS [IMSI:%s,Cause:%d] " - "in emm_state_initial_context_setup", + d_warn("[EMM] EMM STATUS : IMSI[%s] Cause[%d]", mme_ue->imsi_bcd, message->emm.emm_status.emm_cause); FSM_TRAN(s, &emm_state_exception); @@ -575,7 +571,7 @@ void emm_state_initial_context_setup(fsm_t *s, event_t *e) } default: { - d_warn("Unknown message(type:%d)", + d_warn("Unknown message[%d]", message->emm.h.message_type); break; } @@ -584,7 +580,7 @@ void emm_state_initial_context_setup(fsm_t *s, event_t *e) } default: { - d_error("Unknown event %s", mme_event_get_name(e)); + d_error("Unknown event[%s]", mme_event_get_name(e)); break; } } @@ -606,7 +602,7 @@ void emm_state_exception(fsm_t *s, event_t *e) } default: { - d_error("Unknown event %s", mme_event_get_name(e)); + d_error("Unknown event[%s]", mme_event_get_name(e)); break; } } diff --git a/src/mme/esm_build.c b/src/mme/esm_build.c index aac6c2a8a..e99df97e4 100644 --- a/src/mme/esm_build.c +++ b/src/mme/esm_build.c @@ -21,6 +21,10 @@ status_t esm_build_pdn_connectivity_reject( mme_ue = sess->mme_ue; d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[ESM] PDN connectivity reject\n"); + d_trace(3, " IMSI[%s] PTI[%d] Cause[%d]\n", + mme_ue->imsi_bcd, sess->pti, esm_cause); + memset(&message, 0, sizeof(message)); if (FSM_CHECK(&mme_ue->sm, emm_state_attached)) { @@ -61,6 +65,10 @@ status_t esm_build_information_request(pkbuf_t **pkbuf, mme_bearer_t *bearer) mme_ue = bearer->mme_ue; d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[ESM] ESM information request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; @@ -109,6 +117,10 @@ status_t esm_build_activate_default_bearer_context_request( d_assert(mme_bearer_next(bearer) == NULL, return CORE_ERROR, "there is dedicated bearer"); + d_trace(3, "[ESM] Activate default bearer context request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); + memset(&message, 0, sizeof(message)); if (FSM_CHECK(&mme_ue->sm, emm_state_attached)) { @@ -131,17 +143,20 @@ status_t esm_build_activate_default_bearer_context_request( access_point_name->length = strlen(pdn->apn); core_cpystrn(access_point_name->apn, pdn->apn, c_min(access_point_name->length, MAX_APN_LEN) + 1); + d_trace(3, " APN[%s]\n", pdn->apn); pdn_address->pdn_type = pdn->paa.pdn_type; if (pdn_address->pdn_type == GTP_PDN_TYPE_IPV4) { pdn_address->addr = pdn->paa.addr; pdn_address->length = NAS_PDN_ADDRESS_IPV4_LEN; + d_trace(3, " IPv4\n"); } else if (pdn_address->pdn_type == GTP_PDN_TYPE_IPV6) { memcpy(pdn_address->addr6, pdn->paa.addr6+(IPV6_LEN>>1), IPV6_LEN>>1); pdn_address->length = NAS_PDN_ADDRESS_IPV6_LEN; + d_trace(3, " IPv6\n"); } else if (pdn_address->pdn_type == GTP_PDN_TYPE_IPV4V6) { @@ -149,6 +164,7 @@ status_t esm_build_activate_default_bearer_context_request( memcpy(pdn_address->both.addr6, pdn->paa.both.addr6+(IPV6_LEN>>1), IPV6_LEN>>1); pdn_address->length = NAS_PDN_ADDRESS_IPV4V6_LEN; + d_trace(3, " IPv4v6\n"); } else d_assert(0, return CORE_ERROR, @@ -208,6 +224,10 @@ status_t esm_build_activate_dedicated_bearer_context_request( linked_bearer = mme_linked_bearer(bearer); d_assert(linked_bearer, return CORE_ERROR, "Null param"); + d_trace(3, "[ESM] Activate dedicated bearer context request\n"); + d_trace(3, " IMSI[%s] EBI[%d] Linked-EBI[%d]\n", + mme_ue->imsi_bcd, bearer->ebi, linked_bearer->ebi); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; @@ -255,6 +275,10 @@ status_t esm_build_modify_bearer_context_request( mme_ue = bearer->mme_ue; d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[ESM] Modify bearer context request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; @@ -306,6 +330,11 @@ status_t esm_build_deactivate_bearer_context_request( mme_ue = bearer->mme_ue; d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[ESM] Deactivate bearer context request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); + d_trace(3, " Cause[%d]\n", esm_cause); + memset(&message, 0, sizeof(message)); message.h.security_header_type = NAS_SECURITY_HEADER_INTEGRITY_PROTECTED_AND_CIPHERED; diff --git a/src/mme/esm_handler.c b/src/mme/esm_handler.c index 8f5ca0260..95abb7e77 100644 --- a/src/mme/esm_handler.c +++ b/src/mme/esm_handler.c @@ -42,6 +42,8 @@ status_t esm_handle_pdn_connectivity_request(mme_bearer_t *bearer, &pdn_connectivity_request->esm_information_transfer_flag; security_protected_required = esm_information_transfer_flag->security_protected_required; + d_trace(3, " EIT(ESM information transfer)[%d]\n", + security_protected_required); } if (pdn_connectivity_request->presencemask & @@ -85,6 +87,7 @@ status_t esm_handle_pdn_connectivity_request(mme_bearer_t *bearer, if (sess->pdn) { + d_trace(3, " APN[%s]\n", sess->pdn->apn); rv = mme_gtp_send_create_session_request(sess); d_assert(rv == CORE_OK, return CORE_ERROR, "gtp send failed"); } @@ -127,6 +130,7 @@ status_t esm_handle_information_response(mme_sess_t *sess, if (sess->pdn) { + d_trace(3, " APN[%s]\n", sess->pdn->apn); if (MME_HAVE_SGW_S11_PATH(mme_ue)) { rv = nas_send_attach_accept(mme_ue); diff --git a/src/mme/esm_sm.c b/src/mme/esm_sm.c index eae18d5a3..a6535c620 100644 --- a/src/mme/esm_sm.c +++ b/src/mme/esm_sm.c @@ -68,6 +68,9 @@ void esm_state_inactive(fsm_t *s, event_t *e) { case NAS_PDN_CONNECTIVITY_REQUEST: { + d_trace(3, "[ESM] PDN Connectivity request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); rv = esm_handle_pdn_connectivity_request( bearer, &message->esm.pdn_connectivity_request); if (rv != CORE_OK) @@ -79,9 +82,9 @@ void esm_state_inactive(fsm_t *s, event_t *e) } case NAS_ESM_INFORMATION_RESPONSE: { - d_trace(3, "[NAS] ESM information response : " - "UE[%s] --> ESM[PTI:%d]\n", - mme_ue->imsi_bcd, sess->pti); + d_trace(3, "[ESM] ESM information response\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); rv = esm_handle_information_response( sess, &message->esm.esm_information_response); if (rv != CORE_OK) @@ -93,10 +96,10 @@ void esm_state_inactive(fsm_t *s, event_t *e) } case NAS_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_ACCEPT: { - d_trace(3, "[NAS] Activate default EPS bearer " - "context accept : UE[%s] --> ESM[EBI:%d]\n", - mme_ue->imsi_bcd, bearer->ebi); - + d_trace(3, "[ESM] Activate default EPS bearer " + "context accept\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); if (MME_HAVE_ENB_S1U_PATH(bearer)) { rv = mme_gtp_send_modify_bearer_request(bearer, 0); @@ -109,9 +112,10 @@ void esm_state_inactive(fsm_t *s, event_t *e) } case NAS_ACTIVATE_DEDICATED_EPS_BEARER_CONTEXT_ACCEPT: { - d_trace(3, "[NAS] Activate dedicated EPS bearer " - "context accept : UE[%s] --> ESM[EBI:%d]\n", - mme_ue->imsi_bcd, bearer->ebi); + d_trace(3, "[ESM] Activate dedicated EPS bearer " + "context accept\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); if (MME_HAVE_ENB_S1U_PATH(bearer)) { @@ -178,9 +182,9 @@ void esm_state_active(fsm_t *s, event_t *e) { case NAS_PDN_CONNECTIVITY_REQUEST: { - d_trace(3, "[NAS] PDN connectivity request : " - "UE[%s] --> ESM[EBI:%d]\n", - mme_ue->imsi_bcd, bearer->ebi); + d_trace(3, "[ESM] PDN Connectivity request\n"); + d_trace(3, " IMSI[%s] PTI[%d] EBI[%d]\n", + mme_ue->imsi_bcd, sess->pti, bearer->ebi); rv = esm_handle_pdn_connectivity_request( bearer, &message->esm.pdn_connectivity_request); if (rv != CORE_OK) diff --git a/src/mme/mme_context.c b/src/mme/mme_context.c index 888f9812b..3e195616e 100644 --- a/src/mme/mme_context.c +++ b/src/mme/mme_context.c @@ -1486,10 +1486,16 @@ status_t mme_context_setup_trace_module() d_trace_level(&_emm_sm, nas); extern int _esm_sm; d_trace_level(&_esm_sm, nas); + extern int _emm_build; + d_trace_level(&_emm_build, nas); + extern int _esm_build; + d_trace_level(&_esm_build, nas); extern int _emm_handler; d_trace_level(&_emm_handler, nas); extern int _esm_handler; d_trace_level(&_esm_handler, nas); + extern int _nas_path; + d_trace_level(&_nas_path, nas); extern int _nas_decoder; d_trace_level(&_nas_decoder, nas); extern int _nas_encoder; diff --git a/src/mme/nas_path.c b/src/mme/nas_path.c index 17f3108f6..e6951cbc3 100644 --- a/src/mme/nas_path.c +++ b/src/mme/nas_path.c @@ -108,6 +108,9 @@ status_t nas_send_attach_reject(mme_ue_t *mme_ue, d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Attach reject\n"); + d_trace(3, " IMSI[%s] Cause[%d]\n", mme_ue->imsi_bcd, emm_cause); + sess = mme_sess_first(mme_ue); if (sess) { @@ -153,6 +156,9 @@ status_t nas_send_authentication_request( d_assert(mme_ue, return CORE_ERROR, "Null param"); d_assert(e_utran_vector, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Authentication request\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + rv = emm_build_authentication_request(&emmbuf, e_utran_vector); d_assert(rv == CORE_OK && emmbuf, return CORE_ERROR, "nas_build_detach_accept failed"); @@ -170,6 +176,9 @@ status_t nas_send_authentication_reject(mme_ue_t *mme_ue) d_assert(mme_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[EMM] Authentication reject\n"); + d_trace(3, " IMSI[%s]\n", mme_ue->imsi_bcd); + rv = emm_build_authentication_reject(&emmbuf); d_assert(rv == CORE_OK && emmbuf, return CORE_ERROR, "nas_build_detach_accept failed"); @@ -295,9 +304,6 @@ status_t nas_send_activate_dedicated_bearer_context_request( rv = esm_build_activate_dedicated_bearer_context_request(&esmbuf, bearer); d_assert(rv == CORE_OK && esmbuf, return CORE_ERROR, "esm build error"); - d_trace(3, "[NAS] Activate dedicated bearer context request : " - "EMM <-- ESM\n"); - rv = s1ap_build_e_rab_setup_request(&s1apbuf, bearer, esmbuf); d_assert(rv == CORE_OK && s1apbuf, pkbuf_free(esmbuf); return CORE_ERROR, "s1ap build error"); @@ -323,8 +329,6 @@ status_t nas_send_modify_bearer_context_request( &esmbuf, bearer, qos_presence, tft_presence); d_assert(rv == CORE_OK && esmbuf, return CORE_ERROR, "esm build error"); - d_trace(3, "[NAS] Modify bearer context request : EMM <-- ESM\n"); - if (qos_presence == 1) { rv = s1ap_build_e_rab_modify_request(&s1apbuf, bearer, esmbuf); @@ -357,8 +361,6 @@ status_t nas_send_deactivate_bearer_context_request(mme_bearer_t *bearer) &esmbuf, bearer, ESM_CAUSE_REGULAR_DEACTIVATION); d_assert(rv == CORE_OK && esmbuf, return CORE_ERROR, "esm build error"); - d_trace(3, "[NAS] Deactivate bearer context request : EMM <-- ESM\n"); - rv = s1ap_build_e_rab_release_command(&s1apbuf, bearer, esmbuf, S1ap_Cause_PR_nas, S1ap_CauseNas_normal_release); d_assert(rv == CORE_OK && s1apbuf, diff --git a/src/mme/s1ap_build.c b/src/mme/s1ap_build.c index 3cd673e0d..de5593d40 100644 --- a/src/mme/s1ap_build.c +++ b/src/mme/s1ap_build.c @@ -39,6 +39,9 @@ status_t s1ap_build_setup_rsp(pkbuf_t **pkbuf) s1ap_buffer_to_OCTET_STRING( &served_gummei->plmn_id[j], PLMN_ID_LEN, plmnIdentity); ASN_SEQUENCE_ADD(&servedGUMMEI->servedPLMNs, plmnIdentity); + d_trace(3, " PLMN_ID[MCC:%d MNC:%d]\n", + plmn_id_mcc(&served_gummei->plmn_id[j]), + plmn_id_mnc(&served_gummei->plmn_id[j])); } for (j = 0; j < served_gummei->num_of_mme_gid; j++) @@ -48,6 +51,7 @@ status_t s1ap_build_setup_rsp(pkbuf_t **pkbuf) s1ap_uint16_to_OCTET_STRING( served_gummei->mme_gid[j], mmeGroupId); ASN_SEQUENCE_ADD(&servedGUMMEI->servedGroupIDs, mmeGroupId); + d_trace(3, " MME Group[%d]\n", served_gummei->mme_gid[j]); } for (j = 0; j < served_gummei->num_of_mme_code; j++) @@ -57,6 +61,7 @@ status_t s1ap_build_setup_rsp(pkbuf_t **pkbuf) s1ap_uint8_to_OCTET_STRING( served_gummei->mme_code[j], mmeCode); ASN_SEQUENCE_ADD(&servedGUMMEI->servedMMECs, mmeCode); + d_trace(3, " MME Code[%d]\n", served_gummei->mme_code[j]); } ASN_SEQUENCE_ADD(&ies->servedGUMMEIs, servedGUMMEI); } @@ -111,8 +116,6 @@ status_t s1ap_build_setup_failure( status_t s1ap_build_downlink_nas_transport( pkbuf_t **s1apbuf, enb_ue_t *enb_ue, pkbuf_t *emmbuf) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_DownlinkNASTransport_IEs_t *ies = @@ -123,6 +126,10 @@ status_t s1ap_build_downlink_nas_transport( d_assert(enb_ue, return CORE_ERROR, "Null param"); memset(&message, 0, sizeof(s1ap_message_t)); + + d_trace(3, "[MME] Downlink NAS transport\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; ies->eNB_UE_S1AP_ID = enb_ue->enb_ue_s1ap_id; @@ -140,11 +147,6 @@ status_t s1ap_build_downlink_nas_transport( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); pkbuf_free(emmbuf); - d_trace(3, "[S1AP] downlinkNASTransport : " - "UE[eNB-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - return CORE_OK; } @@ -152,7 +154,6 @@ status_t s1ap_build_initial_context_setup_request( pkbuf_t **s1apbuf, mme_ue_t *mme_ue, pkbuf_t *emmbuf) { status_t rv; - char buf[CORE_ADDRSTRLEN]; int encoded; s1ap_message_t message; @@ -172,6 +173,10 @@ status_t s1ap_build_initial_context_setup_request( subscription_data = &mme_ue->subscription_data; d_assert(subscription_data, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] Initial context setup request\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; @@ -195,6 +200,8 @@ status_t s1ap_build_initial_context_setup_request( e_rab->e_RAB_ID = bearer->ebi; e_rab->e_RABlevelQoSParameters.qCI = bearer->qos.qci; + d_trace(3, " EBI[%d] QCI[%d]\n", bearer->ebi, bearer->qos.qci); + e_rab->e_RABlevelQoSParameters.allocationRetentionPriority. priorityLevel = bearer->qos.arp.priority_level; e_rab->e_RABlevelQoSParameters.allocationRetentionPriority. @@ -297,11 +304,6 @@ status_t s1ap_build_initial_context_setup_request( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Initial Context Setup Request : " - "UE[eNB-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - if (emmbuf && emmbuf->len) { pkbuf_free(emmbuf); @@ -313,8 +315,6 @@ status_t s1ap_build_initial_context_setup_request( status_t s1ap_build_e_rab_setup_request( pkbuf_t **s1apbuf, mme_bearer_t *bearer, pkbuf_t *esmbuf) { - char buf[CORE_ADDRSTRLEN]; - status_t rv; int encoded; s1ap_message_t message; @@ -333,6 +333,10 @@ status_t s1ap_build_e_rab_setup_request( enb_ue = mme_ue->enb_ue; d_assert(enb_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] E-RAB setup request\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; @@ -343,6 +347,8 @@ status_t s1ap_build_e_rab_setup_request( e_rab->e_RAB_ID = bearer->ebi; e_rab->e_RABlevelQoSParameters.qCI = bearer->qos.qci; + d_trace(3, " EBI[%d] QCI[%d]\n", bearer->ebi, bearer->qos.qci); + e_rab->e_RABlevelQoSParameters.allocationRetentionPriority. priorityLevel = bearer->qos.arp.priority_level; e_rab->e_RABlevelQoSParameters.allocationRetentionPriority. @@ -395,11 +401,6 @@ status_t s1ap_build_e_rab_setup_request( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] E-RAB Setup Request : " - "UE[eNB-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - pkbuf_free(esmbuf); return CORE_OK; @@ -408,8 +409,6 @@ status_t s1ap_build_e_rab_setup_request( status_t s1ap_build_e_rab_modify_request( pkbuf_t **s1apbuf, mme_bearer_t *bearer, pkbuf_t *esmbuf) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_E_RABModifyRequestIEs_t *ies = &message.s1ap_E_RABModifyRequestIEs; @@ -427,6 +426,10 @@ status_t s1ap_build_e_rab_modify_request( enb_ue = mme_ue->enb_ue; d_assert(enb_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] E-RAB modify request\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; @@ -437,6 +440,8 @@ status_t s1ap_build_e_rab_modify_request( e_rab->e_RAB_ID = bearer->ebi; e_rab->e_RABLevelQoSParameters.qCI = bearer->qos.qci; + d_trace(3, " EBI[%d] QCI[%d]\n", bearer->ebi, bearer->qos.qci); + e_rab->e_RABLevelQoSParameters.allocationRetentionPriority. priorityLevel = bearer->qos.arp.priority_level; e_rab->e_RABLevelQoSParameters.allocationRetentionPriority. @@ -484,11 +489,6 @@ status_t s1ap_build_e_rab_modify_request( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] E-RAB Modify Request : " - "UE[eNB-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - pkbuf_free(esmbuf); return CORE_OK; @@ -498,8 +498,6 @@ status_t s1ap_build_e_rab_release_command(pkbuf_t **s1apbuf, mme_bearer_t *bearer, pkbuf_t *esmbuf, S1ap_Cause_PR group, long cause) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_E_RABReleaseCommandIEs_t *ies = &message.s1ap_E_RABReleaseCommandIEs; @@ -519,6 +517,10 @@ status_t s1ap_build_e_rab_release_command(pkbuf_t **s1apbuf, subscription_data = &mme_ue->subscription_data; d_assert(subscription_data, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] E-RAB release request\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; @@ -538,6 +540,8 @@ status_t s1ap_build_e_rab_release_command(pkbuf_t **s1apbuf, e_rab->cause.present = group; e_rab->cause.choice.radioNetwork = cause; + d_trace(3, " EBI[%d] Gruop[%d] Cause[%d]\n", bearer->ebi, group, cause); + ies->presenceMask |= S1AP_E_RABRELEASECOMMANDIES_NAS_PDU_PRESENT; nasPdu = &ies->nas_pdu; nasPdu->size = esmbuf->len; @@ -554,11 +558,6 @@ status_t s1ap_build_e_rab_release_command(pkbuf_t **s1apbuf, d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] E-RAB Release Command : " - "UE[eNB-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - pkbuf_free(esmbuf); return CORE_OK; @@ -567,8 +566,6 @@ status_t s1ap_build_e_rab_release_command(pkbuf_t **s1apbuf, status_t s1ap_build_ue_context_release_command( pkbuf_t **s1apbuf, enb_ue_t *enb_ue, S1ap_Cause_PR group, long cause) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_UEContextReleaseCommand_IEs_t *ies = @@ -610,12 +607,6 @@ status_t s1ap_build_ue_context_release_command( d_assert(s1apbuf && encoded >= 0, return CORE_ERROR,); - d_trace(3, "[S1AP] UE Context Release Command[%d:%d] : " - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - ies->cause.present, ies->cause.choice.radioNetwork, - enb_ue->mme_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - return CORE_OK; } @@ -633,6 +624,8 @@ status_t s1ap_build_paging(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) memset(&message, 0, sizeof(s1ap_message_t)); + d_trace(3, "[MME] Paging\n"); + /* Set UE Identity Index value : IMSI mod 4096 */ ies->ueIdentityIndexValue.size = 2; ies->ueIdentityIndexValue.buf = @@ -658,6 +651,9 @@ status_t s1ap_build_paging(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) s1ap_uint32_to_OCTET_STRING(mme_ue->guti.m_tmsi, &ies->uePagingID.choice.s_TMSI.m_TMSI); + d_trace(3, " MME_CODE[%d] M_TMSI[0x%x]\n", + mme_ue->guti.mme_code, mme_ue->guti.m_tmsi); + /* FIXME : fixed to ps */ ies->cnDomain = S1ap_CNDomain_ps; @@ -677,15 +673,11 @@ status_t s1ap_build_paging(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) d_assert(s1apbuf && encoded >= 0, return CORE_ERROR,); - d_trace(3, "[S1AP] Paging to UE[m_tmsi:0x%x]\n", mme_ue->guti.m_tmsi); - return CORE_OK; } status_t s1ap_build_path_switch_ack(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_PathSwitchRequestAcknowledgeIEs_t *ies = @@ -696,6 +688,10 @@ status_t s1ap_build_path_switch_ack(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) enb_ue = mme_ue->enb_ue; d_assert(enb_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] Path switch acknowledge\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = enb_ue->mme_ue_s1ap_id; @@ -718,11 +714,6 @@ status_t s1ap_build_path_switch_ack(pkbuf_t **s1apbuf, mme_ue_t *mme_ue) d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Path Switch Ack : " - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - enb_ue->mme_ue_s1ap_id, - CORE_ADDR(enb_ue->enb->addr, buf), enb_ue->enb->enb_id); - return CORE_OK; } @@ -737,6 +728,11 @@ status_t s1ap_build_path_switch_failure(pkbuf_t **s1apbuf, memset(&message, 0, sizeof(s1ap_message_t)); + d_trace(3, "[MME] Path switch failure\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue_s1ap_id, mme_ue_s1ap_id); + d_trace(3, " Group[%d] Cause[%d]\n", group, cause); + ies->mme_ue_s1ap_id = mme_ue_s1ap_id; ies->eNB_UE_S1AP_ID = enb_ue_s1ap_id; ies->cause.present = group; @@ -750,17 +746,12 @@ status_t s1ap_build_path_switch_failure(pkbuf_t **s1apbuf, d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] PathSwitchFailure : " - "UE[eNB-UE-S1AP-ID(%d), mME-UE-S1AP-ID(%d)]", - enb_ue_s1ap_id, mme_ue_s1ap_id); - return CORE_OK; } status_t s1ap_build_handover_command(pkbuf_t **s1apbuf, enb_ue_t *source_ue) { status_t rv; - char buf[CORE_ADDRSTRLEN]; int encoded; s1ap_message_t message; @@ -774,12 +765,17 @@ status_t s1ap_build_handover_command(pkbuf_t **s1apbuf, enb_ue_t *source_ue) d_assert(source_ue, return CORE_ERROR, "Null param"); mme_ue = source_ue->mme_ue; + d_trace(3, "[MME] Handover command\n"); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = source_ue->mme_ue_s1ap_id; ies->eNB_UE_S1AP_ID = source_ue->enb_ue_s1ap_id; ies->handoverType = source_ue->handover_type; + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + sess = mme_sess_first(mme_ue); while(sess) { @@ -852,19 +848,12 @@ status_t s1ap_build_handover_command(pkbuf_t **s1apbuf, enb_ue_t *source_ue) d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Handover Command : ", - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - source_ue->mme_ue_s1ap_id, - CORE_ADDR(source_ue->enb->addr, buf), source_ue->enb->enb_id); - return CORE_OK; } status_t s1ap_build_handover_preparation_failure( pkbuf_t **s1apbuf, enb_ue_t *source_ue, S1ap_Cause_t *cause) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_HandoverPreparationFailureIEs_t *ies = @@ -876,11 +865,18 @@ status_t s1ap_build_handover_preparation_failure( memset(&message, 0, sizeof(s1ap_message_t)); + d_trace(3, "[MME] Handover preparation failure\n"); + ies->mme_ue_s1ap_id = source_ue->mme_ue_s1ap_id; ies->eNB_UE_S1AP_ID = source_ue->enb_ue_s1ap_id; ies->cause.present = cause->present; ies->cause.choice.radioNetwork = cause->choice.radioNetwork; + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Group[%d] Cause[%d]\n", + cause->present, cause->choice.radioNetwork); + message.procedureCode = S1ap_ProcedureCode_id_HandoverPreparation; message.direction = S1AP_PDU_PR_unsuccessfulOutcome; @@ -889,11 +885,6 @@ status_t s1ap_build_handover_preparation_failure( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Handover Preparation Failure : ", - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - source_ue->mme_ue_s1ap_id, - CORE_ADDR(source_ue->enb->addr, buf), source_ue->enb->enb_id); - return CORE_OK; } @@ -902,7 +893,6 @@ status_t s1ap_build_handover_request( S1ap_HandoverRequiredIEs_t *required) { status_t rv; - char buf[CORE_ADDRSTRLEN]; int encoded; s1ap_message_t message; @@ -1030,18 +1020,11 @@ status_t s1ap_build_handover_request( d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Handover Request : ", - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - target_ue->mme_ue_s1ap_id, - CORE_ADDR(target_ue->enb->addr, buf), target_ue->enb->enb_id); - return CORE_OK; } status_t s1ap_build_handover_cancel_ack(pkbuf_t **s1apbuf, enb_ue_t *source_ue) { - char buf[CORE_ADDRSTRLEN]; - int encoded; s1ap_message_t message; S1ap_HandoverCancelAcknowledgeIEs_t *ies = @@ -1049,11 +1032,16 @@ status_t s1ap_build_handover_cancel_ack(pkbuf_t **s1apbuf, enb_ue_t *source_ue) d_assert(source_ue, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] Handover cancel acknowledge\n"); + memset(&message, 0, sizeof(s1ap_message_t)); ies->mme_ue_s1ap_id = source_ue->mme_ue_s1ap_id; ies->eNB_UE_S1AP_ID = source_ue->enb_ue_s1ap_id; + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + message.procedureCode = S1ap_ProcedureCode_id_HandoverCancel; message.direction = S1AP_PDU_PR_successfulOutcome; @@ -1062,18 +1050,12 @@ status_t s1ap_build_handover_cancel_ack(pkbuf_t **s1apbuf, enb_ue_t *source_ue) d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] Handover Cancel Ack : ", - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - source_ue->mme_ue_s1ap_id, - CORE_ADDR(source_ue->enb->addr, buf), source_ue->enb->enb_id); - return CORE_OK; } status_t s1ap_build_mme_status_transfer(pkbuf_t **s1apbuf, enb_ue_t *target_ue, S1ap_ENBStatusTransferIEs_t *enb_ies) { - char buf[CORE_ADDRSTRLEN]; int i; int encoded; @@ -1082,12 +1064,17 @@ status_t s1ap_build_mme_status_transfer(pkbuf_t **s1apbuf, d_assert(target_ue, return CORE_ERROR, "Null param"); d_assert(enb_ies, return CORE_ERROR, "Null param"); + + d_trace(3, "[MME] MME status transfer\n"); memset(&message, 0, sizeof(s1ap_message_t)); mme_ies->mme_ue_s1ap_id = target_ue->mme_ue_s1ap_id; mme_ies->eNB_UE_S1AP_ID = target_ue->enb_ue_s1ap_id; + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + for (i = 0; i < enb_ies->eNB_StatusTransfer_TransparentContainer. bearers_SubjectToStatusTransferList.list.count; i++) { @@ -1114,10 +1101,5 @@ status_t s1ap_build_mme_status_transfer(pkbuf_t **s1apbuf, d_assert(s1apbuf && encoded >= 0,return CORE_ERROR,); - d_trace(3, "[S1AP] MME Status Transfer : ", - "UE[mME-UE-S1AP-ID(%d)] <-- eNB[%s:%d]\n", - target_ue->mme_ue_s1ap_id, - CORE_ADDR(target_ue->enb->addr, buf), target_ue->enb->enb_id); - return CORE_OK; } diff --git a/src/mme/s1ap_handler.c b/src/mme/s1ap_handler.c index 3633812cb..c299506f1 100644 --- a/src/mme/s1ap_handler.c +++ b/src/mme/s1ap_handler.c @@ -32,7 +32,10 @@ void s1ap_handle_s1_setup_request(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_S1SetupRequestIEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] S1-Setup request\n"); + s1ap_ENB_ID_to_uint32(&ies->global_ENB_ID.eNB_ID, &enb_id); + d_trace(3, " IP[%s] ENB_ID[%d]\n", CORE_ADDR(enb->addr, buf), enb_id); /* Parse Supported TA */ enb->num_of_supported_ta_list = 0; @@ -55,10 +58,17 @@ void s1ap_handle_s1_setup_request(mme_enb_t *enb, s1ap_message_t *message) enb->supported_ta_list[enb->num_of_supported_ta_list].tac = ntohs(enb->supported_ta_list [enb->num_of_supported_ta_list].tac); + d_trace(3, " TAC[%d]\n", + enb->supported_ta_list[enb->num_of_supported_ta_list].tac); memcpy(&enb->supported_ta_list [enb->num_of_supported_ta_list].plmn_id, pLMNidentity->buf, sizeof(plmn_id_t)); + d_trace(3, " PLMN_ID[MCC:%d MNC:%d]\n", + plmn_id_mcc(&enb->supported_ta_list + [enb->num_of_supported_ta_list].plmn_id), + plmn_id_mnc(&enb->supported_ta_list + [enb->num_of_supported_ta_list].plmn_id)); enb->num_of_supported_ta_list++; } } @@ -69,8 +79,8 @@ void s1ap_handle_s1_setup_request(mme_enb_t *enb, s1ap_message_t *message) } d_assert(enb->sock, return,); - d_trace(3, "[S1AP] S1SetupRequest : eNB[%s:%d] --> MME\n", - CORE_ADDR(enb->addr, buf), enb_id); + + d_trace(3, "[MME] S1-Setup response\n"); d_assert(mme_enb_set_enb_id(enb, enb_id) == CORE_OK, return, "hash add error"); @@ -80,8 +90,6 @@ void s1ap_handle_s1_setup_request(mme_enb_t *enb, s1ap_message_t *message) d_assert(s1ap_send_to_enb(enb, s1apbuf) == CORE_OK, , "send error"); d_assert(enb->sock, return,); - d_trace(3, "[S1AP] S1SetupResponse: eNB[%s:%d] <-- MME\n", - CORE_ADDR(enb->addr, buf), enb_id); } void s1ap_handle_initial_ue_message(mme_enb_t *enb, s1ap_message_t *message) @@ -101,6 +109,10 @@ void s1ap_handle_initial_ue_message(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_InitialUEMessage_IEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] Initial UE Message\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); if (!enb_ue) { @@ -137,6 +149,8 @@ void s1ap_handle_initial_ue_message(mme_enb_t *enb, s1ap_message_t *message) } else { + d_trace(3, " S_TMSI[G:%d,C:%d,M_TMSI:0x%x]\n", + guti.mme_gid, guti.mme_code, guti.m_tmsi); mme_ue_associate_enb_ue(mme_ue, enb_ue); } } @@ -167,10 +181,8 @@ void s1ap_handle_initial_ue_message(mme_enb_t *enb, s1ap_message_t *message) enb_ue->nas.e_cgi.cell_id = (ntohl(enb_ue->nas.e_cgi.cell_id) >> 4); d_assert(enb->sock, enb_ue_remove(enb_ue); return,); - d_trace(3, "[S1AP] InitialUEMessage : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] TAC[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->nas.tai.tac); d_assert(s1ap_send_to_nas(enb_ue, &ies->nas_pdu) == CORE_OK,, "s1ap_send_to_nas failed"); @@ -187,13 +199,15 @@ void s1ap_handle_uplink_nas_transport( ies = &message->s1ap_UplinkNASTransport_IEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] Uplink NAS transport\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(enb_ue, return, "No UE Context[%d]", ies->eNB_UE_S1AP_ID); - d_trace(3, "[S1AP] uplinkNASTransport : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); d_assert(s1ap_send_to_nas(enb_ue, &ies->nas_pdu) == CORE_OK,, "s1ap_send_to_nas failed"); @@ -210,9 +224,16 @@ void s1ap_handle_ue_capability_info_indication( ies = &message->s1ap_UECapabilityInfoIndicationIEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] UE capability info indication\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(enb_ue, return, "No UE Context[%d]", ies->eNB_UE_S1AP_ID); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + if (enb_ue->mme_ue) { S1ap_UERadioCapability_t *ue_radio_capa = NULL; @@ -242,11 +263,6 @@ void s1ap_handle_ue_capability_info_indication( radio_capa->size); memcpy(radio_capa->buf, ue_radio_capa->buf, radio_capa->size); } - - d_trace(3, "[S1AP] UE Capability Info Indication : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); } void s1ap_handle_initial_context_setup_response( @@ -263,15 +279,17 @@ void s1ap_handle_initial_context_setup_response( ies = &message->s1ap_InitialContextSetupResponseIEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] Initial context setup response\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(enb_ue, return, "No UE Context[%d]", ies->eNB_UE_S1AP_ID); mme_ue = enb_ue->mme_ue; d_assert(mme_ue, return,); - d_trace(3, "[S1AP] Initial Context Setup Response : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); for (i = 0; i < ies->e_RABSetupListCtxtSURes. s1ap_E_RABSetupItemCtxtSURes.count; i++) @@ -295,6 +313,8 @@ void s1ap_handle_initial_context_setup_response( &e_rab->transportLayerAddress, &bearer->enb_s1u_ip); d_assert(rv == CORE_OK, return,); + d_trace(3, " EBI[%d]\n", bearer->ebi); + if (FSM_CHECK(&bearer->sm, esm_state_active)) { int uli_presence = 0; @@ -326,10 +346,9 @@ void s1ap_handle_initial_context_setup_failure( mme_ue = enb_ue->mme_ue; d_assert(mme_ue, return,); - d_warn("[S1AP] Initial Context Setup Failure(%ld:%ld) : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - ies->cause.present, ies->cause.choice.radioNetwork, - enb_ue->enb_ue_s1ap_id, + d_error("[MME] Initial context setup failure : " + "ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d] ENB[%s:%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id, CORE_ADDR(enb->addr, buf), enb->enb_id); if (MME_HAVE_SGW_S11_PATH(mme_ue)) @@ -364,15 +383,17 @@ void s1ap_handle_e_rab_setup_response( ies = &message->s1ap_E_RABSetupResponseIEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] E-RAB setup response\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(enb_ue, return, "No UE Context[%d]", ies->eNB_UE_S1AP_ID); mme_ue = enb_ue->mme_ue; d_assert(mme_ue, return,); - d_trace(3, "[S1AP] E-RAB Setup Response : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); for (i = 0; i < ies->e_RABSetupListBearerSURes. s1ap_E_RABSetupItemBearerSURes.count; i++) @@ -394,12 +415,15 @@ void s1ap_handle_e_rab_setup_response( &e_rab->transportLayerAddress, &bearer->enb_s1u_ip); d_assert(rv == CORE_OK, return,); + d_trace(3, " EBI[%d]\n", bearer->ebi); + if (FSM_CHECK(&bearer->sm, esm_state_active)) { status_t rv; mme_bearer_t *linked_bearer = mme_linked_bearer(bearer); - d_assert(bearer, return, "Null param"); + d_assert(linked_bearer, return, "Null param"); + d_trace(3, " Linked-EBI[%d]\n", linked_bearer->ebi); if (bearer->ebi == linked_bearer->ebi) { @@ -427,14 +451,17 @@ void s1ap_handle_ue_context_release_request( ies = &message->s1ap_UEContextReleaseRequest_IEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] UE Context release request\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_mme_ue_s1ap_id(ies->mme_ue_s1ap_id); d_assert(enb_ue, return, "No UE Context[%d]", ies->mme_ue_s1ap_id); - d_trace(3, "[S1AP] UE Context Release Request[%d:%d] : " - "UE[mME-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - ies->cause.present, ies->cause.choice.radioNetwork, - enb_ue->mme_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + d_trace(3, " Cause[Group:%d Cause:%d]\n", + ies->cause.present, ies->cause.choice.radioNetwork); switch(ies->cause.present) { @@ -462,11 +489,11 @@ void s1ap_handle_ue_context_release_request( } else { - d_error("[S1AP] UE Context Release Request" - "[RadioNetwork Cause: %d] : " - "UE[mME-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", + d_error("[MME] UE Context release request : " + "RadioNetwork Cause[%d] " + "ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d] ENB[%s:%d]\n", ies->cause.choice.radioNetwork, - enb_ue->enb_ue_s1ap_id, + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id, CORE_ADDR(enb->addr, buf), enb->enb_id); if (MME_HAVE_SGW_S11_PATH(mme_ue)) { @@ -488,13 +515,12 @@ void s1ap_handle_ue_context_release_request( { mme_ue_t *mme_ue = enb_ue->mme_ue; - d_error("[S1AP] UE Context Release Request" - "[Transport Cause: %d] : " - "UE[mME-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - ies->cause.choice.transport, - enb_ue->enb_ue_s1ap_id, + d_error("[MME] UE Context release request : " + "Transport Cause[%d] " + "ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d] ENB[%s:%d]\n", + ies->cause.choice.radioNetwork, + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id, CORE_ADDR(enb->addr, buf), enb->enb_id); - if (MME_HAVE_SGW_S11_PATH(mme_ue)) { rv = mme_gtp_send_delete_all_sessions(mme_ue); @@ -541,13 +567,15 @@ void s1ap_handle_ue_context_release_complete( ies = &message->s1ap_UEContextReleaseComplete_IEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] UE Context release complete\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + enb_ue = enb_ue_find_by_mme_ue_s1ap_id(ies->mme_ue_s1ap_id); d_assert(enb_ue, return, "No UE Context[%d]", ies->mme_ue_s1ap_id); - d_trace(3, "[S1AP] UE Context Release Complete : " - "UE[mME-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->mme_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); ue_ctx_rel_action = enb_ue->ue_ctx_rel_action; enb_ue->ue_ctx_rel_action = S1AP_UE_CTX_REL_INVALID_ACTION; @@ -561,15 +589,18 @@ void s1ap_handle_ue_context_release_complete( { case S1AP_UE_CTX_REL_NO_ACTION: { + d_trace(3, " No Action\n"); break; } case S1AP_UE_CTX_REL_REMOVE_MME_UE_CONTEXT: { + d_trace(3, " Action: UE(mme) context\n"); mme_ue_remove(mme_ue); break; } case S1AP_UE_CTX_REL_DELETE_INDIRECT_TUNNEL: { + d_trace(3, " Action: Delete indirect tunnel\n"); rv = mme_gtp_send_delete_indirect_data_forwarding_tunnel_request( mme_ue); d_assert(rv == CORE_OK, return, "gtp send error"); @@ -577,7 +608,7 @@ void s1ap_handle_ue_context_release_complete( } default: { - d_assert(0, return, "Invalid action(%d)", ue_ctx_rel_action); + d_assert(0, return, "Invalid action[%d]", ue_ctx_rel_action); break; } } @@ -647,6 +678,10 @@ void s1ap_handle_path_switch_request( ies = &message->s1ap_PathSwitchRequestIEs; d_assert(ies, return, "Null param"); + d_trace(3, "[MME] Path switch request\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + eutran_cgi = &ies->eutran_cgi; d_assert(eutran_cgi, return,); pLMNidentity = &eutran_cgi->pLMNidentity; @@ -682,6 +717,9 @@ void s1ap_handle_path_switch_request( return; } + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + mme_ue = enb_ue->mme_ue; d_assert(mme_ue, return, "Null param"); @@ -750,11 +788,6 @@ void s1ap_handle_path_switch_request( /* Switch to enb */ enb_ue_switch_to_enb(enb_ue, enb); - - d_trace(3, "[S1AP] PathSwitchRequest : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - enb_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); } void s1ap_handle_handover_required(mme_enb_t *enb, s1ap_message_t *message) @@ -772,6 +805,10 @@ void s1ap_handle_handover_required(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_HandoverRequiredIEs; d_assert(ies, return,); + d_trace(3, "[MME] Handover required\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + source_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(source_ue, return, "Cannot find UE for eNB-UE-S1AP-ID[%d] and eNB[%s:%d]", @@ -781,6 +818,9 @@ void s1ap_handle_handover_required(mme_enb_t *enb, s1ap_message_t *message) "Conflict MME-UE-S1AP-ID : %d != %d\n", source_ue->mme_ue_s1ap_id, ies->mme_ue_s1ap_id); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + mme_ue = source_ue->mme_ue; d_assert(mme_ue, return,); @@ -801,11 +841,6 @@ void s1ap_handle_handover_required(mme_enb_t *enb, s1ap_message_t *message) rv = s1ap_send_handover_request(mme_ue, ies); d_assert(rv == CORE_OK,, "s1ap send error"); - - d_trace(3, "[S1AP] Handover Required : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - source_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); } void s1ap_handle_handover_request_ack(mme_enb_t *enb, s1ap_message_t *message) @@ -825,6 +860,10 @@ void s1ap_handle_handover_request_ack(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_HandoverRequestAcknowledgeIEs; d_assert(ies, return,); + d_trace(3, "[MME] Handover request acknowledge\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + target_ue = enb_ue_find_by_mme_ue_s1ap_id(ies->mme_ue_s1ap_id); d_assert(target_ue, return, "Cannot find UE for MME-UE-S1AP-ID[%d] and eNB[%s:%d]", @@ -838,6 +877,11 @@ void s1ap_handle_handover_request_ack(mme_enb_t *enb, s1ap_message_t *message) mme_ue = source_ue->mme_ue; d_assert(mme_ue, return,); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + for (i = 0; i < ies->e_RABAdmittedList.s1ap_E_RABAdmittedItem.count; i++) { mme_bearer_t *bearer = NULL; @@ -896,11 +940,6 @@ void s1ap_handle_handover_request_ack(mme_enb_t *enb, s1ap_message_t *message) rv = s1ap_send_handover_command(source_ue); d_assert(rv == CORE_OK, return, "gtp send failed"); } - - d_trace(3, "[S1AP] Handover Request Ack : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - target_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); } void s1ap_handle_handover_failure(mme_enb_t *enb, s1ap_message_t *message) @@ -917,6 +956,10 @@ void s1ap_handle_handover_failure(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_HandoverFailureIEs; d_assert(ies, return,); + d_trace(3, "[MME] Handover failure\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + target_ue = enb_ue_find_by_mme_ue_s1ap_id(ies->mme_ue_s1ap_id); d_assert(target_ue, return, "Cannot find UE for MME-UE-S1AP-ID[%d] and eNB[%s:%d]", @@ -925,6 +968,12 @@ void s1ap_handle_handover_failure(mme_enb_t *enb, s1ap_message_t *message) source_ue = target_ue->source_ue; d_assert(source_ue, return,); + + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + rv = s1ap_send_handover_preparation_failure(source_ue, &ies->cause); d_assert(rv == CORE_OK, return, "s1ap send error"); @@ -933,11 +982,6 @@ void s1ap_handle_handover_failure(mme_enb_t *enb, s1ap_message_t *message) S1ap_CauseRadioNetwork_ho_failure_in_target_EPC_eNB_or_target_system, S1AP_UE_CTX_REL_DELETE_INDIRECT_TUNNEL, 0); d_assert(rv == CORE_OK, return, "s1ap send error"); - - d_trace(3, "[S1AP] Handover Failure : " - "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", - target_ue->enb_ue_s1ap_id, - CORE_ADDR(enb->addr, buf), enb->enb_id); } void s1ap_handle_handover_cancel(mme_enb_t *enb, s1ap_message_t *message) @@ -955,6 +999,10 @@ void s1ap_handle_handover_cancel(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_HandoverCancelIEs; d_assert(ies, return,); + d_trace(3, "[MME] Handover cancel\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + source_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(source_ue, return, "Cannot find UE for eNB-UE-S1AP-ID[%d] and eNB[%s:%d]", @@ -967,6 +1015,11 @@ void s1ap_handle_handover_cancel(mme_enb_t *enb, s1ap_message_t *message) target_ue = source_ue->target_ue; d_assert(target_ue, return,); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + rv = s1ap_send_handover_cancel_ack(source_ue); d_assert(rv == CORE_OK,, "s1ap send error"); @@ -976,7 +1029,7 @@ void s1ap_handle_handover_cancel(mme_enb_t *enb, s1ap_message_t *message) S1AP_UE_CTX_REL_DELETE_INDIRECT_TUNNEL, 300); d_assert(rv == CORE_OK, return, "s1ap send error"); - d_trace(3, "[S1AP] Handover Cancel : " + d_trace(3, "[MME] Handover Cancel : " "UE[eNB-UE-S1AP-ID(%d)] --> eNB[%s:%d]\n", source_ue->enb_ue_s1ap_id, CORE_ADDR(enb->addr, buf), enb->enb_id); @@ -996,6 +1049,10 @@ void s1ap_handle_enb_status_transfer(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_ENBStatusTransferIEs; d_assert(ies, return,); + d_trace(3, "[MME] ENB status transfer\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + source_ue = enb_ue_find_by_enb_ue_s1ap_id(enb, ies->eNB_UE_S1AP_ID); d_assert(source_ue, return, "Cannot find UE for eNB-UE-S1AP-ID[%d] and eNB[%s:%d]", @@ -1008,6 +1065,11 @@ void s1ap_handle_enb_status_transfer(mme_enb_t *enb, s1ap_message_t *message) target_ue = source_ue->target_ue; d_assert(target_ue, return,); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + rv = s1ap_send_mme_status_transfer(target_ue, ies); d_assert(rv == CORE_OK,,); } @@ -1035,6 +1097,10 @@ void s1ap_handle_handover_notification(mme_enb_t *enb, s1ap_message_t *message) ies = &message->s1ap_HandoverNotifyIEs; d_assert(ies, return,); + d_trace(3, "[MME] Handover notification\n"); + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); + eutran_cgi = &ies->eutran_cgi; d_assert(eutran_cgi, return,); pLMNidentity = &eutran_cgi->pLMNidentity; @@ -1063,6 +1129,11 @@ void s1ap_handle_handover_notification(mme_enb_t *enb, s1ap_message_t *message) mme_ue = source_ue->mme_ue; d_assert(mme_ue, return,); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + mme_ue_associate_enb_ue(mme_ue, target_ue); memcpy(&mme_ue->tai.plmn_id, pLMNidentity->buf, diff --git a/src/mme/s1ap_path.c b/src/mme/s1ap_path.c index 9085e290f..4bee24826 100644 --- a/src/mme/s1ap_path.c +++ b/src/mme/s1ap_path.c @@ -70,10 +70,15 @@ static status_t s1ap_delete_list(list_t *list) status_t s1ap_send_to_enb(mme_enb_t *enb, pkbuf_t *pkbuf) { - status_t rv = CORE_ERROR; - d_assert(enb,,); - d_assert(pkbuf,,); - d_assert(enb->sock,,); + char buf[CORE_ADDRSTRLEN]; + status_t rv; + + d_assert(enb, return CORE_ERROR,); + d_assert(pkbuf, return CORE_ERROR,); + d_assert(enb->sock, return CORE_ERROR,); + + d_trace(3, " IP[%s] ENB_ID[%d]\n", + CORE_ADDR(enb->addr, buf), enb->enb_id); rv = s1ap_send(enb->sock, pkbuf, enb->sock_type == SOCK_STREAM ? NULL : enb->addr); @@ -83,7 +88,7 @@ status_t s1ap_send_to_enb(mme_enb_t *enb, pkbuf_t *pkbuf) pkbuf_free(pkbuf); } - return rv; + return CORE_OK;; } status_t s1ap_delayed_send_to_enb( @@ -250,12 +255,18 @@ status_t s1ap_send_ue_context_release_command( enb = enb_ue->enb; d_assert(enb, return CORE_ERROR, "Null param"); + d_trace(3, "[MME] UE Context release command\n"); + d_trace(3, " ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + enb_ue->enb_ue_s1ap_id, enb_ue->mme_ue_s1ap_id); + d_trace(3, " Group[%d] Cause[%d] Action[%d] Delay[%d]\n", + group, cause, action, delay); + rv = s1ap_build_ue_context_release_command(&s1apbuf, enb_ue, group, cause); d_assert(rv == CORE_OK && s1apbuf, return CORE_ERROR, "s1ap build error"); rv = s1ap_delayed_send_to_enb(enb, s1apbuf, delay); d_assert(rv == CORE_OK,, "s1ap send error"); - + return CORE_OK; } @@ -368,6 +379,8 @@ status_t s1ap_send_handover_request( mme_enb_t *target_enb = NULL; enb_ue_t *source_ue = NULL, *target_ue = NULL; + d_trace(3, "[MME] Handover request\n"); + d_assert(mme_ue, return CORE_ERROR,); source_ue = mme_ue->enb_ue; d_assert(source_ue, return CORE_ERROR,); @@ -402,6 +415,11 @@ status_t s1ap_send_handover_request( target_ue = enb_ue_add(target_enb); d_assert(target_ue, return CORE_ERROR,); + d_trace(3, " Source : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + source_ue->enb_ue_s1ap_id, source_ue->mme_ue_s1ap_id); + d_trace(3, " Target : ENB_UE_S1AP_ID[%d] MME_UE_S1AP_ID[%d]\n", + target_ue->enb_ue_s1ap_id, target_ue->mme_ue_s1ap_id); + rv = source_ue_associate_target_ue(source_ue, target_ue); d_assert(rv == CORE_OK, return CORE_ERROR,);